oelite/oven.py: record and store detailed task timings

All pre- and post-funcs run synchronously in the main oe process. Some
of these tend to be rather time-consuming, so it would be better if they
could be made into tasks of their own, or run as part of the main task
function, or just optimized to run faster. Otherwise, the oven risks
being underused for a long time (for example, some do_install script
finishes, and we go on to execute the associated postfuncs, which may
take > 30 seconds to complete - meanwhile, some do_compile task has
finished, but there's no way we'll notice before we're done with those
postfuncs).

Knowing which tasks' pre- and postfuncs take a long time is useful for
finding recipes (or maybe whole classes) that are worth optimizing.

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,12 +100,14 @@ 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))
             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))
             self.failed_tasks.append(task)
@@ -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()