search

dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
15.17k stars 4.72k forks source link

Restoring packages takes ~1hr #18940

Closed CIPop closed 4 years ago

CIPop commented 8 years ago

The dotnet process is using a lot of CPU and makes build take >1hr. There isn't a lot of network activity.

  [13:44:10.53] Restoring all packages...
  [14:43:30.73] Restoring all packages...Done.

image

CIPop commented 8 years ago

Two of the threads are doing System.IO file operations using synchronous Read. Is this something that changed?

0:005> ~*k

   0  Id: 2128.2ae8 Suspend: 1 Teb: 000000b6`02646000 Unfrozen
 # Child-SP          RetAddr           Call Site
00 000000b6`0297df08 00007ffa`bf168157 ntdll!ZwReadFile+0x14 [d:\rs2.obj.amd64fre\minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 227]
01 000000b6`0297df10 00007ffa`398cb851 KERNELBASE!ReadFile+0x77 [d:\rs2\minkernel\kernelbase\filehops.c @ 1397]
02 000000b6`0297df90 00007ffa`398cb6e1 System_Runtime_Extensions!DomainBoundILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.SafeHandle, Byte*, Int32, Int32 ByRef, IntPtr)+0xd1
03 000000b6`0297e070 00007ffa`398cb568 System_IO_FileSystem!System.IO.Win32FileStream.ReadFileNative(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Int32, System.Threading.NativeOverlapped*, Int32 ByRef)+0xb1 [D:\A\_work\1\s\src\System.IO.FileSystem\src\System\IO\Win32FileStream.cs @ 1595]
04 000000b6`0297e0d0 00007ffa`398cb0f3 System_IO_FileSystem!System.IO.Win32FileStream.ReadCore(Byte[], Int32, Int32)+0xa8 [D:\A\_work\1\s\src\System.IO.FileSystem\src\System\IO\Win32FileStream.cs @ 760]
05 000000b6`0297e140 00007ffa`735f7713 System_IO_FileSystem!System.IO.Win32FileStream.Read(Byte[], Int32, Int32)+0xb3 [D:\A\_work\1\s\src\System.IO.FileSystem\src\System\IO\Win32FileStream.cs @ 688]
06 000000b6`0297e1a0 00007ffa`735f710a System_Private_CoreLib_ni!System.IO.StreamReader.ReadBuffer()+0xb3 [D:\A\_work\38\s\src\mscorlib\src\System\IO\StreamReader.cs @ 592]
07 000000b6`0297e1f0 00007ffa`39ad79dc System_Private_CoreLib_ni!System.IO.StreamReader.ReadToEnd()+0x5a [D:\A\_work\38\s\src\mscorlib\src\System\IO\StreamReader.cs @ 411]
08 000000b6`0297e230 00007ffa`39ad2b3f run!Microsoft.DotNet.Execute.RunProcess.ExecuteProcess(System.String, System.String)+0x15c [D:\A\_work\27\s\src\Run\RunProcess.cs @ 37]
09 000000b6`0297e290 00007ffa`398c14a1 run!Microsoft.DotNet.Execute.Setup.ExecuteCommand(System.String, System.Collections.Generic.List`1<System.String>)+0xef [D:\A\_work\27\s\src\Run\Setup.cs @ 204]
0a 000000b6`0297e2e0 00007ffa`995d7463 run!Microsoft.DotNet.Execute.Executor.Main(System.String[])+0x451 [D:\A\_work\27\s\src\Run\Executor.cs @ 189]
0b 000000b6`0297e3f0 00007ffa`993353e3 coreclr!CallDescrWorkerInternal+0x83 [D:\A\_work\38\s\src\vm\amd64\CallDescrWorkerAMD64.asm @ 101]
0c 000000b6`0297e430 00007ffa`9930731e coreclr!MethodDescCallSite::CallTargetWorker+0x21b [d:\a\_work\38\s\src\vm\callhelpers.cpp @ 653]
0d (Inline Function) --------`-------- coreclr!MethodDescCallSite::Call_RetArgSlot+0x5 [d:\a\_work\38\s\src\vm\callhelpers.h @ 420]
0e 000000b6`0297e540 00007ffa`993075ae coreclr!RunMain+0x226 [d:\a\_work\38\s\src\vm\assembly.cpp @ 2594]
0f 000000b6`0297e7b0 00007ffa`992b7582 coreclr!Assembly::ExecuteMainMethod+0xda [d:\a\_work\38\s\src\vm\assembly.cpp @ 2715]
10 000000b6`0297ea80 00007ffa`992a3255 coreclr!CorHost2::ExecuteAssembly+0x1f2 [d:\a\_work\38\s\src\vm\corhost.cpp @ 1350]
11 000000b6`0297eb80 00007ffa`a4fbf2c4 coreclr!coreclr_execute_assembly+0x135 [d:\a\_work\38\s\src\dlls\mscoree\unixinterface.cpp @ 350]
12 000000b6`0297ec10 00007ffa`a4fbf8c2 hostpolicy!run+0xc44 [f:\agent\_work\13\s\src\corehost\cli\hostpolicy.cpp @ 212]
13 000000b6`0297f2a0 00007ffa`b2f6941e hostpolicy!corehost_main+0x222 [f:\agent\_work\13\s\src\corehost\cli\hostpolicy.cpp @ 290]
14 000000b6`0297f400 00007ffa`b2f6d63f hostfxr!execute_app+0xae [f:\agent\_work\13\s\src\corehost\cli\fxr\hostfxr.cpp @ 71]
15 000000b6`0297f460 00007ffa`b2f6cd6c hostfxr!fx_muxer_t::read_config_and_execute+0x74f [f:\agent\_work\13\s\src\corehost\cli\fxr\fx_muxer.cpp @ 759]
16 000000b6`0297f9d0 00007ffa`b2f6b90d hostfxr!fx_muxer_t::parse_args_and_execute+0x70c [f:\agent\_work\13\s\src\corehost\cli\fxr\fx_muxer.cpp @ 685]
*** WARNING: Unable to verify checksum for S:\c1\Tools\dotnetcli\dotnet.exe
17 000000b6`0297fb50 00007ff7`23b193f6 hostfxr!fx_muxer_t::execute+0x23d [f:\agent\_work\13\s\src\corehost\cli\fxr\fx_muxer.cpp @ 806]
18 000000b6`0297fcc0 00007ff7`23b1c9cc dotnet!run+0xe6 [f:\agent\_work\13\s\src\corehost\corehost.cpp @ 84]
19 (Inline Function) --------`-------- dotnet!invoke_main+0x22 [f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl @ 89]
1a 000000b6`0297fd80 00007ffa`c0ceef44 dotnet!__scrt_common_main_seh+0x124 [f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl @ 264]
1b 000000b6`0297fdc0 00007ffa`c29fddd1 KERNEL32!BaseThreadInitThunk+0x14 [d:\rs2\base\win32\client\thread.c @ 64]
1c 000000b6`0297fdf0 00000000`00000000 ntdll!RtlUserThreadStart+0x21 [d:\rs2\minkernel\ntdll\rtlstrt.c @ 997]

   1  Id: 2128.1834 Suspend: 1 Teb: 000000b6`0264e000 Unfrozen
 # Child-SP          RetAddr           Call Site
00 000000b6`02f7f8a8 00007ffa`bf190f70 ntdll!ZwWaitForMultipleObjects+0x14 [d:\rs2.obj.amd64fre\minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 907]
01 000000b6`02f7f8b0 00007ffa`995d1d11 KERNELBASE!WaitForMultipleObjectsEx+0xf0 [d:\rs2\minkernel\kernelbase\synch.c @ 1551]
02 000000b6`02f7fbb0 00007ffa`995d1aed coreclr!DebuggerRCThread::MainLoop+0xe1 [d:\a\_work\38\s\src\debug\ee\rcthread.cpp @ 1241]
03 000000b6`02f7fc70 00007ffa`995d21ba coreclr!DebuggerRCThread::ThreadProc+0x155 [d:\a\_work\38\s\src\debug\ee\rcthread.cpp @ 1042]
04 000000b6`02f7fcc0 00007ffa`c0ceef44 coreclr!DebuggerRCThread::ThreadProcStatic+0x1a [d:\a\_work\38\s\src\debug\ee\rcthread.cpp @ 1642]
05 000000b6`02f7fcf0 00007ffa`c29fddd1 KERNEL32!BaseThreadInitThunk+0x14 [d:\rs2\base\win32\client\thread.c @ 64]
06 000000b6`02f7fd20 00000000`00000000 ntdll!RtlUserThreadStart+0x21 [d:\rs2\minkernel\ntdll\rtlstrt.c @ 997]

   2  Id: 2128.35fc Suspend: 1 Teb: 000000b6`02650000 Unfrozen
 # Child-SP          RetAddr           Call Site
