BlythMeister
Reputation: 299
MSBuild Duration
I have a solution with around 1000 projects and the build duration total is around 4 and a half minutes.
I want to be able to diagnose what that 4 and a half minutes is spent doing to try and establish if the build process can be optimised.
Is there a way to get this sort of information?
EDIT: this is always on a clean checkout, so a full build (not rebuild) will always occur.
Upvotes: 0
Views: 407
Answers (2)
UserName
Reputation: 895
You can use /ds (/detailedsummary) option of MSBuild CLI.
/ds:
Show detailed information at the end of the build log about the configurations that were built and how they were scheduled to nodes.
Example output:
Detailed Build Summary
======================
============================== Build Hierarchy (IDs represent configurations) =====================================================
Id : Exclusive Time Total Time Path (Targets)
———————————————————————————————————————————–
0 : 0.036s 0.295s F:BugsMultiProccir1.proj (ParallelBuild)
| 1 : 0.047s 0.047s F:BugsMultiProccir2.proj ()
| 3 : 0.209s 0.209s F:BugsMultiProccir4.proj ()
| 2 : 0.210s 0.210s F:BugsMultiProccir3.proj ()
| 4 : 0.212s 0.217s F:BugsMultiProccir5.proj ()
| | 10 : 0.005s 0.005s F:BugsMultiProccir8.proj ()
| . 11 : 0.003s 0.003s F:BugsMultiProccir9.proj ()
| 5 : 0.001s 0.001s F:BugsMultiProccir6.proj ()
. 6 : 0.003s 0.015s F:BugsMultiProccir7.proj ()
| . 7 : 0.004s 0.012s F:BugsMultiProccir5.proj ()
| | | 8 : 0.007s 0.007s F:BugsMultiProccir8.proj ()
| | . 9 : 0.001s 0.001s F:BugsMultiProccir9.proj ()
============================== Node Utilization (IDs represent configurations) ====================================================
Timestamp: 1 2 3 4 Duration Cumulative
———————————————————————————————————————————–
634032540333349050: 0 x x x 0.035s 0.035s
634032540333699050: 1 x x x 0.041s 0.076s
634032540334109050: | 4 2 3 0.006s 0.082s
634032540334169050: 5 | | | 0.001s 0.083s
634032540334179050: 6 | | | 0.002s 0.085s
634032540334199050: 7 | | | 0.002s 0.087s
634032540334219050: 8 | | | 0.007s 0.094s
634032540334289050: 9 | | | 0.001s 0.095s
634032540334299050: 7 | | | 0.002s 0.097s
634032540334319050: 6 | | | 0.001s 0.098s
634032540334329050: x | | | 0.188s 0.286s ###
634032540336209050: x x 10 11 0.003s 0.289s
634032540336239050: x x | x 0.002s 0.291s
634032540336259050: x 4 x x 0.003s 0.294s
634032540336289050: 0 x x x 0.002s 0.296s
———————————————————————————————————————————–
Utilization: 33.8 96.8 97.7 96.8 Average Utilization: 81.3
MSBuild 4 Detailed Build Summary
Or you can try set /verbosity:diag - MSBuildVerbosity. After build at end of log you get the same results. My example log is not full, because it has personality information.
============================== Node Utilization (IDs represent configurations) ====================================================
Timestamp: 1 Duration Cumulative
----------------------------------------------------------------------------------------------------------------------------------- (TaskId:0)
636605029034003906: 0 0,278s 0,278s ##### (TaskId:0)
636605029036787109: 1 2,406s 2,685s ################################################ (TaskId:0)
636605029060849609: 4 0,874s 3,559s ################# (TaskId:0)
636605029069589843: 5 0,796s 4,354s ############### (TaskId:0)
636605029077548828: 1 0,235s 4,590s #### (TaskId:0)
636605029079902343: 3 6,171s 10,761s ########################################################################################################################### (TaskId:0)
636605029141611328: 2 0,854s 11,614s ################# (TaskId:0)
636605029150146484: 6 2,154s 13,769s ########################################### (TaskId:0)
636605029171689453: 2 8,570s 22,339s ########################################################################################################################################################################### (TaskId:0)
636605029257392578: 1 0,006s 22,345s (TaskId:0)
636605029257451171: 7 4,986s 27,331s ################################################################################################### (TaskId:0)
636605029307314453: 1 14,229s 41,560s ############################################################################################################################################################################################################
################################################################################ (TaskId:0)
636605029449599609: 0 0,003s 41,563s (TaskId:0)
-----------------------------------------------------------------------------------------------------------------------------------
Utilization: 100,0 Average Utilization: 100,0 (TaskId:0)
Target Performance Summary:
0 ms PrepareResources 3 calls
0 ms SetWin32ManifestProperties 3 calls
0 ms ResGen 3 calls
0 ms AfterResGen 3 calls
0 ms CreateSatelliteAssemblies 3 calls
0 ms BeforeResGen 3 calls
0 ms PrepareResourceNames 3 calls
0 ms CreateCustomManifestResourceNames 3 calls
0 ms ComputeIntermediateSatelliteAssemblies 1 calls
0 ms GetTargetPath 3 calls
0 ms Compile 3 calls
0 ms AfterMarkupCompilePass1 3 calls
0 ms ResolveReferences 3 calls
0 ms BeforeCompile 3 calls
0 ms _CopySourceItemsToOutputDirectory 3 calls
0 ms PrepareForRun 3 calls
0 ms AfterResolveReferences 3 calls
0 ms PrepareProjectReferences 3 calls
0 ms ValidateToolsVersions 1 calls
0 ms ValidateProjects 1 calls
0 ms GetNativeManifest 2 calls
0 ms BeforeBuild 3 calls
0 ms BuildOnlySettings 3 calls
0 ms _AfterCompileWinFXInternal 3 calls
0 ms CoreBuild 3 calls
0 ms BeforeResolveReferences 3 calls
0 ms AfterCompileWinFX 3 calls
0 ms AfterBuild 3 calls
0 ms AfterCompile 3 calls
1 ms GetTargetFrameworks 2 calls
1 ms ExpandSDKReferences 3 calls
2 ms _BeforeVBCSCoreCompile 3 calls
2 ms GenerateSatelliteAssemblies 1 calls
2 ms ExpressionBuildExtension 3 calls
2 ms ValidationExtension 3 calls
3 ms _CheckForCompileOutputs 3 calls
3 ms FileClassification 3 calls
5 ms CopySilverlightApplications 1 calls
6 ms _CopyAppConfigFile 1 calls
9 ms ResolveKeySource 3 calls
13 ms PrepareForBuild 3 calls
14 ms _SetEmbeddedWin32ManifestProperties 3 calls
17 ms _SplitProjectReferencesByFileExistence 3 calls
20 ms GenerateTargetFrameworkMonikerAttribute 3 calls
25 ms GetCopyToOutputDirectoryXamlAppDefs 3 calls
34 ms _GenerateCompileInputs 3 calls
35 ms GetFrameworkPaths 3 calls
38 ms AssignProjectConfiguration 3 calls
45 ms CleanXsdCodeGen 3 calls
55 ms ResolveCodeAnalysisRuleSet 3 calls
56 ms PreXsdCodeGen 3 calls
58 ms _SetTargetFrameworkMonikerAttribute 3 calls
62 ms GetTargetPathWithTargetPlatformMoniker 3 calls
66 ms CoreCompile 3 calls
66 ms _GenerateSatelliteAssemblyInputs 3 calls
71 ms GetReferenceAssemblyPaths 3 calls
76 ms ImplicitlyExpandDesignTimeFacades 3 calls
81 ms ValidateSolutionConfiguration 1 calls
82 ms GetCopyToOutputDirectoryItems 3 calls
88 ms CopyFilesToOutputDirectory 3 calls
97 ms ResolveSDKReferences 3 calls
105 ms _CheckForInvalidConfigurationAndPlatform 3 calls
611 ms SplitResourcesByCulture 3 calls
642 ms CreateManifestResourceNames 1 calls
798 ms ResolveNuGetPackageAssets 2 calls
1008 ms FindReferenceAssembliesForReferences 3 calls
1177 ms _BuiltWebOutputGroupOutput 1 calls
1249 ms CoreResGen 3 calls
1632 ms IncrementalClean 3 calls
1659 ms _CopyFilesMarkedCopyLocal 2 calls
1984 ms _HandlePackageFileConflicts 3 calls
2005 ms _GetProjectReferenceTargetFrameworkProperties 3 calls
2292 ms AssignTargetPaths 3 calls
3007 ms _GenerateCompileDependencyCache 3 calls
4538 ms ResolveAssemblyReferences 3 calls
6253 ms _CleanGetCurrentAndPriorFileWrites 3 calls
25037 ms ResolveProjectReferences 3 calls
41369 ms Build 4 calls
Task Performance Summary:
3 ms FindAppConfigFile 2 calls
6 ms MakeDir 3 calls
7 ms ResolveKeySource 3 calls
7 ms WriteLinesToFile 3 calls
7 ms Touch 2 calls
8 ms GetFrameworkPath 3 calls
12 ms GetReferenceAssemblyPaths 3 calls
27 ms AssignProjectConfiguration 3 calls
35 ms Message 10 calls
42 ms Delete 6 calls
52 ms CallTarget 3 calls
55 ms ResolveCodeAnalysisRuleSet 3 calls
99 ms GetReferenceNearestTargetFrameworkTask 2 calls
128 ms ReadLinesFromFile 3 calls
163 ms AssignCulture 3 calls
300 ms CreateCSharpManifestResourceName 2 calls
463 ms ResolveNuGetPackageAssets 2 calls
590 ms GenerateResource 1 calls
1007 ms ResolvePackageFileConflicts 3 calls
1177 ms CreateItem 3 calls
1498 ms Hash 3 calls
1661 ms ConvertToAbsolutePath 3 calls
1712 ms Copy 9 calls
2040 ms RemoveDuplicates 6 calls
2104 ms AssignTargetPath 18 calls
2583 ms FindUnderPath 15 calls
4530 ms ResolveAssemblyReference 3 calls
68091 ms MSBuild
10 calls
Upvotes: 1
Tanveer Badar
Reputation: 5512
There is indeed. Kirill Osenkov wrote two very helpful blog posts on the very subject.
You should try following the steps listed in them to get an idea of what's going on.
Upvotes: 0
Related Questions
- Log the time taken in each task when running a msbuild build
- Speeding up build times in ASP.NET
- MSBUILD.exe is executing very slow
- Why building project using msbuild is way slower than using visual studio IDE?
- Why msbuild is so slow when nothing has changed since the last build of the solution?
- How to decrease MSBuild times
- Speed up MSBuild build process
- why doesn't Visual Studio 2010 (msbuild?) build faster?
- Visual Studio Build Time
- msbuild timeout