show elapsed time for steps

Here's a patch, not yet tested:

Tue Apr 15 16:31:05 MDT 2008  zooko@zooko.com
  * log elapsedTime in slave.Command.commandComplete()
diff -rN -u old-trunk/buildbot/slave/commands.py new-trunk/buildbot/slave/commands.py
--- old-trunk/buildbot/slave/commands.py	2008-04-15 16:31:56.000000000 -0600
+++ new-trunk/buildbot/slave/commands.py	2008-04-15 16:31:56.000000000 -0600
@@ -649,6 +649,14 @@
     running = False # set by Builder, cleared on shutdown or when the
                     # Deferred fires
 
+    # For logging elapsed time:
+    startTime = None
+    elapsedTime = None
+    # I wish we had easy access to CLOCK_MONOTONIC in Python:
+    # http://www.opengroup.org/onlinepubs/000095399/functions/clock_getres.html
+    # Then changes to the system clock during a run wouldn't effect the "elapsed
+    # time" results.
+
     def __init__(self, builder, stepId, args):
         self.builder = builder
         self.stepId = stepId # just for logging
@@ -661,6 +669,7 @@
 
     def doStart(self):
         self.running = True
+        self.startTime = time.time()
         d = defer.maybeDeferred(self.start)
         d.addBoth(self.commandComplete)
         return d
@@ -694,6 +703,8 @@
 
     def commandComplete(self, res):
         self.running = False
+        self.elapsedTime = time.time() - self.startTime
+        log.msg("elapsedTime: %s" % self.elapsedTime)
         return res
 
     # utility methods, mostly used by SlaveShellCommand and the like

This only applies to the twistd.log on the buildslave side.. is that really what you want? If so, I have no problem with this. Let me know.

This was not what I wanted. I will submit an improved patch soon.

Okay, here is the one that does what I want. You can see it for example in the nooxie buildslave results at http://allmydata.org/buildbot .

Unfortunately, it doesn't pass the unit tests! Tsk, Tsk. :)

Also, I don't see it in use at allmydata.org?

Full list:

    testInterrupt1 ...                                                   [FAIL]
    testInterrupt2 ...                                                     [OK]
    testShell1 ...                                                       [FAIL]
    testShell2 ...                                                       [FAIL]
    testShellEnv ...                                                     [FAIL]
    testShellMissingCommand ...                                          [FAIL]
    testShellRC ...                                                      [FAIL]
    testShellSubdir ...                                                  [FAIL]
    testTimeout ...                                                      [FAIL]
  ShellPTY
    testInterrupt1 ...                                                   [FAIL]
    testShell1 ...                                                       [FAIL]
    testShell2 ...                                                       [FAIL]
    testShellEnv ...                                                     [FAIL]
    testShellMissingCommand ...                                          [FAIL]
    testShellRC ...                                                      [FAIL]
    testShellSubdir ...                                                  [FAIL]
    testTimeout ...                                                      [FAIL]

Example:

===============================================================================
[FAIL]: buildbot.test.test_slavecommand.ShellPTY.testShellSubdir

Traceback (most recent call last):
  File "/home/dev/devel/projects/buildbot/t/dustin/buildbot/test/test_slavecommand.py", line 130, in _checkPass
    self.checkrc(rc)
  File "/home/dev/devel/projects/buildbot/t/dustin/buildbot/test/test_slavecommand.py", line 109, in checkrc
    got = self.getrc()
  File "/home/dev/devel/projects/buildbot/t/dustin/buildbot/test/test_slavecommand.py", line 105, in getrc
    self.failUnless(self.builder.updates[-1].has_key('rc'))
twisted.trial.unittest.FailTest: None

I do use this patch on various buildslaves at allmydata.org, e.g.:

http://allmydata.org/buildbot/builders/windows/builds/648/steps/darcs-version/logs/stdio

I will look at the unit tests failures at some point.