00 000000b6`030ff0b8 00007ffa`bf190f70 ntdll!ZwWaitForMultipleObjects+0x14 [d:\rs2.obj.amd64fre\minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 907]
01 000000b6`030ff0c0 00007ffa`993bce80 KERNELBASE!WaitForMultipleObjectsEx+0xf0 [d:\rs2\minkernel\kernelbase\synch.c @ 1551]
02 (Inline Function) --------`-------- coreclr!FinalizerThread::WaitForFinalizerEvent+0x68 [d:\a\_work\38\s\src\vm\finalizerthread.cpp @ 518]
03 000000b6`030ff3c0 00007ffa`99302460 coreclr!FinalizerThread::FinalizerThreadWorker+0x190 [d:\a\_work\38\s\src\vm\finalizerthread.cpp @ 673]
04 000000b6`030ff430 00007ffa`993024f5 coreclr!ManagedThreadBase_DispatchInner+0x70 [d:\a\_work\38\s\src\vm\threads.cpp @ 10113]
05 000000b6`030ff470 00007ffa`99302844 coreclr!ManagedThreadBase_DispatchMiddle+0x89 [d:\a\_work\38\s\src\vm\threads.cpp @ 10162]
06 000000b6`030ff5d0 00007ffa`99302923 coreclr!ManagedThreadBase_DispatchOuter+0xb4 [d:\a\_work\38\s\src\vm\threads.cpp @ 10417]
07 (Inline Function) --------`-------- coreclr!ManagedThreadBase_NoADTransition+0x36 [d:\a\_work\38\s\src\vm\threads.cpp @ 10504]
08 000000b6`030ff680 00007ffa`993bd254 coreclr!ManagedThreadBase::FinalizerBase+0x3f [d:\a\_work\38\s\src\vm\threads.cpp @ 10531]
09 000000b6`030ff6e0 00007ffa`992fd4db coreclr!FinalizerThread::FinalizerThreadStart+0x64 [d:\a\_work\38\s\src\vm\finalizerthread.cpp @ 888]
0a 000000b6`030ff720 00007ffa`c0ceef44 coreclr!Thread::intermediateThreadProc+0x8b [d:\a\_work\38\s\src\vm\threads.cpp @ 2869]
0b 000000b6`030ff7e0 00007ffa`c29fddd1 KERNEL32!BaseThreadInitThunk+0x14 [d:\rs2\base\win32\client\thread.c @ 64]
0c 000000b6`030ff810 00000000`00000000 ntdll!RtlUserThreadStart+0x21 [d:\rs2\minkernel\ntdll\rtlstrt.c @ 997]

   3  Id: 2128.17b0 Suspend: 1 Teb: 000000b6`02654000 Unfrozen
 # Child-SP          RetAddr           Call Site
00 000000b6`0256f6e8 00007ffa`bf190f70 ntdll!ZwWaitForMultipleObjects+0x14 [d:\rs2.obj.amd64fre\minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 907]
01 000000b6`0256f6f0 00007ffa`9943d711 KERNELBASE!WaitForMultipleObjectsEx+0xf0 [d:\rs2\minkernel\kernelbase\synch.c @ 1551]
02 000000b6`0256f9f0 00007ffa`c0ceef44 coreclr!ThreadpoolMgr::WaitThreadStart+0x111 [d:\a\_work\38\s\src\vm\win32threadpool.cpp @ 3019]
03 000000b6`0256fa40 00007ffa`c29fddd1 KERNEL32!BaseThreadInitThunk+0x14 [d:\rs2\base\win32\client\thread.c @ 64]
04 000000b6`0256fa70 00000000`00000000 ntdll!RtlUserThreadStart+0x21 [d:\rs2\minkernel\ntdll\rtlstrt.c @ 997]

   4  Id: 2128.2ff8 Suspend: 1 Teb: 000000b6`0265e000 Unfrozen
 # Child-SP          RetAddr           Call Site
