From 02bd6b8e08710d989718f44df6510b1842f26a7b Mon Sep 17 00:00:00 2001 From: William Deegan Date: Sat, 3 Dec 2022 16:44:43 -0800 Subject: Added TestCommon.must_match_file() function. Updated test for --taskmastertracefor (NewParallel/LegacyParallel Jobs). Now uses golden files to compare expected output and output files --- SCons/Taskmaster/Job.py | 29 ++-- test/option/fixture/SConstruct__taskmastertrace.py | 9 + test/option/fixture/taskmaster_expected_file_1.txt | 74 ++++++++ .../fixture/taskmaster_expected_new_parallel.txt | 90 ++++++++++ .../fixture/taskmaster_expected_stdout_1.txt | 76 +++++++++ test/option/taskmastertrace.py | 190 ++------------------- testing/framework/TestCommon.py | 21 +++ 7 files changed, 303 insertions(+), 186 deletions(-) create mode 100644 test/option/fixture/SConstruct__taskmastertrace.py create mode 100644 test/option/fixture/taskmaster_expected_file_1.txt create mode 100644 test/option/fixture/taskmaster_expected_new_parallel.txt create mode 100644 test/option/fixture/taskmaster_expected_stdout_1.txt diff --git a/SCons/Taskmaster/Job.py b/SCons/Taskmaster/Job.py index 58f3f01..853fe63 100644 --- a/SCons/Taskmaster/Job.py +++ b/SCons/Taskmaster/Job.py @@ -504,7 +504,8 @@ else: def trace_message(self, message): # This grabs the name of the function which calls trace_message() method_name = sys._getframe(1).f_code.co_name + "():" - self.trace.debug('%s.%s %s' % (type(self).__name__, method_name, message)) + thread_id=threading.get_ident() + self.trace.debug('%s.%s [Thread:%s] %s' % (type(self).__name__, method_name, thread_id, message)) # print('%-15s %s' % (method_name, message)) def start(self): @@ -551,7 +552,7 @@ else: with self.can_search_cv: if self.trace: - self.trace_message(f"{threading.get_ident()} Gained exclusive access") + self.trace_message("Gained exclusive access") # Capture whether we got here with `task` set, # then drop our reference to the task as we are no @@ -572,19 +573,19 @@ else: # here with a completed task. if self.state == NewParallel.State.STALLED and completed_task: if self.trace: - self.trace_message(f"{threading.get_ident()} Detected stall with completed task, bypassing wait") + self.trace_message("Detected stall with completed task, bypassing wait") self.state = NewParallel.State.READY # Wait until we are neither searching nor stalled. while self.state == NewParallel.State.SEARCHING or self.state == NewParallel.State.STALLED: if self.trace: - self.trace_message(f"{threading.get_ident()} Search already in progress, waiting") + self.trace_message("Search already in progress, waiting") self.can_search_cv.wait() # If someone set the completed flag, bail. if self.state == NewParallel.State.COMPLETED: if self.trace: - self.trace_message(f"{threading.get_ident()} Completion detected, breaking from main loop") + self.trace_message("Completion detected, breaking from main loop") break # Set the searching flag to indicate that a thread @@ -592,7 +593,7 @@ else: # taskmaster work. # if self.trace: - self.trace_message(f"{threading.get_ident()} Starting search") + self.trace_message("Starting search") self.state = NewParallel.State.SEARCHING # Bulk acquire the tasks in the results queue @@ -606,7 +607,7 @@ else: results_queue, self.results_queue = self.results_queue, results_queue if self.trace: - self.trace_message(f"{threading.get_ident()} Found {len(results_queue)} completed tasks to process") + self.trace_message("Found {len(results_queue)} completed tasks to process") for (rtask, rresult) in results_queue: if rresult: rtask.executed() @@ -636,7 +637,7 @@ else: # mark the walk as complete if not. while self.state == NewParallel.State.SEARCHING: if self.trace: - self.trace_message(f"{threading.get_ident()} Searching for new tasks") + self.trace_message("Searching for new tasks") task = self.taskmaster.next_task() if task: @@ -657,13 +658,13 @@ else: else: if not task.needs_execute(): if self.trace: - self.trace_message(f"{threading.get_ident()} Found internal task") + self.trace_message("Found internal task") task.executed() task.postprocess() else: self.jobs += 1 if self.trace: - self.trace_message(f"{threading.get_ident()} Found task requiring execution") + self.trace_message("Found task requiring execution") self.state = NewParallel.State.READY self.can_search_cv.notify() @@ -682,7 +683,7 @@ else: # loop. # if self.trace: - self.trace_message(f"{threading.get_ident()} Found no task requiring execution, but have jobs: marking stalled") + self.trace_message("Found no task requiring execution, but have jobs: marking stalled") self.state = NewParallel.State.STALLED else: # We didn't find a task and there are @@ -695,7 +696,7 @@ else: # sleeping on the condvar. # if self.trace: - self.trace_message(f"{threading.get_ident()} Found no task requiring execution, and have no jobs: marking complete") + self.trace_message("Found no task requiring execution, and have no jobs: marking complete") self.state = NewParallel.State.COMPLETED self.can_search_cv.notify_all() @@ -705,7 +706,7 @@ else: # taskmaster crank in NewParallel. if task: if self.trace: - self.trace_message(f"{threading.get_ident()} Executing task") + self.trace_message("Executing task") ok = True try: if self.interrupted(): @@ -722,7 +723,7 @@ else: # postprocessing work under the taskmaster lock. # if self.trace: - self.trace_message(f"{threading.get_ident()} Enqueueing executed task results") + self.trace_message("Enqueueing executed task results") with self.results_queue_lock: self.results_queue.append((task, ok)) diff --git a/test/option/fixture/SConstruct__taskmastertrace.py b/test/option/fixture/SConstruct__taskmastertrace.py new file mode 100644 index 0000000..91e8c91 --- /dev/null +++ b/test/option/fixture/SConstruct__taskmastertrace.py @@ -0,0 +1,9 @@ +DefaultEnvironment(tools=[]) +env = Environment(tools=[]) + +# We name the files 'Tfile' so that they will sort after the SConstruct +# file regardless of whether the test is being run on a case-sensitive +# or case-insensitive system. + +env.Command('Tfile.out', 'Tfile.mid', Copy('$TARGET', '$SOURCE')) +env.Command('Tfile.mid', 'Tfile.in', Copy('$TARGET', '$SOURCE')) diff --git a/test/option/fixture/taskmaster_expected_file_1.txt b/test/option/fixture/taskmaster_expected_file_1.txt new file mode 100644 index 0000000..3d34b2d --- /dev/null +++ b/test/option/fixture/taskmaster_expected_file_1.txt @@ -0,0 +1,74 @@ + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: adjusted ref count: , child 'SConstruct' +Taskmaster: adjusted ref count: , child 'Tfile.in' +Taskmaster: adjusted ref count: , child 'Tfile.mid' +Taskmaster: adjusted ref count: , child 'Tfile.out' +Taskmaster: Considering node and its children: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.execute(): node +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.execute(): node +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.execute(): node +Task.executed_with_callbacks(): node +Task.postprocess(): node + +Taskmaster: Looking for a node to evaluate +Taskmaster: No candidate anymore. diff --git a/test/option/fixture/taskmaster_expected_new_parallel.txt b/test/option/fixture/taskmaster_expected_new_parallel.txt new file mode 100644 index 0000000..77334d9 --- /dev/null +++ b/test/option/fixture/taskmaster_expected_new_parallel.txt @@ -0,0 +1,90 @@ +Job.NewParallel._work(): [Thread:XXXXX] Gained exclusive access +Job.NewParallel._work(): [Thread:XXXXX] Starting search +Job.NewParallel._work(): [Thread:XXXXX] Found {len(results_queue)} completed tasks to process +Job.NewParallel._work(): [Thread:XXXXX] Searching for new tasks + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: adjusted ref count: , child 'SConstruct' +Taskmaster: adjusted ref count: , child 'Tfile.in' +Taskmaster: adjusted ref count: , child 'Tfile.mid' +Taskmaster: adjusted ref count: , child 'Tfile.out' +Taskmaster: Considering node and its children: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Job.NewParallel._work(): [Thread:XXXXX] Found internal task +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count +Job.NewParallel._work(): [Thread:XXXXX] Searching for new tasks + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Job.NewParallel._work(): [Thread:XXXXX] Found internal task +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count +Job.NewParallel._work(): [Thread:XXXXX] Searching for new tasks + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Job.NewParallel._work(): [Thread:XXXXX] Found internal task +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count +Job.NewParallel._work(): [Thread:XXXXX] Searching for new tasks + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Job.NewParallel._work(): [Thread:XXXXX] Found internal task +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count +Job.NewParallel._work(): [Thread:XXXXX] Searching for new tasks + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Job.NewParallel._work(): [Thread:XXXXX] Found internal task +Task.executed_with_callbacks(): node +Task.postprocess(): node +Job.NewParallel._work(): [Thread:XXXXX] Searching for new tasks + +Taskmaster: Looking for a node to evaluate +Taskmaster: No candidate anymore. +Job.NewParallel._work(): [Thread:XXXXX] Found no task requiring execution, and have no jobs: marking complete +Job.NewParallel._work(): [Thread:XXXXX] Gained exclusive access +Job.NewParallel._work(): [Thread:XXXXX] Completion detected, breaking from main loop +Job.NewParallel._work(): [Thread:XXXXX] Gained exclusive access +Job.NewParallel._work(): [Thread:XXXXX] Completion detected, breaking from main loop diff --git a/test/option/fixture/taskmaster_expected_stdout_1.txt b/test/option/fixture/taskmaster_expected_stdout_1.txt new file mode 100644 index 0000000..9076e68 --- /dev/null +++ b/test/option/fixture/taskmaster_expected_stdout_1.txt @@ -0,0 +1,76 @@ + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: adjusted ref count: , child 'SConstruct' +Taskmaster: adjusted ref count: , child 'Tfile.in' +Taskmaster: adjusted ref count: , child 'Tfile.mid' +Taskmaster: adjusted ref count: , child 'Tfile.out' +Taskmaster: Considering node and its children: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.execute(): node +Copy("Tfile.mid", "Tfile.in") +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.execute(): node +Copy("Tfile.out", "Tfile.mid") +Task.executed_with_callbacks(): node +Task.postprocess(): node +Task.postprocess(): removing +Task.postprocess(): adjusted parent ref count + +Taskmaster: Looking for a node to evaluate +Taskmaster: Considering node and its children: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: +Taskmaster: Evaluating + +Task.make_ready_current(): node +Task.prepare(): node +Task.execute(): node +Task.executed_with_callbacks(): node +Task.postprocess(): node + +Taskmaster: Looking for a node to evaluate +Taskmaster: No candidate anymore. diff --git a/test/option/taskmastertrace.py b/test/option/taskmastertrace.py index fc8522c..0e44896 100644 --- a/test/option/taskmastertrace.py +++ b/test/option/taskmastertrace.py @@ -1,6 +1,8 @@ #!/usr/bin/env python # -# __COPYRIGHT__ +# MIT License +# +# Copyright The SCons Foundation # # Permission is hereby granted, free of charge, to any person obtaining # a copy of this software and associated documentation files (the @@ -20,111 +22,25 @@ # 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. -# - -__revision__ = "__FILE__ __REVISION__ __DATE__ __DEVELOPER__" """ Simple tests of the --taskmastertrace= option. """ +import os +import re import TestSCons test = TestSCons.TestSCons() -test.write('SConstruct', """ -DefaultEnvironment(tools=[]) -env = Environment(tools=[]) - -# We name the files 'Tfile' so that they will sort after the SConstruct -# file regardless of whether the test is being run on a case-sensitive -# or case-insensitive system. - -env.Command('Tfile.out', 'Tfile.mid', Copy('$TARGET', '$SOURCE')) -env.Command('Tfile.mid', 'Tfile.in', Copy('$TARGET', '$SOURCE')) -""") +test.file_fixture('fixture/SConstruct__taskmastertrace.py', 'SConstruct') +test.file_fixture('fixture/taskmaster_expected_stdout_1.txt', 'taskmaster_expected_stdout_1.txt') +test.file_fixture('fixture/taskmaster_expected_file_1.txt', 'taskmaster_expected_file_1.txt') +test.file_fixture('fixture/taskmaster_expected_new_parallel.txt', 'taskmaster_expected_new_parallel.txt') test.write('Tfile.in', "Tfile.in\n") -expect_stdout = test.wrap_stdout("""\ - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: -Taskmaster: -Taskmaster: -Taskmaster: -Taskmaster: adjusted ref count: , child 'SConstruct' -Taskmaster: adjusted ref count: , child 'Tfile.in' -Taskmaster: adjusted ref count: , child 'Tfile.mid' -Taskmaster: adjusted ref count: , child 'Tfile.out' -Taskmaster: Considering node and its children: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.executed_with_callbacks(): node -Task.postprocess(): node -Task.postprocess(): removing -Task.postprocess(): adjusted parent ref count - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.executed_with_callbacks(): node -Task.postprocess(): node -Task.postprocess(): removing -Task.postprocess(): adjusted parent ref count - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.execute(): node -Copy("Tfile.mid", "Tfile.in") -Task.executed_with_callbacks(): node -Task.postprocess(): node -Task.postprocess(): removing -Task.postprocess(): adjusted parent ref count - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.execute(): node -Copy("Tfile.out", "Tfile.mid") -Task.executed_with_callbacks(): node -Task.postprocess(): node -Task.postprocess(): removing -Task.postprocess(): adjusted parent ref count - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: -Taskmaster: -Taskmaster: -Taskmaster: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.execute(): node -Task.executed_with_callbacks(): node -Task.postprocess(): node - -Taskmaster: Looking for a node to evaluate -Taskmaster: No candidate anymore. - -""") +expect_stdout = test.wrap_stdout(test.read('taskmaster_expected_stdout_1.txt', mode='r')) test.run(arguments='--taskmastertrace=- .', stdout=expect_stdout) @@ -136,86 +52,16 @@ Copy("Tfile.out", "Tfile.mid") """) test.run(arguments='--taskmastertrace=trace.out .', stdout=expect_stdout) +test.must_match_file('trace.out', 'taskmaster_expected_file_1.txt', mode='r') -expect_trace = """\ - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: -Taskmaster: -Taskmaster: -Taskmaster: -Taskmaster: adjusted ref count: , child 'SConstruct' -Taskmaster: adjusted ref count: , child 'Tfile.in' -Taskmaster: adjusted ref count: , child 'Tfile.mid' -Taskmaster: adjusted ref count: , child 'Tfile.out' -Taskmaster: Considering node and its children: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.executed_with_callbacks(): node -Task.postprocess(): node -Task.postprocess(): removing -Task.postprocess(): adjusted parent ref count - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.executed_with_callbacks(): node -Task.postprocess(): node -Task.postprocess(): removing -Task.postprocess(): adjusted parent ref count - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.execute(): node -Task.executed_with_callbacks(): node -Task.postprocess(): node -Task.postprocess(): removing -Task.postprocess(): adjusted parent ref count - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.execute(): node -Task.executed_with_callbacks(): node -Task.postprocess(): node -Task.postprocess(): removing -Task.postprocess(): adjusted parent ref count - -Taskmaster: Looking for a node to evaluate -Taskmaster: Considering node and its children: -Taskmaster: -Taskmaster: -Taskmaster: -Taskmaster: -Taskmaster: Evaluating - -Task.make_ready_current(): node -Task.prepare(): node -Task.execute(): node -Task.executed_with_callbacks(): node -Task.postprocess(): node - -Taskmaster: Looking for a node to evaluate -Taskmaster: No candidate anymore. - -""" +# Test NewParallel Job implementation +os.environ['SCONS_NEW_PARALLEL'] = "1" +test.run(arguments='-j 2 --taskmastertrace=new_parallel_trace.out .') -test.must_match('trace.out', expect_trace, mode='r') +new_trace = test.read('new_parallel_trace.out', mode='r') +thread_id = re.compile(r'\[Thread:\d+\]') +new_trace=thread_id.sub('[Thread:XXXXX]', new_trace) +test.must_match('taskmaster_expected_new_parallel.txt', new_trace, mode='r') test.pass_test() diff --git a/testing/framework/TestCommon.py b/testing/framework/TestCommon.py index f45b856..da24c3b 100644 --- a/testing/framework/TestCommon.py +++ b/testing/framework/TestCommon.py @@ -527,6 +527,27 @@ class TestCommon(TestCmd): self.diff(expect, file_contents, 'contents ') raise + def must_match_file(self, file, golden_file, mode='rb', match=None, message=None, newline=None): + """Matches the contents of the specified file (first argument) + against the expected contents (second argument). The expected + contents are a list of lines or a string which will be split + on newlines. + """ + file_contents = self.read(file, mode, newline) + golden_file_contents = self.read(golden_file, mode, newline) + + if not match: + match = self.match + + try: + self.fail_test(not match(to_str(file_contents), to_str(golden_file_contents)), message=message) + except KeyboardInterrupt: + raise + except: + print("Unexpected contents of `%s'" % file) + self.diff(golden_file_contents, file_contents, 'contents ') + raise + def must_not_contain(self, file, banned, mode = 'rb', find = None): """Ensures that the specified file doesn't contain the banned text. """ -- cgit v0.12