Add a --debug=taskmaster option to print traces of what it's doing on its stack.

7 files changed, 164 insertions, 11 deletions

diff --git a/doc/SConscript b/doc/SConscript
index 3fc327f..de8e21e 100644
--- a/doc/SConscript
+++ b/doc/SConscript
@@ -392,6 +392,7 @@ man_intermediate_files = env.Command(man_intermediate_files,
                                      scons_doc_files,
                                      cmd)
 env.Depends(man_intermediate_files, "$SCONS_PROC_PY")
+Local(man_intermediate_files)
 
 for man_1 in man_page_list:
     man, _1 = os.path.splitext(man_1)
diff --git a/doc/man/scons.1 b/doc/man/scons.1
index b2fec58..cab561c 100644
--- a/doc/man/scons.1
+++ b/doc/man/scons.1
@@ -31,7 +31,7 @@
 .fi
 .RE
 ..
-.TH SCONS 1 "October 2005"
+.TH SCONS 1 "December 2005"
 .SH NAME
 scons \- a software construction tool
 .SH SYNOPSIS
@@ -882,6 +882,7 @@ and save the results in the specified
 .IR file .
 The results may be analyzed using the Python
 pstats module.
+
 .TP
 -q, --question
 Do not run any commands, or print anything.  Just return an exit
@@ -928,6 +929,16 @@ appear up-to-date is unnecessary when using
 .BR scons .)
 
 .TP
+.RI --taskmastertrace= file
+Prints trace information to the specified
+.I file
+about how the internal Taskmaster object
+evaluates and controls the order in which Nodes are built.
+A file name of
+.B -
+may be used to specify the standard output.
+
+.TP
 -u, --up, --search-up
 Walks up the directory structure until an 
 .I SConstruct ,
diff --git a/src/CHANGES.txt b/src/CHANGES.txt
index db48e3f..44bff4a 100644
--- a/src/CHANGES.txt
+++ b/src/CHANGES.txt
@@ -408,6 +408,9 @@ RELEASE 0.97 - XXX
   - Fix a man page example of overriding variables when calling
     SharedLibrary() to also set the $LIBSUFFIXES variable.
 
+  - Add a --taskmastertrace=FILE option to give some insight on how
+    the taskmaster decides what Node to build next.
+
   From Chen Lee:
 
   - Handle Visual Studio project and solution files in Unicode.
diff --git a/src/engine/SCons/Script/Main.py b/src/engine/SCons/Script/Main.py
index 2ffe97b..cc7bf13 100644
--- a/src/engine/SCons/Script/Main.py
+++ b/src/engine/SCons/Script/Main.py
@@ -768,6 +768,10 @@ class OptParser(OptionParser):
         self.add_option('-s', '--silent', '--quiet', action="store_true",
                         default=0, help="Don't print commands.")
 