00 000000b6`039fedb8 00007ffa`bf168157 ntdll!ZwReadFile+0x14 [d:\rs2.obj.amd64fre\minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 227]
01 000000b6`039fedc0 00007ffa`398cb851 KERNELBASE!ReadFile+0x77 [d:\rs2\minkernel\kernelbase\filehops.c @ 1397]
02 000000b6`039fee40 00007ffa`398cb6e1 System_Runtime_Extensions!DomainBoundILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.SafeHandle, Byte*, Int32, Int32 ByRef, IntPtr)+0xd1
03 000000b6`039fef20 00007ffa`398cb568 System_IO_FileSystem!System.IO.Win32FileStream.ReadFileNative(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Int32, System.Threading.NativeOverlapped*, Int32 ByRef)+0xb1 [D:\A\_work\1\s\src\System.IO.FileSystem\src\System\IO\Win32FileStream.cs @ 1595]
04 000000b6`039fef80 00007ffa`398cb0f3 System_IO_FileSystem!System.IO.Win32FileStream.ReadCore(Byte[], Int32, Int32)+0xa8 [D:\A\_work\1\s\src\System.IO.FileSystem\src\System\IO\Win32FileStream.cs @ 760]
05 000000b6`039feff0 00007ffa`7353ca99 System_IO_FileSystem!System.IO.Win32FileStream.Read(Byte[], Int32, Int32)+0xb3 [D:\A\_work\1\s\src\System.IO.FileSystem\src\System\IO\Win32FileStream.cs @ 688]
06 000000b6`039ff050 00007ffa`734fca8d System_Private_CoreLib_ni!System.IO.Stream+<>c.<BeginReadInternal>b__38_0(System.Object)+0x69 [D:\A\_work\38\s\src\mscorlib\src\System\IO\Stream.cs @ 281]
07 000000b6`039ff0a0 00007ffa`734f55e6 System_Private_CoreLib_ni!System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].InnerInvoke()+0xffffffff`fffc7e0d [D:\A\_work\38\s\src\mscorlib\src\System\Threading\Tasks\future.cs @ 686]
08 000000b6`039ff0d0 00007ffa`7349614e System_Private_CoreLib_ni!System.Threading.Tasks.Task.Execute()+0x46 [D:\A\_work\38\s\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2472]
09 000000b6`039ff110 00007ffa`734f5b53 System_Private_CoreLib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0x6e [D:\A\_work\38\s\src\mscorlib\src\System\Threading\ExecutionContext.cs @ 104]
0a 000000b6`039ff180 00007ffa`734f58ef System_Private_CoreLib_ni!System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)+0x223 [D:\A\_work\38\s\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2794]
0b 000000b6`039ff230 00007ffa`73564e50 System_Private_CoreLib_ni!System.Threading.Tasks.Task.ExecuteEntry(Boolean)+0x9f [D:\A\_work\38\s\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2730]
0c 000000b6`039ff270 00007ffa`995d7463 System_Private_CoreLib_ni!System.Threading.ThreadPoolWorkQueue.Dispatch()+0x1c0 [D:\A\_work\38\s\src\mscorlib\src\System\Threading\ThreadPool.cs @ 815]
0d 000000b6`039ff310 00007ffa`993353e3 coreclr!CallDescrWorkerInternal+0x83 [D:\A\_work\38\s\src\vm\amd64\CallDescrWorkerAMD64.asm @ 101]
0e 000000b6`039ff350 00007ffa`9948435a coreclr!MethodDescCallSite::CallTargetWorker+0x21b [d:\a\_work\38\s\src\vm\callhelpers.cpp @ 653]
0f (Inline Function) --------`-------- coreclr!MethodDescCallSite::Call_RetBool+0xc [d:\a\_work\38\s\src\vm\callhelpers.h @ 420]
10 000000b6`039ff460 00007ffa`99302460 coreclr!QueueUserWorkItemManagedCallback+0x2a [d:\a\_work\38\s\src\vm\comthreadpool.cpp @ 510]
11 000000b6`039ff550 00007ffa`993024f5 coreclr!ManagedThreadBase_DispatchInner+0x70 [d:\a\_work\38\s\src\vm\threads.cpp @ 10113]
12 000000b6`039ff590 00007ffa`99302844 coreclr!ManagedThreadBase_DispatchMiddle+0x89 [d:\a\_work\38\s\src\vm\threads.cpp @ 10162]
13 000000b6`039ff6f0 00007ffa`993028de coreclr!ManagedThreadBase_DispatchOuter+0xb4 [d:\a\_work\38\s\src\vm\threads.cpp @ 10417]
14 (Inline Function) --------`-------- coreclr!ManagedThreadBase_FullTransitionWithAD+0x2b [d:\a\_work\38\s\src\vm\threads.cpp @ 10480]
15 000000b6`039ff7a0 00007ffa`994492f4 coreclr!ManagedThreadBase::ThreadPool+0x32 [d:\a\_work\38\s\src\vm\threads.cpp @ 10523]
16 000000b6`039ff800 00007ffa`9943c229 coreclr!ManagedPerAppDomainTPCount::DispatchWorkItem+0xe4 [d:\a\_work\38\s\src\vm\threadpoolrequest.cpp @ 760]
17 000000b6`039ff950 00007ffa`9943cdb9 coreclr!ThreadpoolMgr::ExecuteWorkRequest+0x179 [d:\a\_work\38\s\src\vm\win32threadpool.cpp @ 1893]
18 000000b6`039ff9b0 00007ffa`992fd4db coreclr!ThreadpoolMgr::WorkerThreadStart+0x4f9 [d:\a\_work\38\s\src\vm\win32threadpool.cpp @ 2363]
19 000000b6`039ffa50 00007ffa`c0ceef44 coreclr!Thread::intermediateThreadProc+0x8b [d:\a\_work\38\s\src\vm\threads.cpp @ 2869]
1a 000000b6`039ffb90 00007ffa`c29fddd1 KERNEL32!BaseThreadInitThunk+0x14 [d:\rs2\base\win32\client\thread.c @ 64]
1b 000000b6`039ffbc0 00000000`00000000 ntdll!RtlUserThreadStart+0x21 [d:\rs2\minkernel\ntdll\rtlstrt.c @ 997]

#  5  Id: 2128.3c8 Suspend: 1 Teb: 000000b6`02672000 Unfrozen
 # Child-SP          RetAddr           Call Site
00 000000b6`0477feb8 00007ffa`c2a5d76a ntdll!DbgBreakPoint [d:\rs2\minkernel\ntos\rtl\amd64\debugstb.asm @ 51]
01 000000b6`0477fec0 00007ffa`c0ceef44 ntdll!DbgUiRemoteBreakin+0x4a [d:\rs2\minkernel\ntdll\dlluistb.c @ 312]
02 000000b6`0477fef0 00007ffa`c29fddd1 KERNEL32!BaseThreadInitThunk+0x14 [d:\rs2\base\win32\client\thread.c @ 64]
03 000000b6`0477ff20 00000000`00000000 ntdll!RtlUserThreadStart+0x21 [d:\rs2\minkernel\ntdll\rtlstrt.c @ 997]
weshaggard commented 8 years ago

@karajas is working on this in PR https://github.com/dotnet/corefx/pull/12345.

CIPop commented 8 years ago

Thanks @weshaggard! @karajas In my case it's not 12 minutes but 1hr...

Is there any known workaround?

Here's the perfview breakdown:

Name                                                    Exc %       Exc Inc %         Inc     Fold                               When
module ntoskrnl <<ntoskrnl!EtwpTraceFileIo>>             17.5    13,720  17.5      13,720      182   oHJJJHIHKHKKKJJKIJJIKJFHFFGFFEGF
module ntoskrnl <<ntoskrnl!KiSystemServiceCopyEnd>>       9.8     7,677  66.9      52,537      435   1*******************************
module ntfs.sys <<ntfs.sys!NtfsCommonCreateCallout>>      6.5     5,072   9.3       7,303    2,819   09BA99A8A8999A9A899AAA9997787887
module ntfs.sys <<ntfs.sys!NtfsFsdDirectoryControl>>      4.5     3,515   8.0       6,279    1,169   58887887887798987o88888877777777
module fltmgr.sys <<fltmgr.sys!FltpCreate>>               4.2     3,324  38.9      30,543    2,014   1************************Y*YXXYW

