[PATCH] charter: Introduce build chart generation tool

[PATCH] charter: Introduce build chart generation tool

[Anton Mikanovich]

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()
-- 
2.20.1

Re: [PATCH] charter: Introduce build chart generation tool

[Anton Mikanovich]

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>

-- 
Anton Mikanovich
Promwad Ltd.
External service provider of ilbers GmbH
Maria-Merian-Str. 8
85521 Ottobrunn, Germany
+49 (89) 122 67 24-0
Commercial register Munich, HRB 214197
General Manager: Baurzhan Ismagulov

Re: [PATCH] charter: Introduce build chart generation tool

[Jan Kiszka]

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>
> 

-- 
Siemens AG, T RDA IOT
Corporate Competence Center Embedded Linux

Re: [PATCH] charter: Introduce build chart generation tool

[Anton Mikanovich]

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.

-- 
Anton Mikanovich
Promwad Ltd.
External service provider of ilbers GmbH
Maria-Merian-Str. 8
85521 Ottobrunn, Germany
+49 (89) 122 67 24-0
Commercial register Munich, HRB 214197
General Manager: Baurzhan Ismagulov

Re: [PATCH] charter: Introduce build chart generation tool

[Henning Schild]

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()

Re: [PATCH] charter: Introduce build chart generation tool

[Anton Mikanovich]

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.

-- 
Anton Mikanovich
Promwad Ltd.
External service provider of ilbers GmbH
Maria-Merian-Str. 8
85521 Ottobrunn, Germany
+49 (89) 122 67 24-0
Commercial register Munich, HRB 214197
General Manager: Baurzhan Ismagulov

Re: [PATCH] charter: Introduce build chart generation tool

[Henning Schild]

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&amp;data=04%7C01%7Cde173c00-e982-4fda-8644-47edf4671d63%40ad011.siemens.com%7Cc6c6d17c69c04eeaf7af08d909a1e352%7C38ae3bcd95794fd4addab42e1495d55a%7C1%7C0%7C637551413172636476%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&amp;sdata=hYyPIOO5TOCgZ%2B3kO7deFafAfhTi787HeXsgDqUTy1A%3D&amp;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