+        self.add_option('--taskmastertrace', action="store",
+                        dest="taskmastertrace_file", metavar="FILE",
+                        help="Trace Node evaluation to FILE.")
+
         self.add_option('-u', '--up', '--search-up', action="store_const",
                         dest="climb_up", default=0, const=1,
                         help="Search up directory tree for SConstruct,       "
@@ -1229,7 +1233,13 @@ def _main(args, parser):
             return dependencies
 
     progress_display("scons: " + opening_message)
-    taskmaster = SCons.Taskmaster.Taskmaster(nodes, task_class, order)
+    if options.taskmastertrace_file == '-':
+        tmtrace = sys.stdout
+    elif options.taskmastertrace_file:
+        tmtrace = open(options.taskmastertrace_file, 'w')
+    else:
+        tmtrace = None
+    taskmaster = SCons.Taskmaster.Taskmaster(nodes, task_class, order, tmtrace)
 
     nj = ssoptions.get('num_jobs')
     jobs = SCons.Job.Jobs(nj, taskmaster)
diff --git a/src/engine/SCons/Taskmaster.py b/src/engine/SCons/Taskmaster.py
index 2f7da74..cbb3f89 100644
--- a/src/engine/SCons/Taskmaster.py
+++ b/src/engine/SCons/Taskmaster.py
@@ -38,7 +38,7 @@ import SCons.Errors
 
 # 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
-# a --debug= option); enabled it by changing the value of CollectStats.
+# a --debug= option); enable it by changing the value of CollectStats.
 
 CollectStats = None
 
@@ -276,7 +276,7 @@ class Taskmaster:
     the base class method, so this class can do its thing.
     """
 
-    def __init__(self, targets=[], tasker=Task, order=order):
+    def __init__(self, targets=[], tasker=Task, order=order, trace=None):
         self.targets = targets # top level targets
         self.candidates = targets[:] # nodes that might be ready to be executed
         self.candidates.reverse()
@@ -286,6 +286,7 @@ class Taskmaster:
         self.ready = None # the next task that is ready to be executed
         self.order = order
         self.message = None
+        self.trace = trace
 
         # See if we can alter the target list to find any
         # corresponding targets in linked build directories
@@ -304,6 +305,8 @@ class Taskmaster:
 
         self.ready_exc = None
 
+        T = self.trace
+
         while self.candidates:
             node = self.candidates.pop()
             state = node.get_state()
@@ -317,9 +320,12 @@ class Taskmaster:
             else:
                 S = None
 
+            if T: T.write('Taskmaster: %s' % repr(str(node)))
+
             # Skip this node if it has already been handled:
             if not state in [ SCons.Node.no_state, SCons.Node.stack ]:
                 if S: S.already_handled = S.already_handled + 1
+                if T: T.write(': already handled\n')
                 continue
 
             # Mark this node as being on the execution stack:
@@ -334,6 +340,7 @@ class Taskmaster:
                 e = SCons.Errors.ExplicitExit(node, exc_value.code)
                 self.ready_exc = (SCons.Errors.ExplicitExit, e)
                 self.ready = node
+                if T: T.write(': SystemExit\n')
                 break
             except KeyboardInterrupt:
                 raise
@@ -345,15 +352,19 @@ class Taskmaster:
                 self.ready_exc = sys.exc_info()
                 self.ready = node
                 if S: S.problem = S.problem + 1
+                if T: T.write(': exception problem\n')
                 break
 
             # Skip this node if any of its children have failed.  This
             # catches the case where we're descending a top-level target
             # and one of our children failed while trying to be built
             # by a *previous* descent of an earlier top-level target.
-            if filter(lambda I: I[0] == SCons.Node.failed, childinfo):
+            failed_children = filter(lambda I: I[0] == SCons.Node.failed,
+                                     childinfo)
+            if failed_children:
                 node.set_state(SCons.Node.failed)
                 if S: S.child_failed = S.child_failed + 1
+                if T: T.write(': children failed:\n    %s\n' % map(str, failed_children))
                 continue
 
             # Detect dependency cycles:
@@ -368,6 +379,7 @@ class Taskmaster:
                                map(lambda I: I[2], cycle)
                 nodes.reverse()
                 desc = "Dependency cycle: " + string.join(map(str, nodes), " -> ")
+                if T: T.write(': dependency cycle\n')
                 raise SCons.Errors.UserError, desc
 
             # Select all of the dependencies that are derived targets
@@ -401,40 +413,47 @@ class Taskmaster:
                 not_started.reverse()
                 self.candidates.extend(self.order(not_started))
                 if S: S.not_started = S.not_started + 1
+                if T: T.write(': waiting on unstarted children:\n    %s\n' % map(str, not_started))
                 continue
 
             not_built = filter(lambda I: I[0] <= SCons.Node.executing, derived_children)
             if not_built:
+                not_built = map(lambda I: I[2], not_built)
+
                 # We're waiting on one or more derived targets that have
                 # started building but not yet finished.  Add this node
                 # to the waiting parents lists of those derived files
                 # so that when they've finished building, our implicit
                 # dependency list will get cleared and we'll re-scan the
                 # newly-built file(s) for updated implicit dependencies.
-                map(lambda I, P=node: I[2].add_to_waiting_parents(P), not_built)
+                map(lambda n, P=node: n.add_to_waiting_parents(P), not_built)
 
                 # And add this node to the "pending" list, so it can get
                 # put back on the candidates list when appropriate.
                 self.pending.append(node)
                 node.set_state(SCons.Node.pending)
                 if S: S.not_built = S.not_built + 1
+                if T: T.write(': waiting on unfinished children:\n    %s\n' % map(str, not_built))
                 continue
 
             # Skip this node if it has side-effects that are
             # currently being built:
-            if reduce(lambda E,N:
-                      E or N.get_state() == SCons.Node.executing,
-                      node.side_effects,
-                      0):
+            side_effects = reduce(lambda E,N:
+                                  E or N.get_state() == SCons.Node.executing,
+                                  node.side_effects,
+                                  0)
+            if side_effects:
                 self.pending.append(node)
                 node.set_state(SCons.Node.pending)
                 if S: S.side_effects = S.side_effects + 1
+                if T: T.write(': waiting on side effects:\n    %s\n' % map(str, side_effects))
                 continue
 
             # The default when we've gotten through all of the checks above:
             # this node is ready to be built.
             self.ready = node
             if S: S.build = S.build + 1
+            if T: T.write(': building\n')
             break
 
     def next_task(self):
diff --git a/src/engine/SCons/TaskmasterTests.py b/src/engine/SCons/TaskmasterTests.py
index 62d3d6a..dc23159 100644
--- a/src/engine/SCons/TaskmasterTests.py
+++ b/src/engine/SCons/TaskmasterTests.py
@@ -171,7 +171,7 @@ class TaskmasterTestCase(unittest.TestCase):
         """Test fetching the next task
         """
         global built_text
-        
+
         n1 = Node("n1")
         tm = SCons.Taskmaster.Taskmaster([n1, n1])
         t = tm.next_task()
@@ -1031,6 +1031,37 @@ class TaskmasterTestCase(unittest.TestCase):
         assert n2.postprocessed
         assert n3.postprocessed
 
+    def test_trace(self):
+        """Test Taskmaster tracing
+        """
+        import StringIO
+
+        trace = StringIO.StringIO()
+        n1 = Node("n1")
+        n2 = Node("n2")
+        n3 = Node("n3", [n1, n2])
+        tm = SCons.Taskmaster.Taskmaster([n1, n1, n3], trace=trace)
+        t = tm.next_task()
+        t.prepare()
+        t.execute()
+        n1.set_state(SCons.Node.executed)
+        t = tm.next_task()
+        t.prepare()
+        t.execute()
+        t = tm.next_task()
+
+        value = trace.getvalue()
+        expect = """\
+Taskmaster: 'n1': building
+Taskmaster: 'n1': already handled
+Taskmaster: 'n3': waiting on unstarted children:
+    ['n2']
+Taskmaster: 'n2': building
+Taskmaster: 'n3': waiting on unfinished children:
+    ['n2']
+"""
+        assert value == expect, value
+
 
 
 if __name__ == "__main__":
diff --git a/test/option/taskmastertrace.py b/test/option/taskmastertrace.py
new file mode 100644
index 0000000..066e1ff
--- /dev/null
+++ b/test/option/taskmastertrace.py
@@ -0,0 +1,78 @@
+#!/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.
+#
+
+__revision__ = "__FILE__ __REVISION__ __DATE__ __DEVELOPER__"
+
+"""
+Simple tests of the --taskmastertrace= option.
+"""
+
+import TestSCons
+
+test = TestSCons.TestSCons()
+
+test.write('SConstruct', """
+env = Environment()
+env.Command('file.out', 'file.mid', Copy('$TARGET', '$SOURCE'))
+env.Command('file.mid', 'file.in', Copy('$TARGET', '$SOURCE'))
+""")
+
+test.write('file.in', "file.in\n")
+
+expect_stdout = test.wrap_stdout("""\
+Taskmaster: '.': waiting on unstarted children:
+    ['file.out', 'file.mid']
+Taskmaster: 'file.mid': building
+Copy("file.mid", "file.in")
+Taskmaster: 'file.out': building
+Copy("file.out", "file.mid")
+Taskmaster: '.': building
+""")
+
+test.run(arguments='--taskmastertrace=- .', stdout=expect_stdout)
+
+
+
+test.run(arguments='-c .')
+
+
+
+expect_stdout = test.wrap_stdout("""\
+Copy("file.mid", "file.in")
+Copy("file.out", "file.mid")
+""")
+
+test.run(arguments='--taskmastertrace=trace.out .', stdout=expect_stdout)
+
+expect_trace = """\
+Taskmaster: '.': waiting on unstarted children:
+    ['file.out', 'file.mid']
+Taskmaster: 'file.mid': building
+Taskmaster: 'file.out': building
+Taskmaster: '.': building
+"""
+
+test.must_match('trace.out', expect_trace)
+
+test.pass_test()