Top 1 is caused by NuGet package resolver:

Name                                                                                                                                                                                                                                Inc %         Inc   Exc %       Exc Fold                                 When
 module ntoskrnl <<ntoskrnl!EtwpTraceFileIo>>                                                                                                                                                                                        17.2      13,545    17.2    13,545  179     oGJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
+ module fileinfo.sys <<fileinfo.sys!??FIPreCreateCallback>>                                                                                                                                                                         17.2      13,545     0.0         0    0     1GJJoHIGJHJKJJIKHIIIKIFHFFGFFEFF
 + module fltmgr.sys <<fltmgr.sys!FltpCreate>>                                                                                                                                                                                       17.2      13,545     0.0         0    0     1GJJoHIGJHJKJJIKHIIIKIFHFFGFFEFF
  + module ntoskrnl <<ntoskrnl!KiSystemServiceCopyEnd>>                                                                                                                                                                              17.2      13,545     0.0         0    0     1GJJoHIGJHJKJJIKHIIIKIFHFFGFFEFF
   + module ntdll <<ntdll!ZwOpenFile>>                                                                                                                                                                                               17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |+ module kernelbase <<kernelbase!FindFirstFileExW>>                                                                                                                                                                              17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   | + module microsoft.dotnet.internalabstractions.il <<microsoft.dotnet.internalabstractions.il!dynamicClass.IL_STUB_PInvoke(class System.String,pMT: 00007FFA3995F3C8,pMT: 00007FFA3995F8C8&,pMT: 00007FFA3995F518,int,int32)>>   17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |  + module system.io.filesystem <<system.io.filesystem!DirectoryInfo.EnumerateFiles>>                                                                                                                                            17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |   + module nuget.protocol.core.v3 <<nuget.protocol.core.v3!?>>                                                                                                                                                                  17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |    + module nuget.dependencyresolver <<nuget.dependencyresolver!?>>                                                                                                                                                             17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |     + module system.private.corelib <<system.private.corelib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[System.__Canon].Start(!!0&)>>                                                                             17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |      + module nuget.dependencyresolver <<nuget.dependencyresolver!?>>                                                                                                                                                           17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |       + module nuget.dependencyresolver.core <<nuget.dependencyresolver.core!?>>                                                                                                                                                17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |        + module system.private.corelib <<system.private.corelib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[System.__Canon].Start(!!0&)>>                                                                          17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |         + module nuget.dependencyresolver.core <<nuget.dependencyresolver.core!?>>                                                                                                                                              17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |          + module system.private.corelib <<system.private.corelib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[System.__Canon].Start(!!0&)>>                                                                        17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |           + module nuget.dependencyresolver.core <<nuget.dependencyresolver.core!?>>                                                                                                                                            17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |            + module system.private.corelib <<system.private.corelib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[System.__Canon].Start(!!0&)>>                                                                      17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
   |             + module nuget.dependencyresolver.core <<nuget.dependencyresolver.core!?>>                                                                                                                                          17.2      13,521     0.0         0    0     0GJJJHIGJHJKJJIKHIIIKIFHFFGFFEFF
karajas commented 8 years ago

So from my initial perf investigation, nuget seems to download the packages in a relatively small amount of time (there is still some download contention when the download is parallelised). The main perf hit that was hitting my machine was the IO for reading/generating the project.lock.json which is part of the stack in the perfview trace.

I am planning further investigation into nuget.exe with perfview. The resolver is in the Nuget project on github so might be worth investigating the issues on it.

As for a workaround, the resolve step issue isn't consistently reproable across machines (build machines seem to have a different issue) so you can try grabbing my branch on the pr mentioned. I'm trying to get this checked in this week.

CIPop commented 8 years ago

I've opened this because it's new behavior: I've never seen the package step taking so long before and was definitely not CPU bound.

Clockwork-Muse commented 8 years ago

It's been taking ~40 minutes for me for at least a couple of months.

CIPop commented 8 years ago

/cc @ericeil

I've isolated this issue to a single Dev Box, the only one I have with 12 logical cores. Two other boxes (8 logical cores) took 11/12 minutes. Since it has something to do with the number of cores, this could be a manifestation of dotnet/runtime#18788.

@Clockwork-Muse, out of curiosity, how many logical cores does your machine have? (Sounds odd :) but...) Can you try on a machine with less cores? You can find out the number of cores from Task Manager, Performance tab.

CIPop commented 8 years ago

