Merge branch 'master' into emitter-add

15 files changed, 88 insertions, 53 deletions

diff --git a/CHANGES.txt b/CHANGES.txt
index c3ffef6..3384bb7 100755
--- a/CHANGES.txt
+++ b/CHANGES.txt
@@ -8,12 +8,20 @@ NOTE: The 4.0.0 Release of SCons dropped Python 2.7 Support
 
 RELEASE  VERSION/DATE TO BE FILLED IN LATER
 
+  From Daniel Moody:
+    - Update CacheDir to use uuid for tmpfile uniqueness instead of pid.
+      This fixes cases for shared cache where two systems write to the same
+      cache tmpfile at the same time because the happened to get the same pid.
+
   From Mats Wichmann:
     - Initial support in tests for Python 3.10 - expected bytecode and
       one changed expected exception message. Change some more regexes
       to be specified as rawstrings in response to DeprecationWarnings.
     - Add an example of adding an emitter to User Guide (concept
       from Jeremy Elson)
+    - Add timing information for sconsign database dump when --debug=time
+      is selected. Also switch to generally using time.perf_counter,
+      which is the Python recommended way for timing short durations.
 
 
 RELEASE 4.1.0 - Tues, 19 Jan 2021 15:04:42 -0700
@@ -57,7 +65,7 @@ RELEASE 4.1.0 - Tues, 19 Jan 2021 15:04:42 -0700
       when running multiple tests with multiple jobs.
     - Fix incorrect cache hits and/or misses when running in interactive mode by having
       SCons.Node.Node.clear() clear out all caching-related state.
-    - Change Environment.SideEffect() to not add duplicate side effects. 
+    - Change Environment.SideEffect() to not add duplicate side effects.
       NOTE: The list of returned side effect Nodes will not include any duplicate side effect Nodes.
 
   From David H:
@@ -96,10 +104,10 @@ RELEASE 4.1.0 - Tues, 19 Jan 2021 15:04:42 -0700
       looks like an abbreviation of one one added by AddOption. (#3653)
     - Tool module not found will now raise a UserError to more clearly indicate this is
       probably an SConscript problem, and to make the traceback more relevant.
-    - Fix three issues with MergeFlags: 
-      - Signature/return did not match documentation or existing usage - the implementation 
+    - Fix three issues with MergeFlags:
+      - Signature/return did not match documentation or existing usage - the implementation
         now no longer returns the passed env
-      - merging --param arguments did not work (issue #3107); 
+      - merging --param arguments did not work (issue #3107);
       - passing a dict to merge where the values are strings failed (issue #2961).
     - Include previously-excluded SideEffect section in User Guide.
     - Clean up unneeded imports (autoflake tool).
diff --git a/SCons/Action.py b/SCons/Action.py
index 97309e6..c5e8cd6 100644
--- a/SCons/Action.py
+++ b/SCons/Action.py
@@ -122,9 +122,9 @@ from SCons.Util import is_String, is_List
 class _null:
     pass
 
-print_actions = 1
-execute_actions = 1
-print_actions_presub = 0
+print_actions = True
+execute_actions = True
+print_actions_presub = False
 
 # Use pickle protocol 1 when pickling functions for signature
 # otherwise python3 and python2 will yield different pickles
diff --git a/SCons/CacheDir.py b/SCons/CacheDir.py
index d0c7e5f..82459a6 100644
--- a/SCons/CacheDir.py
+++ b/SCons/CacheDir.py
@@ -29,6 +29,7 @@ import json
 import os
 import stat
 import sys
+import uuid
 
 import SCons.Action
 import SCons.Errors
@@ -39,6 +40,7 @@ cache_debug = False
 cache_force = False
 cache_show = False
 cache_readonly = False
+cache_tmp_uuid = uuid.uuid4().hex
 
 def CacheRetrieveFunc(target, source, env):
     t = target[0]
@@ -100,7 +102,7 @@ def CachePushFunc(target, source, env):
 
     cd.CacheDebug('CachePush(%s):  pushing to %s\n', t, cachefile)
 
-    tempfile = cachefile+'.tmp'+str(os.getpid())
+    tempfile = "%s.tmp%s"%(cachefile,cache_tmp_uuid)
     errfmt = "Unable to copy %s to cache. Cache file is %s"
 
     if not fs.isdir(cachedir):
diff --git a/SCons/Debug.py b/SCons/Debug.py
index f4b802e..fa07743 100644
--- a/SCons/Debug.py
+++ b/SCons/Debug.py
@@ -193,7 +193,7 @@ if sys.platform == 'win32':
 else:
     TraceDefault = '/dev/tty'
 TimeStampDefault = False
-StartTime = time.time()
+StartTime = time.perf_counter()
 PreviousTime = StartTime
 
 def Trace(msg, tracefile=None, mode='w', tstamp=False):
@@ -238,7 +238,7 @@ def Trace(msg, tracefile=None, mode='w', tstamp=False):
             # Assume we were passed an open file pointer.
             fp = tracefile
     if tstamp:
-        now = time.time()
+        now = time.perf_counter()
         fp.write('%8.4f %8.4f:  ' % (now - StartTime, now - PreviousTime))
         PreviousTime = now
     fp.write(msg)
diff --git a/SCons/SConsign.py b/SCons/SConsign.py
index 95b8096..6cb088b 100644
--- a/SCons/SConsign.py
+++ b/SCons/SConsign.py
@@ -27,11 +27,12 @@ import SCons.compat
 
 import os
 import pickle
+import time
 
 import SCons.dblite
 import SCons.Warnings
-
 from SCons.compat import PICKLE_PROTOCOL
+from SCons.Util import print_time
 
 
 def corrupt_dblite_warning(filename):
@@ -100,6 +101,10 @@ normcase = os.path.normcase
 
 def write():
     global sig_files
+
+    if print_time():
+        start_time = time.perf_counter()
+
     for sig_file in sig_files:
         sig_file.write(sync=0)
     for db in DB_sync_list:
@@ -116,6 +121,10 @@ def write():
         else:
             closemethod()
 
+    if print_time():
+        elapsed = time.perf_counter() - start_time
+        print('Total SConsign sync time: %f seconds' % elapsed)
+
 
 class SConsignEntry:
     """
diff --git a/SCons/Script/Main.py b/SCons/Script/Main.py
index 1f2a455..f930ab6 100644
--- a/SCons/Script/Main.py
+++ b/SCons/Script/Main.py
@@ -68,11 +68,11 @@ import SCons.Script.Interactive
 # Global variables
 first_command_start = None
 last_command_end = None
-print_objects = 0
-print_memoizer = 0
-print_stacktrace = 0
-print_time = 0
-print_action_timestamps = 0
+print_objects = False
+print_memoizer = False
+print_stacktrace = False
+print_time = False
+print_action_timestamps = False
 sconscript_time = 0
 cumulative_command_time = 0
 exit_status = 0   # final exit status, assume success by default
@@ -195,11 +195,20 @@ class BuildTask(SCons.Taskmaster.OutOfDateTask):
             global last_command_end
             finish_time = time.time()
             last_command_end = finish_time
-            cumulative_command_time = cumulative_command_time+finish_time-start_time
+            cumulative_command_time += finish_time - start_time
             if print_action_timestamps:
-                sys.stdout.write("Command execution start timestamp: %s: %f\n"%(str(self.node), start_time))
-                sys.stdout.write("Command execution end timestamp: %s: %f\n"%(str(self.node), finish_time))
-            sys.stdout.write("Command execution time: %s: %f seconds\n"%(str(self.node), finish_time-start_time))
+                sys.stdout.write(
+                    "Command execution start timestamp: %s: %f\n"
+                    % (str(self.node), start_time)
+                )
+                sys.stdout.write(
+                    "Command execution end timestamp: %s: %f\n"
+                    % (str(self.node), finish_time)
+                )
+            sys.stdout.write(
+                "Command execution time: %s: %f seconds\n"
+                % (str(self.node), (finish_time - start_time))
+            )
 
     def do_failed(self, status=2):
         _BuildFailures.append(self.exception[1])
@@ -658,22 +667,22 @@ def _set_debug_values(options):
     if print_objects:
         SCons.Debug.track_instances = True
     if "presub" in debug_values:
-        SCons.Action.print_actions_presub = 1
+        SCons.Action.print_actions_presub = True
     if "stacktrace" in debug_values:
-        print_stacktrace = 1
+        print_stacktrace = True
     if "stree" in debug_values:
         options.tree_printers.append(TreePrinter(status=True))
     if "time" in debug_values:
-        print_time = 1
+        print_time = True
     if "action-timestamps" in debug_values:
-        print_time = 1
-        print_action_timestamps = 1
+        print_time = True
+        print_action_timestamps = True
     if "tree" in debug_values:
         options.tree_printers.append(TreePrinter())
     if "prepare" in debug_values:
-        SCons.Taskmaster.print_prepare = 1
+        SCons.Taskmaster.print_prepare = True
     if "duplicate" in debug_values:
-        SCons.Node.print_duplicate = 1
+        SCons.Node.print_duplicate = True
 
 def _create_path(plist):
     path = '.'
@@ -1010,7 +1019,8 @@ def _main(parser):
 
     progress_display("scons: Reading SConscript files ...")
 
-    start_time = time.time()
+    if print_time:
+        start_time = time.time()
     try:
         for script in scripts:
             SCons.Script._SConscript._SConscript(fs, script)
@@ -1023,8 +1033,9 @@ def _main(parser):
         revert_io()
         sys.stderr.write("scons: *** %s  Stop.\n" % e)
         sys.exit(2)
-    global sconscript_time
-    sconscript_time = time.time() - start_time
+    if print_time:
+        global sconscript_time
+        sconscript_time = time.time() - start_time
 
     progress_display("scons: done reading SConscript files.")
 
diff --git a/SCons/Script/SConsOptions.py b/SCons/Script/SConsOptions.py
index 7b79292..0d16e01 100644
--- a/SCons/Script/SConsOptions.py
+++ b/SCons/Script/SConsOptions.py
@@ -34,6 +34,7 @@ _ = gettext.gettext
 import SCons.Node.FS
 import SCons.Platform.virtualenv
 import SCons.Warnings
+from . import Main
 
 OptionValueError        = optparse.OptionValueError
 SUPPRESS_HELP           = optparse.SUPPRESS_HELP
@@ -837,7 +838,6 @@ def Parser(version):
     tree_options = ["all", "derived", "prune", "status", "linedraw"]
 
     def opt_tree(option, opt, value, parser, tree_options=tree_options):
-        from . import Main
         tp = Main.TreePrinter()
         for o in value.split(','):
             if o == 'all':
diff --git a/SCons/Script/SConscript.py b/SCons/Script/SConscript.py
index c47ace3..596fca0 100644
--- a/SCons/Script/SConscript.py
+++ b/SCons/Script/SConscript.py
@@ -34,7 +34,6 @@ import SCons.Node.Alias
 import SCons.Node.FS
 import SCons.Platform
 import SCons.SConf
-import SCons.Script.Main
 import SCons.Tool
 from SCons.Util import is_List, is_String, is_Dict, flatten
 from SCons.Node import SConscriptNodes
@@ -273,7 +272,7 @@ def _SConscript(fs, *files, **kw):
                     try:
                         try:
                             if Main.print_time:
-                                time1 = time.time()
+                                start_time = time.perf_counter()
                             scriptdata = _file_.read()
                             scriptname = _file_.name
                             _file_.close()
@@ -282,8 +281,8 @@ def _SConscript(fs, *files, **kw):
                             pass
                     finally:
                         if Main.print_time:
-                            time2 = time.time()
-                            print('SConscript:%s  took %0.3f ms' % (f.get_abspath(), (time2 - time1) * 1000.0))
+                            elapsed = time.perf_counter() - start_time
+                            print('SConscript:%s  took %0.3f ms' % (f.get_abspath(), elapsed * 1000.0))
 
                         if old_file is not None:
                             call_stack[-1].globals.update({__file__:old_file})
diff --git a/SCons/Taskmaster.py b/SCons/Taskmaster.py
index a1358e0..d571795 100644
--- a/SCons/Taskmaster.py
+++ b/SCons/Taskmaster.py
@@ -63,7 +63,7 @@ NODE_UP_TO_DATE = SCons.Node.up_to_date
 NODE_EXECUTED = SCons.Node.executed
 NODE_FAILED = SCons.Node.failed
 
-print_prepare = 0               # set by option --debug=prepare
+print_prepare = False               # set by option --debug=prepare
 
 # A subsystem for recording stats about how different Nodes are handled by
 # the main Taskmaster loop.  There's no external control here (no need for
diff --git a/SCons/Util.py b/SCons/Util.py
index 0f26fb1..8dd8826 100644
--- a/SCons/Util.py
+++ b/SCons/Util.py
@@ -1648,6 +1648,11 @@ def get_os_env_bool(name, default=False):
     """
     return get_env_bool(os.environ, name, default)
 
+def print_time():
+    """Hack to return a value from Main if can't import Main."""
+    from SCons.Script.Main import print_time
+    return print_time
+
 # Local Variables:
 # tab-width:4
 # indent-tabs-mode:nil
diff --git a/requirements.txt b/requirements.txt
index 16ac5a4..e2f86f4 100644
--- a/requirements.txt
+++ b/requirements.txt
@@ -4,7 +4,8 @@
 # Can be used with twinecheck
 # See: https://github.com/pypa/readme_renderer
 readme-renderer
-sphinx
+# 3.5.0 is bad. Hold at 3.4.3 for now until 3.5.1 is available
+sphinx<3.5.0
 sphinx_rtd_theme
 lxml==4.6.2
-rst2pdf
\ No newline at end of file
+rst2pdf
diff --git a/test/MSVC/msvc.py b/test/MSVC/msvc.py
index b92cf3a..3b32046 100644
--- a/test/MSVC/msvc.py
+++ b/test/MSVC/msvc.py
@@ -170,13 +170,13 @@ test.must_not_exist(test.workpath('test.pdb'))
 test.must_exist(test.workpath('test.obj'))
 
 
-start = time.time()
+start = time.perf_counter()
 test.run(arguments='fast.obj', stderr=None)
-fast = time.time() - start
+fast = time.perf_counter() - start
 
-start = time.time()
+start = time.perf_counter()
 test.run(arguments='slow.obj', stderr=None)
-slow = time.time() - start
+slow = time.perf_counter() - start
 
 
 # TODO: Reevaluate if having this part of the test makes sense any longer
diff --git a/test/option/debug-time.py b/test/option/debug-time.py
index 7e95af3..19f1e7c 100644
--- a/test/option/debug-time.py
+++ b/test/option/debug-time.py
@@ -95,15 +95,15 @@ def get_command_time(stdout):
 test.write('pass.py', "pass\n")
 test.read(test.program)
 
-start_time = time.time()
+start_time = time.perf_counter()
 test.run(program=TestSCons.python, arguments=test.workpath('pass.py'))
-overhead = time.time() - start_time 
+overhead = time.perf_counter() - start_time
 
 
 
-start_time = time.time()
+start_time = time.perf_counter()
 test.run(arguments = "-j1 --debug=time . SLEEP=0")
-complete_time = time.time() - start_time
+complete_time = time.perf_counter() - start_time
 
 
 
@@ -132,7 +132,7 @@ warnings = []
 
 if  targets != expected_targets:
     failures.append("""\
-Scons reported the targets of timing information as %(targets)s, 
+Scons reported the targets of timing information as %(targets)s,
 but the actual targets should have been %(expected_targets)s.
 """ %locals())
 
diff --git a/testing/framework/TestCmdTests.py b/testing/framework/TestCmdTests.py
index e37b90e..01a1390 100644
--- a/testing/framework/TestCmdTests.py
+++ b/testing/framework/TestCmdTests.py
@@ -2169,15 +2169,15 @@ class sleep_TestCase(TestCmdTestCase):
         """Test sleep()"""
         test = TestCmd.TestCmd()
 
-        start = time.time()
+        start = time.perf_counter()
         test.sleep()
-        end = time.time()
+        end = time.perf_counter()
         diff = end - start
         assert diff > 0.9, "only slept %f seconds (start %f, end %f), not default" % (diff, start, end)
 
-        start = time.time()
+        start = time.perf_counter()
         test.sleep(3)
-        end = time.time()
+        end = time.perf_counter()
         diff = end - start
         assert diff > 2.9, "only slept %f seconds (start %f, end %f), not 3" % (diff, start, end)
 
diff --git a/testing/framework/TestSCons.py b/testing/framework/TestSCons.py
index 0783da4..c02be7a 100644
--- a/testing/framework/TestSCons.py
+++ b/testing/framework/TestSCons.py
@@ -1887,11 +1887,11 @@ class TimeSCons(TestSCons):
         --debug=memory and --debug=time options to have SCons report
         its own memory and timing statistics.
         """
-        self.startTime = time.time()
+        self.startTime = time.perf_counter()
         try:
             result = TestSCons.run(self, *args, **kw)
         finally:
-            self.endTime = time.time()
+            self.endTime = time.perf_counter()
         return result
 
     def copy_timing_configuration(self, source_dir, dest_dir):