1+ #!/usr/bin/env python3
2+ # Copyright (c) 2018 The Chromium Authors. All rights reserved.
3+ # Use of this source code is governed by a BSD-style license that can be
4+ # found in the LICENSE file.
5+ """Summarize the last ninja build, invoked with ninja's -C syntax.
6+ This script is designed to be automatically run after each ninja build in
7+ order to summarize the build's performance. Making build performance information
8+ more visible should make it easier to notice anomalies and opportunities. To use
9+ this script on Windows just set NINJA_SUMMARIZE_BUILD=1 and run autoninja.bat.
10+ On Linux you can get autoninja to invoke this script using this syntax:
11+ $ NINJA_SUMMARIZE_BUILD=1 autoninja -C out/Default/ chrome
12+ You can also call this script directly using ninja's syntax to specify the
13+ output directory of interest:
14+ > python3 post_build_ninja_summary.py -C out/Default
15+ Typical output looks like this:
16+ >ninja -C out\debug_component base
17+ ninja.exe -C out\debug_component base -j 960 -l 48 -d keeprsp
18+ ninja: Entering directory `out\debug_component'
19+ [1 processes, 1/1 @ 0.3/s : 3.092s ] Regenerating ninja files
20+ Longest build steps:
21+ 0.1 weighted s to build obj/base/base/trace_log.obj (6.7 s elapsed time)
22+ 0.2 weighted s to build nasm.exe, nasm.exe.pdb (0.2 s elapsed time)
23+ 0.3 weighted s to build obj/base/base/win_util.obj (12.4 s elapsed time)
24+ 1.2 weighted s to build base.dll, base.dll.lib (1.2 s elapsed time)
25+ Time by build-step type:
26+ 0.0 s weighted time to generate 6 .lib files (0.3 s elapsed time sum)
27+ 0.1 s weighted time to generate 25 .stamp files (1.2 s elapsed time sum)
28+ 0.2 s weighted time to generate 20 .o files (2.8 s elapsed time sum)
29+ 1.7 s weighted time to generate 4 PEFile (linking) files (2.0 s elapsed
30+ time sum)
31+ 23.9 s weighted time to generate 770 .obj files (974.8 s elapsed time sum)
32+ 26.1 s weighted time (982.9 s elapsed time sum, 37.7x parallelism)
33+ 839 build steps completed, average of 32.17/s
34+ If no gn clean has been done then results will be for the last non-NULL
35+ invocation of ninja. Ideas for future statistics, and implementations are
36+ appreciated.
37+ The "weighted" time is the elapsed time of each build step divided by the number
38+ of tasks that were running in parallel. This makes it an excellent approximation
39+ of how "important" a slow step was. A link that is entirely or mostly serialized
40+ will have a weighted time that is the same or similar to its elapsed time. A
41+ compile that runs in parallel with 999 other compiles will have a weighted time
42+ that is tiny."""
43+ import argparse
44+ import errno
45+ import fnmatch
46+ import os
47+ import sys
48+ # The number of long build times to report:
49+ long_count = 10
50+ # The number of long times by extension to report
51+ long_ext_count = 10
52+ class Target :
53+ """Represents a single line read for a .ninja_log file."""
54+ def __init__ (self , start , end ):
55+ """Creates a target object by passing in the start/end times in seconds
56+ as a float."""
57+ self .start = start
58+ self .end = end
59+ # A list of targets, appended to by the owner of this object.
60+ self .targets = []
61+ self .weighted_duration = 0.0
62+ def Duration (self ):
63+ """Returns the task duration in seconds as a float."""
64+ return self .end - self .start
65+ def SetWeightedDuration (self , weighted_duration ):
66+ """Sets the duration, in seconds, passed in as a float."""
67+ self .weighted_duration = weighted_duration
68+ def WeightedDuration (self ):
69+ """Returns the task's weighted duration in seconds as a float.
70+ Weighted_duration takes the elapsed time of the task and divides it
71+ by how many other tasks were running at the same time. Thus, it
72+ represents the approximate impact of this task on the total build time,
73+ with serialized or serializing steps typically ending up with much
74+ longer weighted durations.
75+ weighted_duration should always be the same or shorter than duration.
76+ """
77+ # Allow for modest floating-point errors
78+ epsilon = 0.000002
79+ if (self .weighted_duration > self .Duration () + epsilon ):
80+ print ('%s > %s?' % (self .weighted_duration , self .Duration ()))
81+ assert (self .weighted_duration <= self .Duration () + epsilon )
82+ return self .weighted_duration
83+ def DescribeTargets (self ):
84+ """Returns a printable string that summarizes the targets."""
85+ # Some build steps generate dozens of outputs - handle them sanely.
86+ # The max_length was chosen so that it can fit most of the long
87+ # single-target names, while minimizing word wrapping.
88+ result = ', ' .join (self .targets )
89+ max_length = 65
90+ if len (result ) > max_length :
91+ result = result [:max_length ] + '...'
92+ return result
93+ # Copied with some modifications from ninjatracing
94+ def ReadTargets (log , show_all ):
95+ """Reads all targets from .ninja_log file |log_file|, sorted by duration.
96+ The result is a list of Target objects."""
97+ header = log .readline ()
98+ assert header == '# ninja log v5\n ' , \
99+ 'unrecognized ninja log version %r' % header
100+ targets_dict = {}
101+ last_end_seen = 0.0
102+ for line in log :
103+ parts = line .strip ().split ('\t ' )
104+ if len (parts ) != 5 :
105+ # If ninja.exe is rudely halted then the .ninja_log file may be
106+ # corrupt. Silently continue.
107+ continue
108+ start , end , _ , name , cmdhash = parts # Ignore restat.
109+ # Convert from integral milliseconds to float seconds.
110+ start = int (start ) / 1000.0
111+ end = int (end ) / 1000.0
112+ if not show_all and end < last_end_seen :
113+ # An earlier time stamp means that this step is the first in a new
114+ # build, possibly an incremental build. Throw away the previous
115+ # data so that this new build will be displayed independently.
116+ # This has to be done by comparing end times because records are
117+ # written to the .ninja_log file when commands complete, so end
118+ # times are guaranteed to be in order, but start times are not.
119+ targets_dict = {}
120+ target = None
121+ if cmdhash in targets_dict :
122+ target = targets_dict [cmdhash ]
123+ if not show_all and (target .start != start or target .end != end ):
124+ # If several builds in a row just run one or two build steps then
125+ # the end times may not go backwards so the last build may not be
126+ # detected as such. However in many cases there will be a build step
127+ # repeated in the two builds and the changed start/stop points for
128+ # that command, identified by the hash, can be used to detect and
129+ # reset the target dictionary.
130+ targets_dict = {}
131+ target = None
132+ if not target :
133+ targets_dict [cmdhash ] = target = Target (start , end )
134+ last_end_seen = end
135+ target .targets .append (name )
136+ return list (targets_dict .values ())
137+ def GetExtension (target , extra_patterns ):
138+ """Return the file extension that best represents a target.
139+ For targets that generate multiple outputs it is important to return a
140+ consistent 'canonical' extension. Ultimately the goal is to group build steps
141+ by type."""
142+ for output in target .targets :
143+ if extra_patterns :
144+ for fn_pattern in extra_patterns .split (';' ):
145+ if fnmatch .fnmatch (output , '*' + fn_pattern + '*' ):
146+ return fn_pattern
147+ # Not a true extension, but a good grouping.
148+ if output .endswith ('type_mappings' ):
149+ extension = 'type_mappings'
150+ break
151+ # Capture two extensions if present. For example: file.javac.jar should be
152+ # distinguished from file.interface.jar.
153+ root , ext1 = os .path .splitext (output )
154+ _ , ext2 = os .path .splitext (root )
155+ extension = ext2 + ext1 # Preserve the order in the file name.
156+ if len (extension ) == 0 :
157+ extension = '(no extension found)'
158+ if ext1 in ['.pdb' , '.dll' , '.exe' ]:
159+ extension = 'PEFile (linking)'
160+ # Make sure that .dll and .exe are grouped together and that the
161+ # .dll.lib files don't cause these to be listed as libraries
162+ break
163+ if ext1 in ['.so' , '.TOC' ]:
164+ extension = '.so (linking)'
165+ # Attempt to identify linking, avoid identifying as '.TOC'
166+ break
167+ # Make sure .obj files don't get categorized as mojo files
168+ if ext1 in ['.obj' , '.o' ]:
169+ break
170+ # Jars are the canonical output of java targets.
171+ if ext1 == '.jar' :
172+ break
173+ # Normalize all mojo related outputs to 'mojo'.
174+ if output .count ('.mojom' ) > 0 :
175+ extension = 'mojo'
176+ break
177+ return extension
178+ def SummarizeEntries (entries , extra_step_types ):
179+ """Print a summary of the passed in list of Target objects."""
180+ # Create a list that is in order by time stamp and has entries for the
181+ # beginning and ending of each build step (one time stamp may have multiple
182+ # entries due to multiple steps starting/stopping at exactly the same time).
183+ # Iterate through this list, keeping track of which tasks are running at all
184+ # times. At each time step calculate a running total for weighted time so
185+ # that when each task ends its own weighted time can easily be calculated.
186+ task_start_stop_times = []
187+ earliest = - 1
188+ latest = 0
189+ total_cpu_time = 0
190+ for target in entries :
191+ if earliest < 0 or target .start < earliest :
192+ earliest = target .start
193+ if target .end > latest :
194+ latest = target .end
195+ total_cpu_time += target .Duration ()
196+ task_start_stop_times .append ((target .start , 'start' , target ))
197+ task_start_stop_times .append ((target .end , 'stop' , target ))
198+ length = latest - earliest
199+ weighted_total = 0.0
200+ # Sort by the time/type records and ignore |target|
201+ task_start_stop_times .sort (key = lambda times : times [:2 ])
202+ # Now we have all task start/stop times sorted by when they happen. If a
203+ # task starts and stops on the same time stamp then the start will come
204+ # first because of the alphabet, which is important for making this work
205+ # correctly.
206+ # Track the tasks which are currently running.
207+ running_tasks = {}
208+ # Record the time we have processed up to so we know how to calculate time
209+ # deltas.
210+ last_time = task_start_stop_times [0 ][0 ]
211+ # Track the accumulated weighted time so that it can efficiently be added
212+ # to individual tasks.
213+ last_weighted_time = 0.0
214+ # Scan all start/stop events.
215+ for event in task_start_stop_times :
216+ time , action_name , target = event
217+ # Accumulate weighted time up to now.
218+ num_running = len (running_tasks )
219+ if num_running > 0 :
220+ # Update the total weighted time up to this moment.
221+ last_weighted_time += (time - last_time ) / float (num_running )
222+ if action_name == 'start' :
223+ # Record the total weighted task time when this task starts.
224+ running_tasks [target ] = last_weighted_time
225+ if action_name == 'stop' :
226+ # Record the change in the total weighted task time while this task ran.
227+ weighted_duration = last_weighted_time - running_tasks [target ]
228+ target .SetWeightedDuration (weighted_duration )
229+ weighted_total += weighted_duration
230+ del running_tasks [target ]
231+ last_time = time
232+ assert (len (running_tasks ) == 0 )
233+ # Warn if the sum of weighted times is off by more than half a second.
234+ if abs (length - weighted_total ) > 500 :
235+ print ('Warning: Possible corrupt ninja log, results may be '
236+ 'untrustworthy. Length = %.3f, weighted total = %.3f' % (
237+ length , weighted_total ))
238+ # Print the slowest build steps (by weighted time).
239+ print (' Longest build steps:' )
240+ entries .sort (key = lambda x : x .WeightedDuration ())
241+ for target in entries [- long_count :]:
242+ print (' %8.1f weighted s to build %s (%.1f s elapsed time)' % (
243+ target .WeightedDuration (),
244+ target .DescribeTargets (), target .Duration ()))
245+ # Sum up the time by file extension/type of the output file
246+ count_by_ext = {}
247+ time_by_ext = {}
248+ weighted_time_by_ext = {}
249+ # Scan through all of the targets to build up per-extension statistics.
250+ for target in entries :
251+ extension = GetExtension (target , extra_step_types )
252+ time_by_ext [extension ] = time_by_ext .get (extension , 0 ) + target .Duration ()
253+ weighted_time_by_ext [extension ] = weighted_time_by_ext .get (extension ,
254+ 0 ) + target .WeightedDuration ()
255+ count_by_ext [extension ] = count_by_ext .get (extension , 0 ) + 1
256+ print (' Time by build-step type:' )
257+ # Copy to a list with extension name and total time swapped, to (time, ext)
258+ weighted_time_by_ext_sorted = sorted ((y , x ) for (x , y ) in
259+ weighted_time_by_ext .items ())
260+ # Print the slowest build target types (by weighted time):
261+ for time , extension in weighted_time_by_ext_sorted [- long_ext_count :]:
262+ print (' %8.1f s weighted time to generate %d %s files '
263+ '(%1.1f s elapsed time sum)' % (time , count_by_ext [extension ],
264+ extension , time_by_ext [extension ]))
265+ print (' %.1f s weighted time (%.1f s elapsed time sum, %1.1fx '
266+ 'parallelism)' % (length , total_cpu_time ,
267+ total_cpu_time * 1.0 / length ))
268+ print (' %d build steps completed, average of %1.2f/s' % (
269+ len (entries ), len (entries ) / (length )))
270+ def main ():
271+ log_file = '.ninja_log'
272+ parser = argparse .ArgumentParser ()
273+ parser .add_argument ('-C' , dest = 'build_directory' ,
274+ help = 'Build directory.' )
275+ parser .add_argument (
276+ '-s' ,
277+ '--step-types' ,
278+ help = 'semicolon separated fnmatch patterns for build-step grouping' )
279+ parser .add_argument ('--log-file' ,
280+ help = "specific ninja log file to analyze." )
281+ args , _extra_args = parser .parse_known_args ()
282+ if args .build_directory :
283+ log_file = os .path .join (args .build_directory , log_file )
284+ if args .log_file :
285+ log_file = args .log_file
286+ if not args .step_types :
287+ # Offer a convenient way to add extra step types automatically, including
288+ # when this script is run by autoninja. get() returns None if the variable
289+ # isn't set.
290+ args .step_types = os .environ .get ('chromium_step_types' )
291+ if args .step_types :
292+ # Make room for the extra build types.
293+ global long_ext_count
294+ long_ext_count += len (args .step_types .split (';' ))
295+ try :
296+ with open (log_file , 'r' ) as log :
297+ entries = ReadTargets (log , False )
298+ SummarizeEntries (entries , args .step_types )
299+ except IOError :
300+ print ('Log file %r not found, no build summary created.' % log_file )
301+ return errno .ENOENT
302+ if __name__ == '__main__' :
303+ sys .exit (main ())
0 commit comments