@weshaggard Is there anything else other than .\clean; .\sync; .\build that I should to do ensure that the build tools or anything else particular to this machine gets updated? I've already verified that dotnet.exe is ver 1.0.1.4500 in both the affected and one of the unaffected machines.

Clockwork-Muse commented 8 years ago

@CIPop - Two logical processors (I'm back on my old desktop since moving back from Japan - Core2 Duo 6600.... yeah, refresh after Thanksgiving)

ericeil commented 8 years ago

On my Surface Pro 4 (i5, 2 cores, 4 logical processors), package restore takes ~45 minutes; it's been that way for months. I've been running Windows preview builds that whole time, so maybe that makes a difference?

benaadams commented 8 years ago

Antimalware Service Executable or Microsoft Windows Search Indexer/Protocol Host doing anything exciting during this time? They like to go a bit wild depending if I'm restoring to somewhere excluded or not.

ericstj commented 8 years ago

@benaadams was just going to suggest that. Our measurements of restore show that it is typically network and disk bound. First phase as it populates the full set of packages is network bound, with some contention due to shared resources in multiple projects (eg: every project backs up behind the one guy downloading the System.Runtime package). Second phase as it writes out all project.lock.json files is disk bound (reading packages, writing lock.jsons). If you're seeing CPU pegged that points to an AV/anti-malware scanning all that IO.

Clockwork-Muse commented 8 years ago

@ericstj - My CPU is pegged, but it's listing dotnet.exe at >50% (as high as 80%). RuntimeBroker occasionally shows up in the 15-30% range, but is usually way lower, as are the various Windows Defender-related stuff.
I'm neither network nor disk bound, not at this point anyways. It spikes my network (and to a lesser extent, my disk) every few seconds/minute (possibly it's not redownloading everything, just checking it).

CIPop commented 8 years ago

I was able to fix the issue! I now see an acceptable 17min restore time!

Digging deeper I found that the build system is not contained to the enlistment folder. It actually keeps files and locks on the system drive within \Users (.nuget, AppData\Local\Nuget cache). One difference is that the machine with the problem has 2 clones of dotnet\core (which was my workaround for this issue: I'd keep one in working condition while the other is ). I believe that my workaround actually caused the problem given the contention and maybe race-conditions or accumulation of unwanted files within the shared location.

Workaround (I still think this is a design bug for the build system):

  1. Manually remove the following folders: Users\<username>\.nuget Users\<username>\AppData\Local\Nuget
  2. Run .\clean -all (instead of just .\clean) This took about 5-10 minutes and removes some of the files on the systemdrive.
  3. Remove all other clones or stop using them.
  4. Run .\sync; .\build. This time I've noticed that the operation had a lot of I/O (disk was at 100%) followed by a period of lower CPU usage (<60%).

I now see:

  [12:50:03.10] Restoring all packages...
  [13:06:30.21] Restoring all packages...Done.

Other notes:

karajas commented 8 years ago

I might need to look into this further, I was under the impression that --no-cache was enabled on all builds. It might be that we need to ensure a clean local cache prior to build.

Measuring logical cores is something I haven't done yet, but we do know nuget has contention issues. I can file an issue for this accordingly.

CIPop commented 8 years ago

With the fix from dotnet/corefx#12345 I get 6 minutes. Really good progress! Thanks @karajas!

Clockwork-Muse commented 8 years ago

Last run for me was a ~30 min, but that was while the machine was locked (this machine is too old to hibernate well, so I have no clue what happens there)

CIPop commented 8 years ago

@Clockwork-Muse Based on an offline discussion with @ericstj, the issue you are seeing could be different: caused by network speed, not the CPU. To check this theory:

  1. If not already done, please try the above workaround to start from a clean environment.
  2. Manually remove all .project.lock.json from the enlistment but keep the \packages folder. (Don't run .\clean.)
  3. Run .\build.

The difference between the time observed in step 1 and the time it takes to regenerate the lock files is time spent in network downloads.

Clockwork-Muse commented 8 years ago

The 33 minutes was from a clean environment (following the workaround). Manually remove the lock files and then running build makes that step take about ~10 minutes (for a difference of 20 minutes).

So sounds like network is/was my primary issue (not surprising).

mellinoe commented 7 years ago

We've made big progress on this recently. It should take nowhere near 1 hour now, unless your connection is extremely slow.