Merge pull request #3456 from edobez/master

Debug option "timestamp"

5 files changed, 153 insertions, 3 deletions

diff --git a/doc/man/scons.xml b/doc/man/scons.xml
index 9065f25..b346cac 100644
--- a/doc/man/scons.xml
+++ b/doc/man/scons.xml
@@ -890,9 +890,43 @@ since multiple build commands and
 intervening SCons processing
 should take place in parallel.)
 </para>
-
   </listitem>
   </varlistentry>
+
+<varlistentry>
+  <term>--debug=action_timestamps</term>
+  <listitem>
+    <para>Prints additional time profiling information:</para>
+    <itemizedlist>
+      <listitem>
+        <para>The time spent executing each individual build command</para>
+      </listitem>
+      <listitem>
+        <para>The total build time (time SCons ran from beginning to end)</para>
+      </listitem>
+      <listitem>
+        <para>The total time spent reading and executing SConscript files</para>
+      </listitem>
+      <listitem>
+        <para>The total time spent SCons itself spend running
+(that is, not counting reading and executing SConscript files)</para>
+      </listitem>
+      <listitem>
+        <para>The total time spent executing all build commands</para>
+      </listitem>
+      <listitem>
+        <para>The elapsed wall-clock time spent executing those build commands</para>
+      </listitem>
+      <listitem>
+        <para>The absolute start and end wall-clock time spent executing those build commands</para>
+      </listitem>
+      <listitem>
+        <para>The time spent processing each file passed to the <emphasis>SConscript()</emphasis> function</para>
+      </listitem>
+    </itemizedlist>
+  </listitem>
+</varlistentry>
+
   <varlistentry>
   <term>--diskcheck=<emphasis>types</emphasis></term>
   <listitem>
diff --git a/src/CHANGES.txt b/src/CHANGES.txt
index 0a30bfa..260cb91 100755
--- a/src/CHANGES.txt
+++ b/src/CHANGES.txt
@@ -25,6 +25,9 @@ RELEASE  VERSION/DATE TO BE FILLED IN LATER
 
   From Jakub Kulik
     - Fix subprocess result bytes not being decoded in SunOS/Solaris related tools.
+    
+  From Edoardo Bezzeccheri
+    - Added debug option "action_timestamps" which outputs to stdout the absolute start and end time for each target.
 
 RELEASE 3.1.1 - Mon, 07 Aug 2019 20:09:12 -0500
 
diff --git a/src/engine/SCons/Script/Main.py b/src/engine/SCons/Script/Main.py
index acc8678..58dbf64 100644
--- a/src/engine/SCons/Script/Main.py
+++ b/src/engine/SCons/Script/Main.py
@@ -75,6 +75,7 @@ print_objects = 0
 print_memoizer = 0
 print_stacktrace = 0
 print_time = 0
+print_action_timestamps = 0
 sconscript_time = 0
 cumulative_command_time = 0
 exit_status = 0   # final exit status, assume success by default
@@ -209,7 +210,11 @@ class BuildTask(SCons.Taskmaster.OutOfDateTask):
             finish_time = time.time()
             last_command_end = finish_time
             cumulative_command_time = cumulative_command_time+finish_time-start_time
+            if print_action_timestamps:
+                sys.stdout.write("Command execution start time: %s: %f seconds\n"%(str(self.node), start_time))
             sys.stdout.write("Command execution time: %s: %f seconds\n"%(str(self.node), finish_time-start_time))
+            if print_action_timestamps:
+                sys.stdout.write("Command execution stop time: %s: %f seconds\n"%(str(self.node), finish_time))
 
     def do_failed(self, status=2):
         _BuildFailures.append(self.exception[1])
@@ -636,7 +641,7 @@ def _SConstruct_exists(dirname='', repositories=[], filelist=None):
     return None
 
 def _set_debug_values(options):
-    global print_memoizer, print_objects, print_stacktrace, print_time
+    global print_memoizer, print_objects, print_stacktrace, print_time, print_action_timestamps
 
     debug_values = options.debug
 
@@ -674,6 +679,9 @@ def _set_debug_values(options):
         options.tree_printers.append(TreePrinter(status=True))
     if "time" in debug_values:
         print_time = 1
+    if "action_timestamps" in debug_values:
+        print_time = 1
+        print_action_timestamps = 1
     if "tree" in debug_values:
         options.tree_printers.append(TreePrinter())
     if "prepare" in debug_values:
