Merge pull request #16 from bdbaddog/add_sconscript_timing

Add printing time processing each SConscript when --debug=time is specified on command line

3 files changed, 24 insertions, 9 deletions

diff --git a/doc/man/scons.xml b/doc/man/scons.xml
index 1f99753a7..1f38b5d14 100644
--- a/doc/man/scons.xml
+++ b/doc/man/scons.xml
@@ -853,14 +853,18 @@ and ultimately removed.</para>
   <varlistentry>
   <term>--debug=time</term>
   <listitem>
-<para>Prints various time profiling information:
-the time spent executing each individual build command;
-the total build time (time SCons ran from beginning to end);
-the total time spent reading and executing SConscript files;
-the total time spent SCons itself spend running
-(that is, not counting reading and executing SConscript files);
-and both the total time spent executing all build commands
-and the elapsed wall-clock time spent executing those build commands.
+<para>Prints various time profiling information:</para>
+<itemizedlist>
+<listitem>The time spent executing each individual build command</listitem>
+<listitem>The total build time (time SCons ran from beginning to end)</listitem>
+<listitem>The total time spent reading and executing SConscript files</listitem>
+<listitem>The total time spent SCons itself spend running
+(that is, not counting reading and executing SConscript files)</listitem>
+<listitem>The total time spent executing all build commands</listitem>
+<listitem>The elapsed wall-clock time spent executing those build commands</listitem>
+<listitem>The time spent processing each file passed to the <emphasis>SConscript()</emphasis> function</listitem>
+</itemizedlist>
+<para>
 (When
 <command>scons</command>
 is executed without the
@@ -884,7 +888,8 @@ be significantly smaller than the
 total time spent executing all the build commands,
 since multiple build commands and
 intervening SCons processing
-should take place in parallel.)</para>
+should take place in parallel.)
+</para>
 
   </listitem>
   </varlistentry>
diff --git a/src/CHANGES.txt b/src/CHANGES.txt
index 373a9b3d4..07a19389c 100644
--- a/src/CHANGES.txt
+++ b/src/CHANGES.txt
@@ -23,6 +23,7 @@ RELEASE  VERSION/DATE TO BE FILLED IN LATER
       8 years ago it was being used as a boolean parameter.  Now you can specify sort to be a callable, or boolean
       value. (True = normal sort). Manpage also updated.
     - Fixed Tool loading logic from exploding sys.path with many site_scons/site_tools prepended on py3.
+    - Added additional output with time to process each SConscript file when using --debug=time.
 
   From Thomas Berg:
     - Fixed a regression in scons-3.0.0 where "from __future__ import print_function" was imposed
diff --git a/src/engine/SCons/Script/SConscript.py b/src/engine/SCons/Script/SConscript.py
index 8fea9c4da..db6552ce0 100644
--- a/src/engine/SCons/Script/SConscript.py
+++ b/src/engine/SCons/Script/SConscript.py
@@ -44,12 +44,15 @@ import SCons.Script.Main
 import SCons.Tool
 import SCons.Util
 
+from . import Main
+
 import collections
 import os
 import os.path
 import re
 import sys
 import traceback
+import time
 
 class SConscriptReturn(Exception):
     pass
@@ -247,11 +250,17 @@ def _SConscript(fs, *files, **kw):
                     try:
                         try:
 #                            _file_ = SCons.Util.to_str(_file_)
+                            if Main.print_time:
+                                time1 = time.time()
                             exec(compile(_file_.read(), _file_.name, 'exec'),
                                  call_stack[-1].globals)
                         except SConscriptReturn:
                             pass
                     finally:
+                        if Main.print_time:
+                            time2 = time.time()
+                            print('SConscript:%s  took %0.3f ms' % (f.get_abspath(), (time2 - time1) * 1000.0))
+
                         if old_file is not None:
                             call_stack[-1].globals.update({__file__:old_file})
                 else: