diff --git a/lib/oelite/oven.py b/lib/oelite/oven.py index b1930cf5..742fce83 100644 --- a/lib/oelite/oven.py +++ b/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)) + diff --git a/lib/oelite/task.py b/lib/oelite/task.py index 3e2234f0..0f5bad56 100644 --- a/lib/oelite/task.py +++ b/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,6 +293,8 @@ 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) @@ -297,6 +302,7 @@ def wait(self, poll=False): if not postfunc.run(wd or self.cwd): self.result = False break + self.postfunc_time = oelite.util.now() - func_end finally: self.restore_context()