diff --git a/src/engine/SCons/Script/SConsOptions.py b/src/engine/SCons/Script/SConsOptions.py
index add1150..7b5d523 100644
--- a/src/engine/SCons/Script/SConsOptions.py
+++ b/src/engine/SCons/Script/SConsOptions.py
@@ -622,7 +622,7 @@ def Parser(version):
     debug_options = ["count", "duplicate", "explain", "findlibs",
                      "includes", "memoizer", "memory", "objects",
                      "pdb", "prepare", "presub", "stacktrace",
-                     "time"]
+                     "time", "action_timestamps"]
 
     def opt_debug(option, opt, value__, parser,
                   debug_options=debug_options,
diff --git a/test/option/debug-action-timestamps.py b/test/option/debug-action-timestamps.py
new file mode 100644
index 0000000..11a4bf5
--- /dev/null
+++ b/test/option/debug-action-timestamps.py
@@ -0,0 +1,105 @@
+#!/usr/bin/env python
+#
+# __COPYRIGHT__
+#
+# Permission is hereby granted, free of charge, to any person obtaining
+# a copy of this software and associated documentation files (the
+# "Software"), to deal in the Software without restriction, including
+# without limitation the rights to use, copy, modify, merge, publish,
+# distribute, sublicense, and/or sell copies of the Software, and to
+# permit persons to whom the Software is furnished to do so, subject to
+# the following conditions:
+#
+# The above copyright notice and this permission notice shall be included
+# in all copies or substantial portions of the Software.
+#
+# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY
+# KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE
+# WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
+# NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
+# LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
+# OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
+# WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+from __future__ import division, print_function
+
+__revision__ = "__FILE__ __REVISION__ __DATE__ __DEVELOPER__"
+
+import TestSCons
+import re
+
+_python_ = TestSCons._python_
+
+def setup_fixtures():
+    test.file_fixture('../fixture/test_main.c', 'main.c')
+    test.write('SConstruct', """
+DefaultEnvironment(tools=[])
+env = Environment()
+env.Program('main.exe', ['main.c'])
+""")
+
+def test_help_function():
+    # Before anything else, make sure we get valid --debug=action_timestamps results
+    # when just running the help option.
+    test.run(arguments = "-h --debug=action_timestamps")
+    
+def build():
+    # Execute build
+    test.run(arguments='--debug=action_timestamps')
+    build_output = test.stdout()
+    return build_output
+
+def get_matches_from_output(build_output):
+    return [re.findall(pattern, build_output) for pattern in debug_time_patterns]
+
+def test_presence_of_debug_time_strings(build_output):
+    # Check presence of duration and timestamps
+    if None in get_matches_from_output(build_output):
+        print("One or more of the time debug strings were not found in the build output")
+        test.fail_test(1)
+
+def test_equal_number_of_debug_time_strings(build_output):
+    matches = get_matches_from_output(build_output)
+    num_of_matches = [len(match) for match in matches]
+
+    # Check that the number of matches for each pattern is the same
+    if num_of_matches.count(num_of_matches[0]) != len(num_of_matches):
+        print("Debug time strings differs in quantity")
+        test.fail_test(2)
+
+def test_correctness_of_timestamps(build_output):
+    # Check if difference between timestamps is equal to duration
+    matches = get_matches_from_output(build_output)
+
+    def match_to_float(m): 
+        return float(m[1][1])
+
+    execution_time = match_to_float(matches[0])
+    start_time = match_to_float(matches[1])
+    stop_time = match_to_float(matches[2])
+    delta_time = stop_time - start_time
+
+    def within_tolerance(expected, actual, tolerance):
+        return abs((expected-actual)/actual) <= tolerance
+
+    if not within_tolerance(execution_time, delta_time, 0.001):
+        print("Difference of timestamps differ from action duration")
+        print("Execution time = {}. Start time = {}. Stop time = {}. Delta time = {}".format(execution_time, start_time, stop_time, delta_time))
+        test.fail_test(3)
+
+debug_time_patterns = [
+    r'Command execution time: (.*): (\d+\.\d+) seconds',
+    r'Command execution start time: (.*): (\d+\.\d+) seconds',
+    r'Command execution stop time: (.*): (\d+\.\d+) seconds'
+]
+
+test = TestSCons.TestSCons()
+setup_fixtures()
+
+test_help_function()
+
+build_output = build()
+test_presence_of_debug_time_strings(build_output)
+test_equal_number_of_debug_time_strings(build_output)
+test_correctness_of_timestamps(build_output)
+
+test.pass_test()