Merge pull request #183 from Villemoes/ravi/oventweaks

Two leftover oven patches

lib/oelite/oven.py

@@ -35,6 +35,7 @@ def __init__(self, baker, capacity=None):
         self.capacity = capacity
         self.baker = baker
         self.starttime = dict()
+        self.completed_tasks = []
         self.failed_tasks = []
         self.total = baker.runq.number_of_tasks_to_build()
         self.count = 0
@@ -99,14 +100,16 @@ def wait_task(self, poll, task):
         if result is None:
             return None
         delta = self.remove(task)
+        task.task_time = delta
 
         task.recipe.remaining_tasks -= 1
         if result:
-            info("%s finished - %s s" % (task, delta))
+            info("%s finished - %.3f s" % (task, delta))
             task.build_done(self.baker.runq.get_task_buildhash(task))
             self.baker.runq.mark_done(task)
+            self.completed_tasks.append(task)
         else:
-            err("%s failed - %s s" % (task, delta))
+            err("%s failed - %.3f s" % (task, delta))
             self.failed_tasks.append(task)
             task.build_failed()
 
@@ -124,7 +127,7 @@ def wait_any(self, poll):
             t = tasks[0]
             if self.stdout_isatty:
                 now = oelite.util.now()
-                info("waiting for %s (started %6.2f ago) to finish" % (t, now-self.starttime[t]))
+                info("waiting for %s (started %.3f seconds ago) to finish" % (t, now-self.starttime[t]))
             return self.wait_task(False, t)
         tasks.sort(key=lambda t: self.starttime[t])
         i = 0
@@ -140,7 +143,7 @@ def wait_any(self, poll):
                 info("waiting for any of these to finish:")
                 now = oelite.util.now()
                 for t in tasks:
-                    info("  %-40s started %6.2f s ago" % (t, now-self.starttime[t]))
+                    info("  %-40s started %.3f seconds ago" % (t, now-self.starttime[t]))
             time.sleep(0.1)
         return None
 
@@ -163,3 +166,8 @@ def write_profiling_data(self):
                 out.write("%-16s  %7.1fs / %5d = %7.3fs  [%s]\n" %
                           (name, stats.sum, stats.count, stats.mean, quarts))
 
+        with oelite.profiling.profile_output("task_times.txt") as f:
+            for task in self.completed_tasks:
+                f.write("%s\t%.3f\t%.3f\t%.3f\t%.3f\n" %
+                        (task, task.task_time, task.prefunc_time, task.func_time, task.postfunc_time))
+

lib/oelite/task.py

@@ -243,12 +243,15 @@ def _start(self):
         self.apply_context()
 
         try:
+            prefunc_start = oelite.util.now()
             for prefunc in self.get_prefuncs():
                 print "running prefunc", prefunc
                 self.do_cleandirs(prefunc)
                 wd = self.do_dirs(prefunc)
                 if not prefunc.run(wd or self.cwd):
                     return False
+            self.func_start = oelite.util.now()
+            self.prefunc_time = self.func_start - prefunc_start
             try:
                 # start() doesn't return a value - but it may throw an
                 # exception. For, I think, mostly historical reasons,
@@ -290,13 +293,16 @@ def wait(self, poll=False):
             # failed. In either case, we shouldn't run the
             # postfuncs. Otherwise, we should run them.
             if self.result:
+                func_end = oelite.util.now()
+                self.func_time = func_end - self.func_start
                 for postfunc in self.get_postfuncs():
                     print "running postfunc", postfunc
                     self.do_cleandirs(postfunc)
                     wd = self.do_dirs(postfunc)
                     if not postfunc.run(wd or self.cwd):
                         self.result = False
                         break
+                self.postfunc_time = oelite.util.now() - func_end
         finally:
             self.restore_context()