From fb7bb3f969698cbbcdb5af7c97f33c4529ba2e09 Mon Sep 17 00:00:00 2001 From: Mats Wichmann Date: Mon, 8 Feb 2021 13:24:06 -0700 Subject: Add timing of sconsign write if --debug A line is now emitted showing sconsign sync time if --debug=time Some calls to time.time replaced with time.perf_counter, where the objective was to time sections of code (i.e. where there wasn't an actual need to get time-since-epoch) - Python recommends this as getting the best-available timer. Signed-off-by: Mats Wichmann --- CHANGES.txt | 3 +++ SCons/Debug.py | 4 ++-- SCons/SConsign.py | 11 ++++++++++- SCons/Script/Main.py | 10 +++++----- SCons/Script/SConsOptions.py | 2 +- SCons/Script/SConscript.py | 5 ++--- SCons/Util.py | 5 +++++ test/MSVC/msvc.py | 8 ++++---- test/option/debug-time.py | 10 +++++----- testing/framework/TestCmdTests.py | 8 ++++---- testing/framework/TestSCons.py | 4 ++-- 11 files changed, 43 insertions(+), 27 deletions(-) diff --git a/CHANGES.txt b/CHANGES.txt index f3e2b2a..7e1ed12 100755 --- a/CHANGES.txt +++ b/CHANGES.txt @@ -12,6 +12,9 @@ RELEASE VERSION/DATE TO BE FILLED IN LATER - 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 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 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..c488ef9 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(): + time1 = 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(): + time2 = time.perf_counter() + print('Total SConsign sync time: %f seconds' % (time2 - time1)) + class SConsignEntry: """ diff --git a/SCons/Script/Main.py b/SCons/Script/Main.py index 1f2a455..6a794c3 100644 --- a/SCons/Script/Main.py +++ b/SCons/Script/Main.py @@ -185,7 +185,7 @@ class BuildTask(SCons.Taskmaster.OutOfDateTask): def execute(self): if print_time: - start_time = time.time() + start_time = time.perf_counter() global first_command_start if first_command_start is None: first_command_start = start_time @@ -193,7 +193,7 @@ class BuildTask(SCons.Taskmaster.OutOfDateTask): if print_time: global cumulative_command_time global last_command_end - finish_time = time.time() + finish_time = time.perf_counter() last_command_end = finish_time cumulative_command_time = cumulative_command_time+finish_time-start_time if print_action_timestamps: @@ -1010,7 +1010,7 @@ def _main(parser): progress_display("scons: Reading SConscript files ...") - start_time = time.time() + start_time = time.perf_counter() try: for script in scripts: SCons.Script._SConscript._SConscript(fs, script) @@ -1024,7 +1024,7 @@ def _main(parser): sys.stderr.write("scons: *** %s Stop.\n" % e) sys.exit(2) global sconscript_time - sconscript_time = time.time() - start_time + sconscript_time = time.perf_counter() - start_time progress_display("scons: done reading SConscript files.") @@ -1423,7 +1423,7 @@ def main(): SCons.Taskmaster.dump_stats() if print_time: - total_time = time.time() - SCons.Script.start_time + total_time = time.perf_counter() - SCons.Script.start_time if num_jobs == 1: ct = cumulative_command_time else: 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..321fba3 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() + time1 = time.perf_counter() scriptdata = _file_.read() scriptname = _file_.name _file_.close() @@ -282,7 +281,7 @@ def _SConscript(fs, *files, **kw): pass finally: if Main.print_time: - time2 = time.time() + time2 = time.perf_counter() print('SConscript:%s took %0.3f ms' % (f.get_abspath(), (time2 - time1) * 1000.0)) if old_file is not None: 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/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): -- cgit v0.12 From 0281d398d5d3369807b6a2aee1ede45c53b3c8e6 Mon Sep 17 00:00:00 2001 From: Mats Wichmann Date: Tue, 9 Feb 2021 07:56:56 -0700 Subject: [PR #3884] fix some timinng errors from initial submit Signed-off-by: Mats Wichmann --- SCons/SConsign.py | 6 +++--- SCons/Script/Main.py | 6 +++--- SCons/Script/SConscript.py | 6 +++--- 3 files changed, 9 insertions(+), 9 deletions(-) diff --git a/SCons/SConsign.py b/SCons/SConsign.py index c488ef9..6cb088b 100644 --- a/SCons/SConsign.py +++ b/SCons/SConsign.py @@ -103,7 +103,7 @@ def write(): global sig_files if print_time(): - time1 = time.perf_counter() + start_time = time.perf_counter() for sig_file in sig_files: sig_file.write(sync=0) @@ -122,8 +122,8 @@ def write(): closemethod() if print_time(): - time2 = time.perf_counter() - print('Total SConsign sync time: %f seconds' % (time2 - time1)) + 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 6a794c3..c2e9f7c 100644 --- a/SCons/Script/Main.py +++ b/SCons/Script/Main.py @@ -185,7 +185,7 @@ class BuildTask(SCons.Taskmaster.OutOfDateTask): def execute(self): if print_time: - start_time = time.perf_counter() + start_time = time.time() global first_command_start if first_command_start is None: first_command_start = start_time @@ -193,7 +193,7 @@ class BuildTask(SCons.Taskmaster.OutOfDateTask): if print_time: global cumulative_command_time global last_command_end - finish_time = time.perf_counter() + finish_time = time.time() last_command_end = finish_time cumulative_command_time = cumulative_command_time+finish_time-start_time if print_action_timestamps: @@ -1423,7 +1423,7 @@ def main(): SCons.Taskmaster.dump_stats() if print_time: - total_time = time.perf_counter() - SCons.Script.start_time + total_time = time.time() - SCons.Script.start_time if num_jobs == 1: ct = cumulative_command_time else: diff --git a/SCons/Script/SConscript.py b/SCons/Script/SConscript.py index 321fba3..596fca0 100644 --- a/SCons/Script/SConscript.py +++ b/SCons/Script/SConscript.py @@ -272,7 +272,7 @@ def _SConscript(fs, *files, **kw): try: try: if Main.print_time: - time1 = time.perf_counter() + start_time = time.perf_counter() scriptdata = _file_.read() scriptname = _file_.name _file_.close() @@ -281,8 +281,8 @@ def _SConscript(fs, *files, **kw): pass finally: if Main.print_time: - time2 = time.perf_counter() - 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}) -- cgit v0.12 From 9fb6804aae9c4e250dcbe118a03e3c854c224d01 Mon Sep 17 00:00:00 2001 From: Mats Wichmann Date: Thu, 11 Feb 2021 10:25:10 -0700 Subject: A few more tweaks to debug-timing code A big of reformatting; some options changed to explicitly use True / False (functionally no change from 0/1). Signed-off-by: Mats Wichmann --- SCons/Action.py | 6 +++--- SCons/Script/Main.py | 49 ++++++++++++++++++++++++++++++------------------- SCons/Taskmaster.py | 2 +- 3 files changed, 34 insertions(+), 23 deletions(-) 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/Script/Main.py b/SCons/Script/Main.py index c2e9f7c..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.perf_counter() + 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.perf_counter() - 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/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 -- cgit v0.12 From 9c86053654c3c046e6059a0c9278c126ea79b858 Mon Sep 17 00:00:00 2001 From: Daniel Moody Date: Thu, 11 Feb 2021 22:10:32 +0000 Subject: Update CacheDir to use uuid for tmpfile unique name generation. --- CHANGES.txt | 13 +++++++++---- SCons/CacheDir.py | 4 +++- 2 files changed, 12 insertions(+), 5 deletions(-) diff --git a/CHANGES.txt b/CHANGES.txt index f3e2b2a..66cfa3c 100755 --- a/CHANGES.txt +++ b/CHANGES.txt @@ -8,6 +8,11 @@ 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 @@ -55,7 +60,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: @@ -94,10 +99,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/CacheDir.py b/SCons/CacheDir.py index d0c7e5f..f25ea57 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 = f"{cachefile}.tmp{cache_tmp_uuid}" errfmt = "Unable to copy %s to cache. Cache file is %s" if not fs.isdir(cachedir): -- cgit v0.12 From cdb339140b8e508d8173b9bd66988c6b9cd3345e Mon Sep 17 00:00:00 2001 From: William Deegan Date: Thu, 11 Feb 2021 18:21:34 -0800 Subject: Update to be compat with py 3.5 (no f-strings) --- SCons/CacheDir.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/SCons/CacheDir.py b/SCons/CacheDir.py index f25ea57..82459a6 100644 --- a/SCons/CacheDir.py +++ b/SCons/CacheDir.py @@ -102,7 +102,7 @@ def CachePushFunc(target, source, env): cd.CacheDebug('CachePush(%s): pushing to %s\n', t, cachefile) - tempfile = f"{cachefile}.tmp{cache_tmp_uuid}" + tempfile = "%s.tmp%s"%(cachefile,cache_tmp_uuid) errfmt = "Unable to copy %s to cache. Cache file is %s" if not fs.isdir(cachedir): -- cgit v0.12 From 4ab203a346d818134a804b876e3c595b4d417f1d Mon Sep 17 00:00:00 2001 From: William Deegan Date: Tue, 16 Feb 2021 02:03:04 +0000 Subject: Force Sphinx < 3.5.0. Once 3.5.1 is released the bug we're hitting should be resolved --- requirements.txt | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) 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 -- cgit v0.12