| Message ID | 20210322130759.152562-1-amikan@ilbers.de |
|---|---|
| State | Rejected, archived |
| Headers | show |
| Series | charter: Introduce build chart generation tool | expand |
Do anyone interested in integration this profiling tool into ci-build? The main motivation is to have an ability to find the most time-consuming tasks during the build. 22.03.2021 16:07, Anton Mikanovich wrote: > This tool can generate Isar build charts from the logs prepend with > timestamps in format: %Y-%m-%d %H:%M:%S. > > Signed-off-by: Anton Mikanovich <amikan@ilbers.de>
On 22.04.21 12:22, Anton Mikanovich wrote: > Do anyone interested in integration this profiling tool into ci-build? > The main motivation is to have an ability to find the most > time-consuming tasks during the build. > Could you show some example results of it? Will it just work automatically, or how is the usage? Jan > 22.03.2021 16:07, Anton Mikanovich wrote: >> This tool can generate Isar build charts from the logs prepend with >> timestamps in format: %Y-%m-%d %H:%M:%S. >> >> Signed-off-by: Anton Mikanovich <amikan@ilbers.de> >
22.04.2021 14:17, Jan Kiszka wrote: > On 22.04.21 12:22, Anton Mikanovich wrote: >> Do anyone interested in integration this profiling tool into ci-build? >> The main motivation is to have an ability to find the most >> time-consuming tasks during the build. >> > Could you show some example results of it? Will it just work > automatically, or how is the usage? > > Jan > Here is an example of how output looks like: http://dl.ilbers.de/~amikan/buildchart_sample.svg It is just a proof of concept currently without any integration (you can run the tool for the usage guide). But it can be integrated into Isar (or CI?) as optional debugging tool.
I think we should not parse those logs and do our own profiling. bitbake has profiling support in several flavours. Last time i checked isar was missing some library bits that are only in oe. https://wiki.yoctoproject.org/wiki/Profiling We should see what is the state of the art in yocto/OE and use that, no own inventions. Then see how to get that into isar and possibly massage it upstream to get it into isar without forking oe/bitbake bits. Or we add "charter" to bitbake and take it from there, in case we fill a gap that upstream might have. Am i correct that this charter is something that oe/bitbake does not have? regards, Henning Am Mon, 22 Mar 2021 16:07:59 +0300 schrieb Anton Mikanovich <amikan@ilbers.de>: > This tool can generate Isar build charts from the logs prepend with > timestamps in format: %Y-%m-%d %H:%M:%S. > > Signed-off-by: Anton Mikanovich <amikan@ilbers.de> > --- > testsuite/charter/charter.py | 145 > +++++++++++++++++++++++++++++++++++ 1 file changed, 145 insertions(+) > create mode 100755 testsuite/charter/charter.py > > diff --git a/testsuite/charter/charter.py > b/testsuite/charter/charter.py new file mode 100755 > index 0000000..36ced98 > --- /dev/null > +++ b/testsuite/charter/charter.py > @@ -0,0 +1,145 @@ > +#!/usr/bin/python3 > + > +import cairo > +import re > +import sys > +from datetime import datetime > + > +timestamp_format = '%Y-%m-%d %H:%M:%S' > + > +try: > + isar_log = sys.argv[1]; > + output_filename = sys.argv[2]; > +except: > + print("Usage:", sys.argv[0], "isar.log output.svg") > + print("Log time format:", timestamp_format) > + print("Example: some_bitbake_command 2>&1 | gawk '{ print > strftime(\"" > + + timestamp_format + "\"), $0 }' > isar.log") > + sys.exit(1) > + > +class Buildtask: > + def __init__(self, package, task, start, stop): > + self.package = package > + self.task = task > + self.start = start > + self.stop = stop > + > +class Color: > + def __init__(self, r, g, b): > + self.r = r > + self.g = g > + self.b = b > + > +timestamp_first = 0 > +timestamp_last = 0 > +tasks = dict() > + > +log = open(isar_log) > +for line in log: > + line = line.rstrip() > + if re.search('NOTE: recipe', line): > + time = datetime.strptime(re.search('\d{4}-\d{2}-\d{2} > \d{2}:\d{2}:\d{2}', > + line).group(0), > timestamp_format).timestamp() > + if timestamp_first == 0: > + timestamp_first = time > + timestamp_last = time > + package = re.search('recipe\s(\S*):\stask\s\S*:\s\S*', > line).group(1) > + task = re.search('recipe\s\S*:\stask\s(\S*):\s\S*', > line).group(1) > + state = re.search('recipe\s\S*:\stask\s\S*:\s(\S*)', > line).group(1) > + key = package + ':' + task > + if key in tasks and state == 'Succeeded': > + tasks[key].stop = time - timestamp_first > + elif state == 'Started': > + tasks[key] = Buildtask(package, task, time - > timestamp_first, -1) +log.close() > + > +header_height = 40 > +footer_height = 5 > +spacer_left = 5 > +spacer_right = 250 > +line_height = 18 > +width_coef = 6 > +image_width = spacer_left + width_coef * int(timestamp_last - > + timestamp_first) + spacer_right > +image_height = header_height + len(tasks) * line_height + > footer_height + > +def task_color(task): > + return { > + 'do_install_builddeps': Color(1.0, 0.9, 0.7), > + 'do_dpkg_build': Color(0.9, 0.5, 0.4), > + 'do_deploy_deb': Color(0.5, 0.9, 0.5), > + 'do_rootfs_postprocess': Color(1.0, 0.4, 0.3) > + }.get(task, Color(0.7, 0.8, 0.9)) > + > +def fill_background(r, g, b): > + c.save() > + c.set_source_rgb(r, g, b) > + c.paint() > + c.restore() > + > +def draw_text(x, y, text, size, color=None): > + c.save() > + c.move_to(x, y) > + c.set_font_size(size) > + if color: > + c.set_source_rgb(color.r, color.g, color.b) > + c.show_text(text) > + c.restore() > + > +def draw_line(x, y, x2, y2, color, width=0.2): > + c.save() > + c.move_to(x, y) > + c.set_source_rgb(color.r, color.g, color.b) > + c.set_line_width(width) > + c.line_to(x2, y2) > + c.stroke() > + c.restore() > + > +def draw_rect(x, y, width, height, color=None): > + c.save() > + c.rectangle(x, y, width, height) > + if color: > + c.set_source_rgb(color.r, color.g, color.b) > + c.fill_preserve() > + c.set_line_width(0.2) > + c.set_source_rgb(0.8, 0.8, 0.8) > + c.stroke() > + c.restore() > + > +s = cairo.SVGSurface(output_filename, image_width, image_height) > +c = cairo.Context(s) > + > +c.select_font_face("DejaVuSerif", cairo.FONT_SLANT_NORMAL, > + cairo.FONT_WEIGHT_NORMAL) > + > +fill_background(1.0, 1.0, 1.0) > +draw_text(1, 24, "Isar build chart from " + datetime.fromtimestamp( > + timestamp_first).strftime(timestamp_format), 24, > Color(0.1, 0.1, 0.1)) + > +for n in range (int(timestamp_last - timestamp_first)): > + if n % 5 == 0: > + draw_text(spacer_left + n * width_coef, header_height - 1, > + str(n) + "s", 10, Color(0.5, 0.5, 0.5)) > + draw_line(spacer_left + n * width_coef, header_height, > + spacer_left + n * width_coef, image_height - > footer_height, > + Color(0.8, 0.8, 0.8), 0.4) > + else: > + draw_line(spacer_left + n * width_coef, header_height, > + spacer_left + n * width_coef, image_height - > footer_height, > + Color(0.9, 0.9, 0.9)) > + > +current_line = header_height > +for key in tasks: > + if tasks[key].stop < 0: > + tasks[key].stop = int(timestamp_last - timestamp_first) > + x1 = spacer_left + width_coef * tasks[key].start > + width = width_coef * (tasks[key].stop - tasks[key].start) > + if width <= 0: > + width = 1 > + draw_rect(x1, current_line, width, line_height, > task_color(tasks[key].task)) > + draw_text(x1 + 1, current_line + 12, '%s : %s (%ds)' % > (tasks[key].package, > + tasks[key].task, tasks[key].stop - tasks[key].start), > 12, > + Color(0.4, 0.4, 0.4)) > + current_line += line_height > + > +s.finish()
27.04.2021 20:01, Henning Schild wrote: > I think we should not parse those logs and do our own profiling. > bitbake has profiling support in several flavours. Last time i checked > isar was missing some library bits that are only in oe. > > https://wiki.yoctoproject.org/wiki/Profiling > > We should see what is the state of the art in yocto/OE and use that, no > own inventions. Then see how to get that into isar and possibly massage > it upstream to get it into isar without forking oe/bitbake bits. > Or we add "charter" to bitbake and take it from there, in case we fill > a gap that upstream might have. > > Am i correct that this charter is something that oe/bitbake does not > have? > > regards, > Henning Yes, this charter is our simple implementation of the same result as pybootchart+buildstats can produce in oe. Buildstats-based solution is also not real-time and integration of the whole buildstats into Isar can be tricky.
Am Tue, 27 Apr 2021 20:28:28 +0300 schrieb Anton Mikanovich <amikan@ilbers.de>: > 27.04.2021 20:01, Henning Schild wrote: > > I think we should not parse those logs and do our own profiling. > > bitbake has profiling support in several flavours. Last time i > > checked isar was missing some library bits that are only in oe. > > > > https://eur01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwiki.yoctoproject.org%2Fwiki%2FProfiling&data=04%7C01%7Cde173c00-e982-4fda-8644-47edf4671d63%40ad011.siemens.com%7Cc6c6d17c69c04eeaf7af08d909a1e352%7C38ae3bcd95794fd4addab42e1495d55a%7C1%7C0%7C637551413172636476%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&sdata=hYyPIOO5TOCgZ%2B3kO7deFafAfhTi787HeXsgDqUTy1A%3D&reserved=0 > > > > We should see what is the state of the art in yocto/OE and use > > that, no own inventions. Then see how to get that into isar and > > possibly massage it upstream to get it into isar without forking > > oe/bitbake bits. Or we add "charter" to bitbake and take it from > > there, in case we fill a gap that upstream might have. > > > > Am i correct that this charter is something that oe/bitbake does not > > have? > > > > regards, > > Henning > > Yes, this charter is our simple implementation of the same result as > pybootchart+buildstats can produce in oe. If it is "the same" i would like to question why we need that again and can not use what is there. > Buildstats-based solution is also not real-time and integration of > the whole buildstats into Isar can be tricky. We should look into why upstream can be tricky for us and solve those tricky issues, or add that "charter" upstream if it fills a gap that upstream might have. Forking bitbake (and wic, probably not involved here) would be a really bad idea. And even adding plugins might be bad. For such central topics working together with oe and bitbake is the only maintainable way ... IMHO. I already invested a lot on the wic side and also on bitbake, and the projects seem to be open to the isar-case from what i can tell. regards, Henning
diff --git a/testsuite/charter/charter.py b/testsuite/charter/charter.py new file mode 100755 index 0000000..36ced98 --- /dev/null +++ b/testsuite/charter/charter.py @@ -0,0 +1,145 @@ +#!/usr/bin/python3 + +import cairo +import re +import sys +from datetime import datetime + +timestamp_format = '%Y-%m-%d %H:%M:%S' + +try: + isar_log = sys.argv[1]; + output_filename = sys.argv[2]; +except: + print("Usage:", sys.argv[0], "isar.log output.svg") + print("Log time format:", timestamp_format) + print("Example: some_bitbake_command 2>&1 | gawk '{ print strftime(\"" + + timestamp_format + "\"), $0 }' > isar.log") + sys.exit(1) + +class Buildtask: + def __init__(self, package, task, start, stop): + self.package = package + self.task = task + self.start = start + self.stop = stop + +class Color: + def __init__(self, r, g, b): + self.r = r + self.g = g + self.b = b + +timestamp_first = 0 +timestamp_last = 0 +tasks = dict() + +log = open(isar_log) +for line in log: + line = line.rstrip() + if re.search('NOTE: recipe', line): + time = datetime.strptime(re.search('\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}', + line).group(0), timestamp_format).timestamp() + if timestamp_first == 0: + timestamp_first = time + timestamp_last = time + package = re.search('recipe\s(\S*):\stask\s\S*:\s\S*', line).group(1) + task = re.search('recipe\s\S*:\stask\s(\S*):\s\S*', line).group(1) + state = re.search('recipe\s\S*:\stask\s\S*:\s(\S*)', line).group(1) + key = package + ':' + task + if key in tasks and state == 'Succeeded': + tasks[key].stop = time - timestamp_first + elif state == 'Started': + tasks[key] = Buildtask(package, task, time - timestamp_first, -1) +log.close() + +header_height = 40 +footer_height = 5 +spacer_left = 5 +spacer_right = 250 +line_height = 18 +width_coef = 6 +image_width = spacer_left + width_coef * int(timestamp_last - + timestamp_first) + spacer_right +image_height = header_height + len(tasks) * line_height + footer_height + +def task_color(task): + return { + 'do_install_builddeps': Color(1.0, 0.9, 0.7), + 'do_dpkg_build': Color(0.9, 0.5, 0.4), + 'do_deploy_deb': Color(0.5, 0.9, 0.5), + 'do_rootfs_postprocess': Color(1.0, 0.4, 0.3) + }.get(task, Color(0.7, 0.8, 0.9)) + +def fill_background(r, g, b): + c.save() + c.set_source_rgb(r, g, b) + c.paint() + c.restore() + +def draw_text(x, y, text, size, color=None): + c.save() + c.move_to(x, y) + c.set_font_size(size) + if color: + c.set_source_rgb(color.r, color.g, color.b) + c.show_text(text) + c.restore() + +def draw_line(x, y, x2, y2, color, width=0.2): + c.save() + c.move_to(x, y) + c.set_source_rgb(color.r, color.g, color.b) + c.set_line_width(width) + c.line_to(x2, y2) + c.stroke() + c.restore() + +def draw_rect(x, y, width, height, color=None): + c.save() + c.rectangle(x, y, width, height) + if color: + c.set_source_rgb(color.r, color.g, color.b) + c.fill_preserve() + c.set_line_width(0.2) + c.set_source_rgb(0.8, 0.8, 0.8) + c.stroke() + c.restore() + +s = cairo.SVGSurface(output_filename, image_width, image_height) +c = cairo.Context(s) + +c.select_font_face("DejaVuSerif", cairo.FONT_SLANT_NORMAL, + cairo.FONT_WEIGHT_NORMAL) + +fill_background(1.0, 1.0, 1.0) +draw_text(1, 24, "Isar build chart from " + datetime.fromtimestamp( + timestamp_first).strftime(timestamp_format), 24, Color(0.1, 0.1, 0.1)) + +for n in range (int(timestamp_last - timestamp_first)): + if n % 5 == 0: + draw_text(spacer_left + n * width_coef, header_height - 1, + str(n) + "s", 10, Color(0.5, 0.5, 0.5)) + draw_line(spacer_left + n * width_coef, header_height, + spacer_left + n * width_coef, image_height - footer_height, + Color(0.8, 0.8, 0.8), 0.4) + else: + draw_line(spacer_left + n * width_coef, header_height, + spacer_left + n * width_coef, image_height - footer_height, + Color(0.9, 0.9, 0.9)) + +current_line = header_height +for key in tasks: + if tasks[key].stop < 0: + tasks[key].stop = int(timestamp_last - timestamp_first) + x1 = spacer_left + width_coef * tasks[key].start + width = width_coef * (tasks[key].stop - tasks[key].start) + if width <= 0: + width = 1 + draw_rect(x1, current_line, width, line_height, task_color(tasks[key].task)) + draw_text(x1 + 1, current_line + 12, '%s : %s (%ds)' % (tasks[key].package, + tasks[key].task, tasks[key].stop - tasks[key].start), 12, + Color(0.4, 0.4, 0.4)) + current_line += line_height + +s.finish()
This tool can generate Isar build charts from the logs prepend with timestamps in format: %Y-%m-%d %H:%M:%S. Signed-off-by: Anton Mikanovich <amikan@ilbers.de> --- testsuite/charter/charter.py | 145 +++++++++++++++++++++++++++++++++++ 1 file changed, 145 insertions(+) create mode 100755 testsuite/charter/charter.py