Skip to content
This repository has been archived by the owner on Sep 4, 2024. It is now read-only.

Deployments taking ~38 minutes, where previously they took 7-10 minutes #2507

Closed
jonsagara opened this issue Jul 17, 2017 · 2 comments
Closed

Deployments taking ~38 minutes, where previously they took 7-10 minutes #2507

jonsagara opened this issue Jul 17, 2017 · 2 comments

Comments

@jonsagara
Copy link

App Details

  • App Plan: Basic: 1 Medium
  • ASP.NET 4.7 enabled, Java and PHP disabled
  • Always On enabled
  • ARR Affinity off
  • Deployment source configured to use Bitbucket
  • ASP.NET Core MVC app targeting .NET 4.6.1
  • 64-bit

Repro steps.

Any deployment triggered by a Bitbucket commit or sync from Azure portal now takes ~38 minutes, whereas before it took 7-10 minutes.

A big chunk of this is dotnet restore, which seems to pause for ~10 minutes in the middle of execution. I can reproduce this by:

  1. Logging into the kudu DebugConsole
  2. Navigating to the solution directory (D:\home\site\repository)
  3. Typing "dotnet restore MySolution.sln"

If I enable detailed output (dotnet restore -v d MySolution.sln), it echoes a bunch of text back to the screen for about 10 seconds, and then pauses on this line for ~10 minutes:

Importing project "D:\Program Files (x86)\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk.Publish\build\netstandard1.0\DotNetCLIToolTargets\Microsoft.NET.Sdk.DotNetCLITool.targets" into project "D:\Program Files (x86)\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk.Publish\build\netstandard1.0\Microsoft.NET.Sdk.Publish.targets" at (131,3).

After the restore resumes, the program actively echoes output to the screen for another ~1.5 minutes before completing.

If I look at log.log for one of the actual deployments, I see the following lines:

2017-07-17T18:03:25.2275331Z,Command: "D:\home\site\deployments\tools\deploy.cmd",,0
2017-07-17T18:03:25.6494079Z,Handling ASP.NET Core Web Application deployment.,,0
2017-07-17T18:13:15.9182997Z, Restore completed in 347.24 ms for D:\home\site\repository\src[...]

This shows a similar ~10 minute pause when deploy.cmd executes dotnet restore.

Similarly, when viewing the kudu trace logs for a deployment, I see the following ~38 minute block for execution of deploy.cmd:

<step title="Executing external process" date="2017-07-17T17:24:33.335" type="process" path="starter.cmd" arguments="&quot;D:\home\site\deployments\tools\deploy.cmd&quot;" >
          <step title="Cpu: dotnet(9228,56.578s)+dotnet(348,0.250s)+cmd(10488,0.078s)=total(56.906s)" date="2017-07-17T17:25:34.086" /><!-- duration: 31ms -->
          <step title="starter.cmd: no io activity for 60s, prev-cpu=-1.000s, current-cpu=56.906s" date="2017-07-17T17:25:34.117" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(9228,117.109s)+dotnet(348,0.250s)+cmd(10488,0.078s)=total(117.438s)" date="2017-07-17T17:26:34.632" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 121s, prev-cpu=56.906s, current-cpu=117.438s" date="2017-07-17T17:26:34.647" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(9228,177.141s)+dotnet(348,0.250s)+cmd(10488,0.078s)=total(177.469s)" date="2017-07-17T17:27:34.927" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 181s, prev-cpu=117.438s, current-cpu=177.469s" date="2017-07-17T17:27:34.943" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(9228,237.703s)+dotnet(348,0.250s)+cmd(10488,0.078s)=total(238.031s)" date="2017-07-17T17:28:35.504" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 242s, prev-cpu=177.469s, current-cpu=238.031s" date="2017-07-17T17:28:35.520" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(9228,295.766s)+dotnet(348,0.250s)+cmd(10488,0.078s)=total(296.094s)" date="2017-07-17T17:29:36.090" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 302s, prev-cpu=238.031s, current-cpu=296.094s" date="2017-07-17T17:29:36.105" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(9228,355.125s)+dotnet(348,0.250s)+cmd(10488,0.078s)=total(355.453s)" date="2017-07-17T17:30:36.636" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 363s, prev-cpu=296.094s, current-cpu=355.453s" date="2017-07-17T17:30:36.636" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(9228,415.516s)+dotnet(348,0.250s)+cmd(10488,0.078s)=total(415.844s)" date="2017-07-17T17:31:37.119" /><!-- duration: 31ms -->
          <step title="starter.cmd: no io activity for 423s, prev-cpu=355.453s, current-cpu=415.844s" date="2017-07-17T17:31:37.150" /><!-- duration: 16ms -->
          <step title="Cpu: dotnet(9228,476.063s)+dotnet(348,0.250s)+cmd(10488,0.078s)=total(476.391s)" date="2017-07-17T17:32:37.696" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 484s, prev-cpu=415.844s, current-cpu=476.391s" date="2017-07-17T17:32:37.712" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(9228,536.594s)+dotnet(348,0.250s)+cmd(10488,0.078s)=total(536.922s)" date="2017-07-17T17:33:38.257" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 544s, prev-cpu=476.391s, current-cpu=536.922s" date="2017-07-17T17:33:38.257" /><!-- duration: 15ms -->
          <step title="Cpu: dotnet(5016,58.125s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(58.453s)" date="2017-07-17T17:35:30.214" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 60s, prev-cpu=-1.000s, current-cpu=58.453s" date="2017-07-17T17:35:30.229" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,118.922s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(119.250s)" date="2017-07-17T17:36:31.181" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 121s, prev-cpu=58.453s, current-cpu=119.250s" date="2017-07-17T17:36:31.197" /><!-- duration: 16ms -->
          <step title="Cpu: dotnet(5016,179.391s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(179.719s)" date="2017-07-17T17:37:31.680" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 182s, prev-cpu=119.250s, current-cpu=179.719s" date="2017-07-17T17:37:31.696" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,239.766s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(240.094s)" date="2017-07-17T17:38:32.117" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 242s, prev-cpu=179.719s, current-cpu=240.094s" date="2017-07-17T17:38:32.132" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,296.391s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(296.719s)" date="2017-07-17T17:39:32.769" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 303s, prev-cpu=240.094s, current-cpu=296.719s" date="2017-07-17T17:39:32.785" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,356.953s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(357.266s)" date="2017-07-17T17:40:33.377" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 364s, prev-cpu=296.719s, current-cpu=357.266s" date="2017-07-17T17:40:33.393" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,417.500s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(417.828s)" date="2017-07-17T17:41:33.954" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 424s, prev-cpu=357.266s, current-cpu=417.828s" date="2017-07-17T17:41:33.970" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,478.031s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(478.359s)" date="2017-07-17T17:42:34.547" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 485s, prev-cpu=417.828s, current-cpu=478.359s" date="2017-07-17T17:42:34.563" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,538.500s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(538.828s)" date="2017-07-17T17:43:35.077" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 545s, prev-cpu=478.359s, current-cpu=538.828s" date="2017-07-17T17:43:35.093" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,594.938s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(595.266s)" date="2017-07-17T17:44:35.725" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 606s, prev-cpu=538.828s, current-cpu=595.266s" date="2017-07-17T17:44:35.741" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,655.500s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(655.828s)" date="2017-07-17T17:45:36.302" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 667s, prev-cpu=595.266s, current-cpu=655.828s" date="2017-07-17T17:45:36.318" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,715.938s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(716.266s)" date="2017-07-17T17:46:36.785" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 727s, prev-cpu=655.828s, current-cpu=716.266s" date="2017-07-17T17:46:36.801" /><!-- duration: 16ms -->
          <step title="Cpu: dotnet(5016,776.672s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(776.969s)" date="2017-07-17T17:47:37.519" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 788s, prev-cpu=716.266s, current-cpu=776.969s" date="2017-07-17T17:47:37.534" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(5016,837.422s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(837.750s)" date="2017-07-17T17:48:38.345" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 849s, prev-cpu=776.969s, current-cpu=837.750s" date="2017-07-17T17:48:38.361" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(12160,58.594s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(58.922s)" date="2017-07-17T17:50:09.298" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 61s, prev-cpu=-1.000s, current-cpu=58.922s" date="2017-07-17T17:50:09.314" /><!-- duration: 16ms -->
          <step title="Cpu: dotnet(12160,119.141s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(119.469s)" date="2017-07-17T17:51:09.891" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 122s, prev-cpu=58.922s, current-cpu=119.469s" date="2017-07-17T17:51:09.907" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(12160,179.734s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(180.063s)" date="2017-07-17T17:52:10.484" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 182s, prev-cpu=119.469s, current-cpu=180.063s" date="2017-07-17T17:52:10.499" /><!-- duration: 16ms -->
          <step title="Cpu: dotnet(12160,240.359s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(240.672s)" date="2017-07-17T17:53:11.123" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 243s, prev-cpu=180.063s, current-cpu=240.672s" date="2017-07-17T17:53:11.123" /><!-- duration: 16ms -->
          <step title="Cpu: dotnet(4412,55.141s)+cmd(5760,0.031s)+dotnet(11584,6.656s)+dotnet(12160,297.672s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(359.797s)" date="2017-07-17T17:55:27.356" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 60s, prev-cpu=-1.000s, current-cpu=359.797s" date="2017-07-17T17:55:27.388" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(4412,115.875s)+cmd(5760,0.031s)+dotnet(11584,6.656s)+dotnet(12160,297.672s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(420.547s)" date="2017-07-17T17:56:28.136" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 121s, prev-cpu=359.797s, current-cpu=420.547s" date="2017-07-17T17:56:28.136" /><!-- duration: 16ms -->
          <step title="Cpu: dotnet(4412,176.375s)+cmd(5760,0.031s)+dotnet(11584,6.656s)+dotnet(12160,297.672s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(481.047s)" date="2017-07-17T17:57:28.681" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 181s, prev-cpu=420.547s, current-cpu=481.047s" date="2017-07-17T17:57:28.697" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(4412,236.875s)+cmd(5760,0.031s)+dotnet(11584,6.656s)+dotnet(12160,297.672s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(541.547s)" date="2017-07-17T17:58:29.211" /><!-- duration: 16ms -->
          <step title="starter.cmd: no io activity for 242s, prev-cpu=481.047s, current-cpu=541.547s" date="2017-07-17T17:58:29.227" /><!-- duration: 0ms -->
          <step title="Cpu: dotnet(11584,6.859s)+dotnet(12160,313.281s)+dotnet(10068,0.234s)+cmd(10488,0.094s)=total(320.469s)" date="2017-07-17T18:00:25.224" /><!-- duration: 0ms -->
          <step title="starter.cmd: no io activity for 61s, prev-cpu=-1.000s, current-cpu=320.469s" date="2017-07-17T18:00:25.224" /><!-- duration: 16ms -->
        </step><!-- duration: 2307558ms -->

