From 0e9afd2a56f279584af49aca1c4b72485df49a77 Mon Sep 17 00:00:00 2001 From: Bruce Dawson Date: Fri, 8 Nov 2019 18:57:08 +0000 Subject: [PATCH] Change "CPU time" to "elapsed time" The "CPU time" values printed by post_build_ninja_summary.py are not actually measure of CPU time, they are measures of wall-clock time or elapsed time. This just changes the labeling of the numbers - the actual numbers printed are unchanged. The "weighted time" number continues to be the more important number since it is an approximation of how much the build step(s) are affecting build time. See the comments in the script for details. Change-Id: Ibdb4efdd327ece34492ab10337c234a826514197 Reviewed-on: https://chromium-review.googlesource.com/c/chromium/tools/depot_tools/+/1900019 Commit-Queue: Bruce Dawson Reviewed-by: Dirk Pranke --- post_build_ninja_summary.py | 42 ++++++++++++++++--------------------- 1 file changed, 18 insertions(+), 24 deletions(-) diff --git a/post_build_ninja_summary.py b/post_build_ninja_summary.py index c5a868cbf5..04c1bc4809 100644 --- a/post_build_ninja_summary.py +++ b/post_build_ninja_summary.py @@ -24,26 +24,20 @@ Typical output looks like this: ninja.exe -C out\debug_component base -j 960 -l 48 -d keeprsp ninja: Entering directory `out\debug_component' [1 processes, 1/1 @ 0.3/s : 3.092s ] Regenerating ninja files -[1 processes, 23/23 @ 0.9/s : 26.280s ] LINK(DLL) base.dll base.dll.lib - Longest build steps: - 0.9 weighted s to build obj/base/base_jumbo_17.obj (5.0 s CPU time) - 1.0 weighted s to build obj/base/base_jumbo_31.obj (13.1 s CPU time) - 1.2 weighted s to build obj/base/base_jumbo_4.obj (14.7 s CPU time) - 1.3 weighted s to build obj/base/base_jumbo_32.obj (15.0 s CPU time) - 1.6 weighted s to build obj/base/base_jumbo_26.obj (17.1 s CPU time) - 1.7 weighted s to build base.dll, base.dll.lib (1.7 s CPU time) - 1.7 weighted s to build obj/base/base_jumbo_11.obj (15.9 s CPU time) - 1.9 weighted s to build obj/base/base_jumbo_12.obj (18.5 s CPU time) - 3.6 weighted s to build obj/base/base_jumbo_34.obj (20.1 s CPU time) - 4.3 weighted s to build obj/base/base_jumbo_33.obj (22.3 s CPU time) - Time by build-step type: - 0.1 s weighted time to generate 1 .c files (0.1 s CPU time) - 0.1 s weighted time to generate 1 .stamp files (0.1 s CPU time) - 0.2 s weighted time to generate 1 .h files (0.2 s CPU time) - 1.7 s weighted time to generate 1 PEFile files (1.7 s CPU time) - 24.3 s weighted time to generate 19 .obj files (233.4 s CPU time) - 26.3 s weighted time (235.5 s CPU time, 9.0x parallelism) - 23 build steps completed, average of 0.88/s +Longest build steps: + 0.1 weighted s to build obj/base/base/trace_log.obj (6.7 s elapsed time) + 0.2 weighted s to build nasm.exe, nasm.exe.pdb (0.2 s elapsed time) + 0.3 weighted s to build obj/base/base/win_util.obj (12.4 s elapsed time) + 1.2 weighted s to build base.dll, base.dll.lib (1.2 s elapsed time) +Time by build-step type: + 0.0 s weighted time to generate 6 .lib files (0.3 s elapsed time sum) + 0.1 s weighted time to generate 25 .stamp files (1.2 s elapsed time sum) + 0.2 s weighted time to generate 20 .o files (2.8 s elapsed time sum) + 1.7 s weighted time to generate 4 PEFile (linking) files (2.0 s elapsed +time sum) + 23.9 s weighted time to generate 770 .obj files (974.8 s elapsed time sum) +26.1 s weighted time (982.9 s elapsed time sum, 37.7x parallelism) +839 build steps completed, average of 32.17/s If no gn clean has been done then results will be for the last non-NULL invocation of ninja. Ideas for future statistics, and implementations are @@ -265,7 +259,7 @@ def SummarizeEntries(entries): print(' Longest build steps:') entries.sort(key=lambda x: x.WeightedDuration()) for target in entries[-long_count:]: - print(' %8.1f weighted s to build %s (%.1f s CPU time)' % ( + print(' %8.1f weighted s to build %s (%.1f s elapsed time)' % ( target.WeightedDuration(), target.DescribeTargets(), target.Duration())) @@ -288,11 +282,11 @@ def SummarizeEntries(entries): # Print the slowest build target types (by weighted time): for time, extension in weighted_time_by_ext_sorted[-long_ext_count:]: print(' %8.1f s weighted time to generate %d %s files ' - '(%1.1f s CPU time)' % (time, count_by_ext[extension], + '(%1.1f s elapsed time sum)' % (time, count_by_ext[extension], extension, time_by_ext[extension])) - print(' %.1f s weighted time (%.1f s CPU time, %1.1fx parallelism)' % ( - length, total_cpu_time, + print(' %.1f s weighted time (%.1f s elapsed time sum, %1.1fx ' + 'parallelism)' % (length, total_cpu_time, total_cpu_time * 1.0 / length)) print(' %d build steps completed, average of %1.2f/s' % ( len(entries), len(entries) / (length)))