Add --debug=time option. (Anthony Roach)

git-svn-id: http://scons.tigris.org/svn/scons/trunk@379 fdb21ef1-2011-0410-befe-b5e4ea1792b1

diff --git a/doc/man/scons.1 b/doc/man/scons.1
index 7df959a609c852009b2b98da8e649d0bd541af97..10ca9d1ebc0464053c100d40ea96d77a99b09f2d 100644 (file)
--- 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 0fad2309511eba17e12b4b38a277f00c97767240..db75777dd492acdeabb92174c8134eb898658202 100644 (file)
--- 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 2fbde13b905a421de666da4bd38d51694ed2cd91..e58d2d02aa377380853ddef4d56681da5951f469 100644 (file)
--- 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 74019fedf4cf8dc8e32c1e8519d8f08b53ec866f..a4cf39abd8760ebb7cdc7269a2fc215945673243 100644 (file)
--- 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()