As stated above, our deployments were taking 7-10 minutes, but on July 7th, deployment times jumped to ~38 minutes. Coincidentally, this tweet mentions that Azure App Service was upgraded to .NET Core 2.0 Preview 2 on July 7th.

I don't know if my issues are related to kudu using .NET Core Preview 2, but the timing leads me to believe it is possible.

Any ideas as to what could be causing the delay with dotnet restore, or the execution of deploy.cmd taking ~38 minutes?

Project structures.

I was unable to create a skeleton project that successfully reproduces the issue, and the repo in question is proprietary.

The log/error given by the failure.

The issues are:

  • dotnet restore taking ~10 minutes
  • Total deployment taking ~38 minutes, whereas before they took 7-10 minutes

Debug your Azure website remotely.

Indirect site name: kuduidentifier.
The actual site in question begins with the letter "F" and ends with "Dev".

Mention any other details that might be useful.

Things we have tried:

  • Resetting the bitbucket integration
  • Deploying to a new site in the same subscription
  • Deploying to a new site in a different subscription
  • Deploying to a new site in a completely different Azure account
  • Updating node.js tools in App Settings to 6.9.1

None of those have helped. We saw the same delays after making each of those changes.
@watashiSHUN
Copy link
Contributor

it sounds like you are running into this: dotnet/core#724

here is the suggested solution:

the root cause is analysed as gobbling going rogue in restore and build. Workaround dotnet restore /p:EnableDefaultItems=false

can you test it in your console? if it doesn't work, I would suggest you use an older version of the dotnet core cli (since you are not using new features, you can go back to the latest version once they have it fixed)

@jonsagara
Copy link
Author

dotnet restore /p:EnableDefaultItems=false

That restored lightning fast. I didn't time it, but probably less than 10 seconds.

I would suggest you use an older version of the dotnet core cli

Via global.json, I pinned the SDK version at 1.0.4, and now the deployments are back down to 7 minutes.

Thank you!

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jonsagara @watashiSHUN