From 2364682635b3cd17d5d92b4560144889d0e09ecb Mon Sep 17 00:00:00 2001 From: Rasmus Villemoes Date: Tue, 4 Oct 2016 14:03:00 +0200 Subject: [PATCH 1/2] 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 | 8 ++++++++ lib/oelite/task.py | 6 ++++++ 2 files changed, 14 insertions(+) diff --git a/lib/oelite/oven.py b/lib/oelite/oven.py index b1930cf5..fede0cdb 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,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)) + 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() From f538036735c53806ff8e5ef87c3c00fc0104a51e Mon Sep 17 00:00:00 2001 From: Rasmus Villemoes Date: Fri, 28 Oct 2016 12:42:38 +0200 Subject: [PATCH 2/2] oelite/oven.py: print times with millisecond accuracy There's just a tad too many digits in "native:bzip2_1.0.6:do_package finished - 1.51460909843 s". Print all time deltas with "%.3f". --- lib/oelite/oven.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/lib/oelite/oven.py b/lib/oelite/oven.py index fede0cdb..742fce83 100644 --- a/lib/oelite/oven.py +++ b/lib/oelite/oven.py @@ -104,12 +104,12 @@ def wait_task(self, poll, task): 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() @@ -127,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 @@ -143,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