From f6d223db8141b84c3c7e954d3d72db20678886c3 Mon Sep 17 00:00:00 2001 From: stevenknight Date: Thu, 23 May 2002 04:03:56 +0000 Subject: [PATCH] Add --debug=time option. (Anthony Roach) git-svn-id: http://scons.tigris.org/svn/scons/trunk@379 fdb21ef1-2011-0410-befe-b5e4ea1792b1 --- doc/man/scons.1 | 7 ++++ src/CHANGES.txt | 2 ++ src/engine/SCons/Script/__init__.py | 29 +++++++++++++++++ test/option--debug.py | 50 +++++++++++++++++++++++++++++ 4 files changed, 88 insertions(+) diff --git a/doc/man/scons.1 b/doc/man/scons.1 index 7df959a6..10ca9d1e 100644 --- a/doc/man/scons.1 +++ b/doc/man/scons.1 @@ -340,6 +340,13 @@ dependencies. Print the dependency tree after each top-level target is built. This prints out only derived files. +.TP +.RI --debug=time +Prints various time profiling information: the time spent +executing each build command, the total build time, the total time spent +executing build commands, the total time spent executing SConstruct and +SConscript files, and the total time spent executing SCons itself. + .TP -e, --environment-overrides Variables from the execution environment override construction diff --git a/src/CHANGES.txt b/src/CHANGES.txt index 0fad2309..db75777d 100644 --- a/src/CHANGES.txt +++ b/src/CHANGES.txt @@ -52,6 +52,8 @@ RELEASE 0.08 - - Fix .sconsign signature storage so that output files of one build can be safely used as input files to another build. + - Added a --debug=time option to print SCons execution times. + From Zed Shaw: - Add an Append() method to Environments, to append values to diff --git a/src/engine/SCons/Script/__init__.py b/src/engine/SCons/Script/__init__.py index 2fbde13b..e58d2d02 100644 --- a/src/engine/SCons/Script/__init__.py +++ b/src/engine/SCons/Script/__init__.py @@ -36,6 +36,9 @@ it goes here. __revision__ = "__FILE__ __REVISION__ __DATE__ __DEVELOPER__" +import time +start_time = time.time() + import getopt import os import os.path @@ -74,7 +77,15 @@ class BuildTask(SCons.Taskmaster.Task): else: try: self.targets[0].prepare() + if print_time: + start_time = time.time() self.targets[0].build() + if print_time: + finish_time = time.time() + global command_time + command_time = command_time+finish_time-start_time + print "Command execution time: %f seconds"%(finish_time-start_time) + except BuildError, e: sys.stderr.write("scons: *** [%s] %s\n" % (e.node, e.errstr)) if e.errstr == 'Exception': @@ -155,12 +166,16 @@ keep_going_on_error = 0 help_option = None print_tree = 0 print_dtree = 0 +print_time = 0 +sconscript_time = 0 +command_time = 0 climb_up = 0 target_top = None exit_status = 0 # exit status, assume success by default profiling = 0 max_drift = None + # utility functions def get_all_children(node): return node.all_children(None) @@ -436,6 +451,7 @@ def options_init(): def opt_debug(opt, arg): global print_tree global print_dtree + global print_time if arg == "pdb": args = [ sys.executable, "pdb.py" ] + \ filter(lambda x: x != "--debug=pdb", sys.argv) @@ -452,6 +468,8 @@ def options_init(): print_tree = 1 elif arg == "dtree": print_dtree = 1 + elif arg == "time": + print_time = 1 else: sys.stderr.write("Warning: %s is not a valid debug type\n" % arg) @@ -804,8 +822,11 @@ def _main(): sys.path = include_dirs + sys.path + start_time = time.time() for script in scripts: SCons.Script.SConscript.SConscript(script) + global sconscript_time + sconscript_time = time.time() - start_time SCons.Node.FS.default_fs.chdir(SCons.Node.FS.default_fs.Top) @@ -889,4 +910,12 @@ def main(): except: _scons_other_errors() + if print_time: + total_time = time.time()-start_time + scons_time = total_time-sconscript_time-command_time + print "Total build time: %f seconds"%total_time + print "Total SConscript file execution time: %f seconds"%sconscript_time + print "Total SCons execution time: %f seconds"%scons_time + print "Total command execution time: %f seconds"%command_time + sys.exit(exit_status) diff --git a/test/option--debug.py b/test/option--debug.py index 74019fed..a4cf39ab 100644 --- a/test/option--debug.py +++ b/test/option--debug.py @@ -27,6 +27,8 @@ __revision__ = "__FILE__ __REVISION__ __DATE__ __DEVELOPER__" import TestSCons import sys import string +import re +import time test = TestSCons.TestSCons() @@ -125,5 +127,53 @@ test.run(arguments = "--debug=pdb", stdin = "n\ns\nq\n") test.fail_test(string.find(test.stdout(), "(Pdb)") == -1) test.fail_test(string.find(test.stdout(), "scons") == -1) +test.write('foo.c', r""" +#include "foo.h" + +int main(int argc, char *argv[]) +{ + argv[argc++] = "--"; + printf("f1.c\n"); + exit (0); +} +""") + +test.write('bar.c', """ +#include "bar.h" + +""") + +############################ +# test --debug=time + +def num(match, line): + return float(re.match(match, line).group(1)) + +start_time = time.time() +test.run(program=sys.executable, arguments='-c pass') +overhead = time.time() - start_time + +start_time = time.time() +test.run(arguments = "--debug=time .") +expected_total_time = time.time() - start_time - overhead +line = string.split(test.stdout(), '\n') + +expected_command_time = num(r'Command execution time: (\d+\.\d+) seconds', line[1]) +expected_command_time = expected_command_time + num(r'Command execution time: (\d+\.\d+) seconds', line[3]) +expected_command_time = expected_command_time + num(r'Command execution time: (\d+\.\d+) seconds', line[5]) +expected_command_time = expected_command_time + num(r'Command execution time: (\d+\.\d+) seconds', line[6]) + +total_time = num(r'Total build time: (\d+\.\d+) seconds', line[7]) +sconscript_time = num(r'Total SConscript file execution time: (\d+\.\d+) seconds', line[8]) +scons_time = num(r'Total SCons execution time: (\d+\.\d+) seconds', line[9]) +command_time = num(r'Total command execution time: (\d+\.\d+) seconds', line[10]) + +def check(expected, actual, tolerance): + return abs((expected-actual)/actual) <= tolerance + +assert check(expected_command_time, command_time, 0.01) +assert check(total_time, sconscript_time+scons_time+command_time, 0.01) +assert check(total_time, expected_total_time, 0.1) + test.pass_test() -- 2.26.2