[PATCH 00/11] system statistics sampling

[PATCH 00/11] system statistics sampling

[Patrick Ohly]

These patches depend on the corresponding patches to bitbake.

buildstats.bbclass gets extended so that disk bandwidth and capacity,
CPU and memory usage get sampled at regular time intervals by
default. pybootchart had code for most of that data, which gets
restored and re-enabled. The disk capacity graph is new.

The original pybootchart just stored raw dumps of the special files
under /proc. bitbake builds run longer, so a more compact ("reduced")
format is used.

Logging disk capacity was mostly motivated by some work on enhancing
rm_work.bbclass behavior, but could also be useful for others ("how
much free space did my build need").

The following changes since commit 9f1fe76727e98e58fc9e46ea2b49cf5c0cb48e6c:

  libpcap: Fix build when PACKAGECONFIG ipv6 is not enable (2016-11-23 11:02:33 +0000)

are available in the git repository at:

  git://github.com/pohly/openembedded-core buildstats
  https://github.com/pohly/openembedded-core/tree/buildstats

Patrick Ohly (11):
  buildstats: add system state sampling
  pybootchartgui/draw.py: allow moving process chart up and down
  pybootchartgui/draw.py: fix drawing of samples not starting at zero
  pybootchartgui: show system utilization
  pybootchartgui/draw.py: skip empty CPU and disk usage charts
  buildstats: record disk space usage
  pybootchartgui/parsing.py: fix error handling in meminfo parser
  pybootchartgui: render disk space usage
  pybootchartgui: simplify drawing of memory usage
  buildstats: reduce amount of data stored for system utilization
  pybootchartgui: support reading reduced /proc logs

 meta/classes/buildstats.bbclass                  |  16 ++
 meta/lib/buildstats.py                           | 156 ++++++++++++++++++
 scripts/pybootchartgui/pybootchartgui/draw.py    | 192 ++++++++++++++++-------
 scripts/pybootchartgui/pybootchartgui/parsing.py | 122 +++++++++++---
 scripts/pybootchartgui/pybootchartgui/samples.py |  27 ++++
 5 files changed, 435 insertions(+), 78 deletions(-)
 create mode 100644 meta/lib/buildstats.py

-- 
2.1.4

[PATCH 01/11] buildstats: add system state sampling

[Patrick Ohly]

/proc/[diskstats|meminfo|stat] get sampled and written to the same
proc_<filename>.log files as during normal bootchat logging. This will
allow rendering the CPU, disk and memory usage charts.

Right now sampling happens once a second, triggered by the heartbeat
event.That produces quite a bit of data for long builds, which will be
addressed in a separate commit by storing the data in a more compact
form.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 meta/classes/buildstats.bbclass | 16 +++++++++++++
 meta/lib/buildstats.py          | 50 +++++++++++++++++++++++++++++++++++++++++
 2 files changed, 66 insertions(+)
 create mode 100644 meta/lib/buildstats.py

diff --git a/meta/classes/buildstats.bbclass b/meta/classes/buildstats.bbclass
index 57ecc8f..2abc1a7 100644
--- a/meta/classes/buildstats.bbclass
+++ b/meta/classes/buildstats.bbclass
@@ -188,3 +188,19 @@ python run_buildstats () {
 addhandler run_buildstats
 run_buildstats[eventmask] = "bb.event.BuildStarted bb.event.BuildCompleted bb.build.TaskStarted bb.build.TaskSucceeded bb.build.TaskFailed"
 
+python runqueue_stats () {
+    import buildstats
+    from bb import event, runqueue
+    # We should not record any samples before the first task has started,
+    # because that's the first activity shown in the process chart.
+    # Besides, at that point we are sure that the build variables
+    # are available that we need to find the output directory.
+    init = isinstance(e, bb.runqueue.runQueueTaskStarted)
+    system_stats = buildstats.get_system_stats(d, init=init)
+    if system_stats:
+        # Ensure that we sample at important events.
+        system_stats.sample(force=isinstance(e, bb.event.BuildCompleted))
+}
+
+addhandler runqueue_stats
+runqueue_stats[eventmask] = "bb.runqueue.runQueueTaskStarted bb.event.HeartbeatEvent bb.event.BuildCompleted"
diff --git a/meta/lib/buildstats.py b/meta/lib/buildstats.py
new file mode 100644
index 0000000..1664c52
--- /dev/null
+++ b/meta/lib/buildstats.py
@@ -0,0 +1,50 @@
+# Implements system state sampling. Called by buildstats.bbclass.
+# Because it is a real Python module, it can hold persistent state,
+# like open log files and the time of the last sampling.
+
+import time
+
+class SystemStats:
+    def __init__(self, d):
+        bn = d.getVar('BUILDNAME', True)
+        bsdir = os.path.join(d.getVar('BUILDSTATS_BASE', True), bn)
+        bb.utils.mkdirhier(bsdir)
+
+        self.proc_files = []
+        for filename in ('diskstats', 'meminfo', 'stat'):
+            # In practice, this class gets instantiated only once in
+            # the bitbake cooker process.  Therefore 'append' mode is
+            # not strictly necessary, but using it makes the class
+            # more robust should two processes ever write
+            # concurrently.
+            self.proc_files.append((filename,
+                                    open(os.path.join(bsdir, 'proc_%s.log' % filename), 'ab')))
+        # Last time that we sampled data.
+        self.last = 0
+        # Minimum number of seconds between recording a sample. This
+        # becames relevant when we get called very often while many
+        # short tasks get started. Sampling during quiet periods
+        # depends on the heartbeat event, which fires less often.
+        self.min_seconds = 1
+
+    def sample(self, force):
+        now = time.time()
+        if (now - self.last > self.min_seconds) or force:
+            for filename, output in self.proc_files:
+                with open(os.path.join('/proc', filename), 'rb') as input:
+                    data = input.read()
+                    # Unbuffered raw write, less overhead and useful
+                    # in case that we end up with concurrent writes.
+                    os.write(output.fileno(),
+                             ('%.0f\n' % now).encode('ascii') +
+                             data +
+                             b'\n')
+            self.last = now
+
+_system_stats = None
+
+def get_system_stats(d, init):
+    global _system_stats
+    if not _system_stats and init:
+        _system_stats = SystemStats(d)
+    return _system_stats
-- 
2.1.4

Re: [PATCH 01/11] buildstats: add system state sampling

[Andreas Oberritter]

Hi Patrick,

On 28.11.2016 16:33, Patrick Ohly wrote:
> /proc/[diskstats|meminfo|stat] get sampled and written to the same
> proc_<filename>.log files as during normal bootchat logging. This will
> allow rendering the CPU, disk and memory usage charts.
> 
> Right now sampling happens once a second, triggered by the heartbeat
> event.That produces quite a bit of data for long builds, which will be
> addressed in a separate commit by storing the data in a more compact
> form.
> 
> Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
> ---
>  meta/classes/buildstats.bbclass | 16 +++++++++++++
>  meta/lib/buildstats.py          | 50 +++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 66 insertions(+)
>  create mode 100644 meta/lib/buildstats.py
> 
> diff --git a/meta/classes/buildstats.bbclass b/meta/classes/buildstats.bbclass
> index 57ecc8f..2abc1a7 100644
> --- a/meta/classes/buildstats.bbclass
> +++ b/meta/classes/buildstats.bbclass
> @@ -188,3 +188,19 @@ python run_buildstats () {
>  addhandler run_buildstats
>  run_buildstats[eventmask] = "bb.event.BuildStarted bb.event.BuildCompleted bb.build.TaskStarted bb.build.TaskSucceeded bb.build.TaskFailed"
>  
> +python runqueue_stats () {
> +    import buildstats
> +    from bb import event, runqueue
> +    # We should not record any samples before the first task has started,
> +    # because that's the first activity shown in the process chart.
> +    # Besides, at that point we are sure that the build variables
> +    # are available that we need to find the output directory.
> +    init = isinstance(e, bb.runqueue.runQueueTaskStarted)
> +    system_stats = buildstats.get_system_stats(d, init=init)
> +    if system_stats:
> +        # Ensure that we sample at important events.
> +        system_stats.sample(force=isinstance(e, bb.event.BuildCompleted))
> +}
> +
> +addhandler runqueue_stats
> +runqueue_stats[eventmask] = "bb.runqueue.runQueueTaskStarted bb.event.HeartbeatEvent bb.event.BuildCompleted"
> diff --git a/meta/lib/buildstats.py b/meta/lib/buildstats.py
> new file mode 100644
> index 0000000..1664c52
> --- /dev/null
> +++ b/meta/lib/buildstats.py
> @@ -0,0 +1,50 @@
> +# Implements system state sampling. Called by buildstats.bbclass.
> +# Because it is a real Python module, it can hold persistent state,
> +# like open log files and the time of the last sampling.
> +
> +import time
> +
> +class SystemStats:
> +    def __init__(self, d):
> +        bn = d.getVar('BUILDNAME', True)
> +        bsdir = os.path.join(d.getVar('BUILDSTATS_BASE', True), bn)
> +        bb.utils.mkdirhier(bsdir)
> +
> +        self.proc_files = []
> +        for filename in ('diskstats', 'meminfo', 'stat'):
> +            # In practice, this class gets instantiated only once in
> +            # the bitbake cooker process.  Therefore 'append' mode is
> +            # not strictly necessary, but using it makes the class
> +            # more robust should two processes ever write
> +            # concurrently.
> +            self.proc_files.append((filename,
> +                                    open(os.path.join(bsdir, 'proc_%s.log' % filename), 'ab')))
> +        # Last time that we sampled data.
> +        self.last = 0
> +        # Minimum number of seconds between recording a sample. This
> +        # becames relevant when we get called very often while many
> +        # short tasks get started. Sampling during quiet periods
> +        # depends on the heartbeat event, which fires less often.
> +        self.min_seconds = 1
> +
> +    def sample(self, force):
> +        now = time.time()
> +        if (now - self.last > self.min_seconds) or force:
> +            for filename, output in self.proc_files:
> +                with open(os.path.join('/proc', filename), 'rb') as input:
                        ^
this fails with a backtrace if /proc/diskstats is not available, which
may be the case in virtualized environments, e.g. Linux-VServer.

Regards,
Andreas

Re: [PATCH 01/11] buildstats: add system state sampling

[Patrick Ohly]

On Fri, 2016-12-09 at 01:29 +0100, Andreas Oberritter wrote:
> Hi Patrick,
> 
> On 28.11.2016 16:33, Patrick Ohly wrote:
> > +    def sample(self, force):
> > +        now = time.time()
> > +        if (now - self.last > self.min_seconds) or force:
> > +            for filename, output in self.proc_files:
> > +                with open(os.path.join('/proc', filename), 'rb') as input:
>                         ^
> this fails with a backtrace if /proc/diskstats is not available, which
> may be the case in virtualized environments, e.g. Linux-VServer.

Thanks for pointing that out, I'll send a fix.

-- 
Best Regards, Patrick Ohly

The content of this message is my personal opinion only and although
I am an employee of Intel, the statements I make here in no way
represent Intel's position on the issue, nor am I authorized to speak
on behalf of Intel on this matter.

Re: [PATCH 01/11] buildstats: add system state sampling

[Patrick Ohly]

On Fri, 2016-12-09 at 01:29 +0100, Andreas Oberritter wrote:
> Hi Patrick,
> 
> On 28.11.2016 16:33, Patrick Ohly wrote:
> > +    def sample(self, force):
> > +        now = time.time()
> > +        if (now - self.last > self.min_seconds) or force:
> > +            for filename, output in self.proc_files:
> > +                with open(os.path.join('/proc', filename), 'rb') as input:
>                         ^
> this fails with a backtrace if /proc/diskstats is not available, which
> may be the case in virtualized environments, e.g. Linux-VServer.

Thanks for pointing that out, I'll send a fix.

-- 
Best Regards, Patrick Ohly

The content of this message is my personal opinion only and although
I am an employee of Intel, the statements I make here in no way
represent Intel's position on the issue, nor am I authorized to speak
on behalf of Intel on this matter.

[PATCH 02/11] pybootchartgui/draw.py: allow moving process chart up and down

[Patrick Ohly]

Substracting curr_y when determining the hight of the process chart is
wrong because the height is independent of the position where the
chart is about to be drawn. It happens to work at the moment because
curr_y is always 10 when render_processes_chart() gets called. But it
leads to a negative height when other charts are drawn above it, and
then the grid gets drawn on top of those other charts.

Substracting some constant is relevant because otherwise the box is
slightly larger than the process bars. Not sure exactly where that
comes from (text height?); leg_s seems a suitable constant and happens
to be 10, so everything still gets rendered exactly as before.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 scripts/pybootchartgui/pybootchartgui/draw.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/pybootchartgui/pybootchartgui/draw.py b/scripts/pybootchartgui/pybootchartgui/draw.py
index 8c574be..2b5907b 100644
--- a/scripts/pybootchartgui/pybootchartgui/draw.py
+++ b/scripts/pybootchartgui/pybootchartgui/draw.py
@@ -415,7 +415,7 @@ def render_charts(ctx, options, clip, trace, curr_y, w, h, sec_w):
 	return curr_y
 
 def render_processes_chart(ctx, options, trace, curr_y, w, h, sec_w):
-        chart_rect = [off_x, curr_y+header_h, w, h - 2 * off_y - (curr_y+header_h) + proc_h]
+        chart_rect = [off_x, curr_y+header_h, w, h - 2 * off_y - header_h - leg_s + proc_h]
 
 	draw_legend_box (ctx, "Configure", \
 			 TASK_COLOR_CONFIGURE, off_x  , curr_y + 45, leg_s)
-- 
2.1.4

[PATCH 03/11] pybootchartgui/draw.py: fix drawing of samples not starting at zero

[Patrick Ohly]

The code did not handle x scaling correctly when drawing starts at
some time larger than zero, i.e. it worked for normal bootchart data,
but not for the system statistics recorded by buildstats.bbclass.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 scripts/pybootchartgui/pybootchartgui/draw.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/pybootchartgui/pybootchartgui/draw.py b/scripts/pybootchartgui/pybootchartgui/draw.py
index 2b5907b..925002d 100644
--- a/scripts/pybootchartgui/pybootchartgui/draw.py
+++ b/scripts/pybootchartgui/pybootchartgui/draw.py
@@ -256,7 +256,7 @@ def draw_chart(ctx, color, fill, chart_bounds, data, proc_tree, data_range):
 	# avoid divide by zero
 	if max_y == 0:
 		max_y = 1.0
-	xscale = float (chart_bounds[2]) / max_x
+	xscale = float (chart_bounds[2]) / (max_x - x_shift)
 	# If data_range is given, scale the chart so that the value range in
 	# data_range matches the chart bounds exactly.
 	# Otherwise, scale so that the actual data matches the chart bounds.
-- 
2.1.4

[PATCH 04/11] pybootchartgui: show system utilization

[Patrick Ohly]

This enables rendering of the original bootchart charts for CPU, disk
and memory usage. It depends on the /proc samples recorded by the
updated buildstats.bbclass. Currently, empty charts CPU and disk usage
charts are drawn if that data is not present; the memory chart already
gets skipped when there's no data, which will also have to be added
for the other two.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 scripts/pybootchartgui/pybootchartgui/draw.py    | 16 +++++--
 scripts/pybootchartgui/pybootchartgui/parsing.py | 61 +++++++++++++++++-------
 2 files changed, 57 insertions(+), 20 deletions(-)

diff --git a/scripts/pybootchartgui/pybootchartgui/draw.py b/scripts/pybootchartgui/pybootchartgui/draw.py
index 925002d..bddd804 100644
--- a/scripts/pybootchartgui/pybootchartgui/draw.py
+++ b/scripts/pybootchartgui/pybootchartgui/draw.py
@@ -321,6 +321,16 @@ def extents(options, xscale, trace):
 	w = int ((end - start) * sec_w_base * xscale) + 2 * off_x
 	h = proc_h * processes + header_h + 2 * off_y
 
+	if options.charts:
+		if trace.cpu_stats:
+			h += 30 + bar_h
+		if trace.disk_stats:
+			h += 30 + bar_h
+		if trace.monitor_disk:
+			h += 30 + bar_h
+		if trace.mem_stats:
+			h += meminfo_bar_h
+
 	return (w, h)
 
 def clip_visible(clip, rect):
@@ -496,6 +506,9 @@ def render(ctx, options, xscale, trace):
 	w -= 2*off_x
 	curr_y = off_y;
 
+	if options.charts:
+		curr_y = render_charts (ctx, options, clip, trace, curr_y, w, h, sec_w)
+
 	curr_y = render_processes_chart (ctx, options, trace, curr_y, w, h, sec_w)
 
 	return
@@ -513,9 +526,6 @@ def render(ctx, options, xscale, trace):
 	else:
 		curr_y = off_y;
 
-	if options.charts:
-		curr_y = render_charts (ctx, options, clip, trace, curr_y, w, h, sec_w)
-
 	# draw process boxes
 	proc_height = h
 	if proc_tree.taskstats and options.cumulative:
diff --git a/scripts/pybootchartgui/pybootchartgui/parsing.py b/scripts/pybootchartgui/pybootchartgui/parsing.py
index a3a0b0b..af68435 100644
--- a/scripts/pybootchartgui/pybootchartgui/parsing.py
+++ b/scripts/pybootchartgui/pybootchartgui/parsing.py
@@ -38,16 +38,17 @@ class Trace:
         self.min = None
         self.max = None
         self.headers = None
-        self.disk_stats = None
+        self.disk_stats =  []
         self.ps_stats = None
         self.taskstats = None
-        self.cpu_stats = None
+        self.cpu_stats = []
         self.cmdline = None
         self.kernel = None
         self.kernel_tree = None
         self.filename = None
         self.parent_map = None
-        self.mem_stats = None
+        self.mem_stats = []
+        self.times = [] # Always empty, but expected by draw.py when drawing system charts.
 
         if len(paths):
             parse_paths (writer, self, paths)
@@ -58,6 +59,19 @@ class Trace:
                 self.min = min(self.start.keys())
                 self.max = max(self.end.keys())
 
+
+        # Rendering system charts depends on start and end
+        # time. Provide them where the original drawing code expects
+        # them, i.e. in proc_tree.
+        class BitbakeProcessTree:
+            def __init__(self, start_time, end_time):
+                self.start_time = start_time
+                self.end_time = end_time
+                self.duration = self.end_time - self.start_time
+        self.proc_tree = BitbakeProcessTree(min(self.start.keys()),
+                                            max(self.end.keys()))
+
+
         return
 
         # Turn that parsed information into something more useful
@@ -427,7 +441,7 @@ def _parse_proc_stat_log(file):
         # skip the rest of statistics lines
     return samples
 
-def _parse_proc_disk_stat_log(file, numCpu):
+def _parse_proc_disk_stat_log(file):
     """
     Parse file for disk stats, but only look at the whole device, eg. sda,
     not sda1, sda2 etc. The format of relevant lines should be:
@@ -462,7 +476,7 @@ def _parse_proc_disk_stat_log(file, numCpu):
         sums = [ a - b for a, b in zip(sample1.diskdata, sample2.diskdata) ]
         readTput = sums[0] / 2.0 * 100.0 / interval
         writeTput = sums[1] / 2.0 * 100.0 / interval
-        util = float( sums[2] ) / 10 / interval / numCpu
+        util = float( sums[2] ) / 10 / interval
         util = max(0.0, min(1.0, util))
         disk_stats.append(DiskSample(sample2.time, readTput, writeTput, util))
 
@@ -628,6 +642,20 @@ def _parse_cmdline_log(writer, file):
             cmdLines[pid] = values
     return cmdLines
 
+def _parse_bitbake_buildstats(writer, state, filename, file):
+    paths = filename.split("/")
+    task = paths[-1]
+    pn = paths[-2]
+    start = None
+    end = None
+    for line in file:
+        if line.startswith("Started:"):
+            start = int(float(line.split()[-1]))
+        elif line.startswith("Ended:"):
+            end = int(float(line.split()[-1]))
+    if start and end:
+        state.add_process(pn + ":" + task, start, end)
+
 def get_num_cpus(headers):
     """Get the number of CPUs from the system.cpu header property. As the
     CPU utilization graphs are relative, the number of CPUs currently makes
@@ -647,18 +675,17 @@ def get_num_cpus(headers):
 def _do_parse(writer, state, filename, file):
     writer.info("parsing '%s'" % filename)
     t1 = clock()
-    paths = filename.split("/")
-    task = paths[-1]
-    pn = paths[-2]
-    start = None
-    end = None
-    for line in file:
-        if line.startswith("Started:"):
-            start = int(float(line.split()[-1]))
-        elif line.startswith("Ended:"):
-            end = int(float(line.split()[-1]))
-    if start and end:
-        state.add_process(pn + ":" + task, start, end)
+    name = os.path.basename(filename)
+    if name == "proc_diskstats.log":
+        state.disk_stats = _parse_proc_disk_stat_log(file)
+    elif name == "proc_stat.log":
+        state.cpu_stats = _parse_proc_stat_log(file)
+    elif name == "proc_meminfo.log":
+        state.mem_stats = _parse_proc_meminfo_log(file)
+    elif name == "cmdline2.log":
+        state.cmdline = _parse_cmdline_log(writer, file)
+    elif not filename.endswith('.log'):
+        _parse_bitbake_buildstats(writer, state, filename, file)
     t2 = clock()
     writer.info("  %s seconds" % str(t2-t1))
     return state
-- 
2.1.4

[PATCH 05/11] pybootchartgui/draw.py: skip empty CPU and disk usage charts

[Patrick Ohly]

The only real change is the addition of two if checks that skips the
corresponding drawing code when there is no data.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 scripts/pybootchartgui/pybootchartgui/draw.py | 98 ++++++++++++++-------------
 1 file changed, 50 insertions(+), 48 deletions(-)

diff --git a/scripts/pybootchartgui/pybootchartgui/draw.py b/scripts/pybootchartgui/pybootchartgui/draw.py
index bddd804..ec5dd33 100644
--- a/scripts/pybootchartgui/pybootchartgui/draw.py
+++ b/scripts/pybootchartgui/pybootchartgui/draw.py
@@ -344,56 +344,58 @@ def render_charts(ctx, options, clip, trace, curr_y, w, h, sec_w):
 	proc_tree = options.proc_tree(trace)
 
 	# render bar legend
-	ctx.set_font_size(LEGEND_FONT_SIZE)
-
-	draw_legend_box(ctx, "CPU (user+sys)", CPU_COLOR, off_x, curr_y+20, leg_s)
-	draw_legend_box(ctx, "I/O (wait)", IO_COLOR, off_x + 120, curr_y+20, leg_s)
-
-	# render I/O wait
-	chart_rect = (off_x, curr_y+30, w, bar_h)
-	if clip_visible (clip, chart_rect):
-		draw_box_ticks (ctx, chart_rect, sec_w)
-		draw_annotations (ctx, proc_tree, trace.times, chart_rect)
-		draw_chart (ctx, IO_COLOR, True, chart_rect, \
-			    [(sample.time, sample.user + sample.sys + sample.io) for sample in trace.cpu_stats], \
-			    proc_tree, None)
-		# render CPU load
-		draw_chart (ctx, CPU_COLOR, True, chart_rect, \
-			    [(sample.time, sample.user + sample.sys) for sample in trace.cpu_stats], \
-			    proc_tree, None)
-
-	curr_y = curr_y + 30 + bar_h
+	if trace.cpu_stats:
+		ctx.set_font_size(LEGEND_FONT_SIZE)
+
+		draw_legend_box(ctx, "CPU (user+sys)", CPU_COLOR, off_x, curr_y+20, leg_s)
+		draw_legend_box(ctx, "I/O (wait)", IO_COLOR, off_x + 120, curr_y+20, leg_s)
+
+		# render I/O wait
+		chart_rect = (off_x, curr_y+30, w, bar_h)
+		if clip_visible (clip, chart_rect):
+			draw_box_ticks (ctx, chart_rect, sec_w)
+			draw_annotations (ctx, proc_tree, trace.times, chart_rect)
+			draw_chart (ctx, IO_COLOR, True, chart_rect, \
+				    [(sample.time, sample.user + sample.sys + sample.io) for sample in trace.cpu_stats], \
+				    proc_tree, None)
+			# render CPU load
+			draw_chart (ctx, CPU_COLOR, True, chart_rect, \
+				    [(sample.time, sample.user + sample.sys) for sample in trace.cpu_stats], \
+				    proc_tree, None)
+
+		curr_y = curr_y + 30 + bar_h
 
 	# render second chart
-	draw_legend_line(ctx, "Disk throughput", DISK_TPUT_COLOR, off_x, curr_y+20, leg_s)
-	draw_legend_box(ctx, "Disk utilization", IO_COLOR, off_x + 120, curr_y+20, leg_s)
-
-        # render I/O utilization
-	chart_rect = (off_x, curr_y+30, w, bar_h)
-	if clip_visible (clip, chart_rect):
-		draw_box_ticks (ctx, chart_rect, sec_w)
-		draw_annotations (ctx, proc_tree, trace.times, chart_rect)
-		draw_chart (ctx, IO_COLOR, True, chart_rect, \
-			    [(sample.time, sample.util) for sample in trace.disk_stats], \
-			    proc_tree, None)
-
-	# render disk throughput
-	max_sample = max (trace.disk_stats, key = lambda s: s.tput)
-	if clip_visible (clip, chart_rect):
-		draw_chart (ctx, DISK_TPUT_COLOR, False, chart_rect, \
-			    [(sample.time, sample.tput) for sample in trace.disk_stats], \
-			    proc_tree, None)
-
-	pos_x = off_x + ((max_sample.time - proc_tree.start_time) * w / proc_tree.duration)
-
-	shift_x, shift_y = -20, 20
-	if (pos_x < off_x + 245):
-		shift_x, shift_y = 5, 40
-
-	label = "%dMB/s" % round ((max_sample.tput) / 1024.0)
-	draw_text (ctx, label, DISK_TPUT_COLOR, pos_x + shift_x, curr_y + shift_y)
-
-	curr_y = curr_y + 30 + bar_h
+	if trace.disk_stats:
+		draw_legend_line(ctx, "Disk throughput", DISK_TPUT_COLOR, off_x, curr_y+20, leg_s)
+		draw_legend_box(ctx, "Disk utilization", IO_COLOR, off_x + 120, curr_y+20, leg_s)
+
+		# render I/O utilization
+		chart_rect = (off_x, curr_y+30, w, bar_h)
+		if clip_visible (clip, chart_rect):
+			draw_box_ticks (ctx, chart_rect, sec_w)
+			draw_annotations (ctx, proc_tree, trace.times, chart_rect)
+			draw_chart (ctx, IO_COLOR, True, chart_rect, \
+				    [(sample.time, sample.util) for sample in trace.disk_stats], \
+				    proc_tree, None)
+
+		# render disk throughput
+		max_sample = max (trace.disk_stats, key = lambda s: s.tput)
+		if clip_visible (clip, chart_rect):
+			draw_chart (ctx, DISK_TPUT_COLOR, False, chart_rect, \
+				    [(sample.time, sample.tput) for sample in trace.disk_stats], \
+				    proc_tree, None)
+
+		pos_x = off_x + ((max_sample.time - proc_tree.start_time) * w / proc_tree.duration)
+
+		shift_x, shift_y = -20, 20
+		if (pos_x < off_x + 245):
+			shift_x, shift_y = 5, 40
+
+		label = "%dMB/s" % round ((max_sample.tput) / 1024.0)
+		draw_text (ctx, label, DISK_TPUT_COLOR, pos_x + shift_x, curr_y + shift_y)
+
+		curr_y = curr_y + 30 + bar_h
 
 	# render mem usage
 	chart_rect = (off_x, curr_y+30, w, meminfo_bar_h)
-- 
2.1.4

[PATCH 06/11] buildstats: record disk space usage

[Patrick Ohly]

Hooks into the new monitordisk.py event and records the used space for
each volume. That is probably the only relevant value when it comes to
visualizing the build and recording more would only increase disk
usage.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 meta/classes/buildstats.bbclass |  4 ++--
 meta/lib/buildstats.py          | 22 +++++++++++++++++-----
 2 files changed, 19 insertions(+), 7 deletions(-)

diff --git a/meta/classes/buildstats.bbclass b/meta/classes/buildstats.bbclass
index 2abc1a7..113a246 100644
--- a/meta/classes/buildstats.bbclass
+++ b/meta/classes/buildstats.bbclass
@@ -199,8 +199,8 @@ python runqueue_stats () {
     system_stats = buildstats.get_system_stats(d, init=init)
     if system_stats:
         # Ensure that we sample at important events.
-        system_stats.sample(force=isinstance(e, bb.event.BuildCompleted))
+        system_stats.sample(e, force=isinstance(e, bb.event.BuildCompleted))
 }
 
 addhandler runqueue_stats
-runqueue_stats[eventmask] = "bb.runqueue.runQueueTaskStarted bb.event.HeartbeatEvent bb.event.BuildCompleted"
+runqueue_stats[eventmask] = "bb.runqueue.runQueueTaskStarted bb.event.HeartbeatEvent bb.event.BuildCompleted bb.event.MonitorDiskEvent"
diff --git a/meta/lib/buildstats.py b/meta/lib/buildstats.py
index 1664c52..2499fb1 100644
--- a/meta/lib/buildstats.py
+++ b/meta/lib/buildstats.py
@@ -3,6 +3,7 @@
 # like open log files and the time of the last sampling.
 
 import time
+import bb.event
 
 class SystemStats:
     def __init__(self, d):
@@ -19,17 +20,19 @@ class SystemStats:
             # concurrently.
             self.proc_files.append((filename,
                                     open(os.path.join(bsdir, 'proc_%s.log' % filename), 'ab')))
-        # Last time that we sampled data.
-        self.last = 0
+        self.monitor_disk = open(os.path.join(bsdir, 'monitor_disk.log'), 'ab')
+        # Last time that we sampled /proc data resp. recorded disk monitoring data.
+        self.last_proc = 0
+        self.last_disk_monitor = 0
         # Minimum number of seconds between recording a sample. This
         # becames relevant when we get called very often while many
         # short tasks get started. Sampling during quiet periods
         # depends on the heartbeat event, which fires less often.
         self.min_seconds = 1
 
-    def sample(self, force):
+    def sample(self, event, force):
         now = time.time()
-        if (now - self.last > self.min_seconds) or force:
+        if (now - self.last_proc > self.min_seconds) or force:
             for filename, output in self.proc_files:
                 with open(os.path.join('/proc', filename), 'rb') as input:
                     data = input.read()
@@ -39,7 +42,16 @@ class SystemStats:
                              ('%.0f\n' % now).encode('ascii') +
                              data +
                              b'\n')
-            self.last = now
+            self.last_proc = now
+
+        if isinstance(event, bb.event.MonitorDiskEvent) and \
+           ((now - self.last_disk_monitor > self.min_seconds) or force):
+            os.write(self.monitor_disk.fileno(),
+                     ('%.0f\n' % now).encode('ascii') +
+                     ''.join(['%s: %d\n' % (dev, sample.total_bytes - sample.free_bytes)
+                              for dev, sample in event.disk_usage.items()]).encode('ascii') +
+                     b'\n')
+            self.last_disk_monitor = now
 
 _system_stats = None
 
-- 
2.1.4

[PATCH 07/11] pybootchartgui/parsing.py: fix error handling in meminfo parser

[Patrick Ohly]

When matching fails, m.group(0) is invalid and can't be used in the
error message.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 scripts/pybootchartgui/pybootchartgui/parsing.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/pybootchartgui/pybootchartgui/parsing.py b/scripts/pybootchartgui/pybootchartgui/parsing.py
index af68435..48eb048 100644
--- a/scripts/pybootchartgui/pybootchartgui/parsing.py
+++ b/scripts/pybootchartgui/pybootchartgui/parsing.py
@@ -498,7 +498,7 @@ def _parse_proc_meminfo_log(file):
         for line in lines:
             match = meminfo_re.match(line)
             if not match:
-                raise ParseError("Invalid meminfo line \"%s\"" % match.groups(0))
+                raise ParseError("Invalid meminfo line \"%s\"" % line)
             sample.add_value(match.group(1), int(match.group(2)))
 
         if sample.valid():
-- 
2.1.4

[PATCH 08/11] pybootchartgui: render disk space usage

[Patrick Ohly]

This adds a new, separate chart showing the amount of disk space used
over time for each volume monitored during the build. The hight of the
graph entries represents the delta between current usage and minimal
usage during the build.

That's more useful than showing just the current usage, because then a
graph showing changes in the order of MBs in a volume that is several
GB large would be just flat.

The legend shows the maximum of those deltas, i.e. maximum amount of
space needed for the build. Minor caveat: sampling of disk space usage
starts a bit later than the initial task, so the displayed value may
be slightly lower than the actual amount of space needed because
sampling does not record the actual initial state.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 scripts/pybootchartgui/pybootchartgui/draw.py    | 62 ++++++++++++++++++++++++
 scripts/pybootchartgui/pybootchartgui/parsing.py | 26 ++++++++++
 scripts/pybootchartgui/pybootchartgui/samples.py | 11 +++++
 3 files changed, 99 insertions(+)

diff --git a/scripts/pybootchartgui/pybootchartgui/draw.py b/scripts/pybootchartgui/pybootchartgui/draw.py
index ec5dd33..f0143ad 100644
--- a/scripts/pybootchartgui/pybootchartgui/draw.py
+++ b/scripts/pybootchartgui/pybootchartgui/draw.py
@@ -133,6 +133,16 @@ TASK_COLOR_PACKAGE = (0.0, 1.00, 1.00, 1.0)
 # Package Write RPM/DEB/IPK task color
 TASK_COLOR_PACKAGE_WRITE = (0.0, 0.50, 0.50, 1.0)
 
+# Distinct colors used for different disk volumnes.
+# If we have more volumns, colors get re-used.
+VOLUME_COLORS = [
+	(1.0, 1.0, 0.00, 1.0),
+	(0.0, 1.00, 0.00, 1.0),
+	(1.0, 0.00, 1.00, 1.0),
+	(0.0, 0.00, 1.00, 1.0),
+	(0.0, 1.00, 1.00, 1.0),
+]
+
 # Process states
 STATE_UNDEFINED = 0
 STATE_RUNNING   = 1
@@ -397,6 +407,58 @@ def render_charts(ctx, options, clip, trace, curr_y, w, h, sec_w):
 
 		curr_y = curr_y + 30 + bar_h
 
+	# render disk space usage
+	#
+	# Draws the amount of disk space used on each volume relative to the
+	# lowest recorded amount. The graphs for each volume are stacked above
+	# each other so that total disk usage is visible.
+	if trace.monitor_disk:
+		ctx.set_font_size(LEGEND_FONT_SIZE)
+		# Determine set of volumes for which we have
+		# information and the minimal amount of used disk
+		# space for each. Currently samples are allowed to
+		# not have a values for all volumes; drawing could be
+		# made more efficient if that wasn't the case.
+		volumes = set()
+		min_used = {}
+		for sample in trace.monitor_disk:
+			for volume, used in sample.records.items():
+				volumes.add(volume)
+				if volume not in min_used or min_used[volume] > used:
+					min_used[volume] = used
+		volumes = sorted(list(volumes))
+		disk_scale = 0
+		for i, volume in enumerate(volumes):
+			volume_scale = max([sample.records[volume] - min_used[volume]
+			                    for sample in trace.monitor_disk
+			                    if volume in sample.records])
+			# Does not take length of volume name into account, but fixed offset
+			# works okay in practice.
+			draw_legend_box(ctx, '%s (max: %u MiB)' % (volume, volume_scale / 1024 / 1024),
+			                VOLUME_COLORS[i % len(VOLUME_COLORS)],
+			                off_x + i * 250, curr_y+20, leg_s)
+			disk_scale += volume_scale
+
+		# render used amount of disk space
+		chart_rect = (off_x, curr_y+30, w, bar_h)
+		if clip_visible (clip, chart_rect):
+			draw_box_ticks (ctx, chart_rect, sec_w)
+			draw_annotations (ctx, proc_tree, trace.times, chart_rect)
+			for i in range(len(volumes), 0, -1):
+				draw_chart (ctx, VOLUME_COLORS[(i - 1) % len(VOLUME_COLORS)], True, chart_rect, \
+				            [(sample.time,
+				              # Sum up used space of all volumes including the current one
+				              # so that the graphs appear as stacked on top of each other.
+				              reduce(lambda x,y: x+y,
+				                     [sample.records[volume] - min_used[volume]
+				                      for volume in volumes[0:i]
+				                      if volume in sample.records],
+				                     0))
+				             for sample in trace.monitor_disk], \
+				            proc_tree, [0, disk_scale])
+
+		curr_y = curr_y + 30 + bar_h
+
 	# render mem usage
 	chart_rect = (off_x, curr_y+30, w, meminfo_bar_h)
 	mem_stats = trace.mem_stats
diff --git a/scripts/pybootchartgui/pybootchartgui/parsing.py b/scripts/pybootchartgui/pybootchartgui/parsing.py
index 48eb048..301145a 100644
--- a/scripts/pybootchartgui/pybootchartgui/parsing.py
+++ b/scripts/pybootchartgui/pybootchartgui/parsing.py
@@ -48,6 +48,7 @@ class Trace:
         self.filename = None
         self.parent_map = None
         self.mem_stats = []
+        self.monitor_disk = None
         self.times = [] # Always empty, but expected by draw.py when drawing system charts.
 
         if len(paths):
@@ -506,6 +507,29 @@ def _parse_proc_meminfo_log(file):
 
     return mem_stats
 
+def _parse_monitor_disk_log(file):
+    """
+    Parse file with information about amount of diskspace used.
+    The format of relevant lines should be: ^volume path: number-of-bytes?
+    """
+    disk_stats = []
+    diskinfo_re = re.compile(r'^(.+):\s*(\d+)$')
+
+    for time, lines in _parse_timed_blocks(file):
+        sample = DiskSpaceSample(time)
+
+        for line in lines:
+            match = diskinfo_re.match(line)
+            if not match:
+                raise ParseError("Invalid monitor_disk line \"%s\"" % line)
+            sample.add_value(match.group(1), int(match.group(2)))
+
+        if sample.valid():
+            disk_stats.append(sample)
+
+    return disk_stats
+
+
 # if we boot the kernel with: initcall_debug printk.time=1 we can
 # get all manner of interesting data from the dmesg output
 # We turn this into a pseudo-process tree: each event is
@@ -684,6 +708,8 @@ def _do_parse(writer, state, filename, file):
         state.mem_stats = _parse_proc_meminfo_log(file)
     elif name == "cmdline2.log":
         state.cmdline = _parse_cmdline_log(writer, file)
+    elif name == "monitor_disk.log":
+        state.monitor_disk = _parse_monitor_disk_log(file)
     elif not filename.endswith('.log'):
         _parse_bitbake_buildstats(writer, state, filename, file)
     t2 = clock()
diff --git a/scripts/pybootchartgui/pybootchartgui/samples.py b/scripts/pybootchartgui/pybootchartgui/samples.py
index 015d743..bedca41 100644
--- a/scripts/pybootchartgui/pybootchartgui/samples.py
+++ b/scripts/pybootchartgui/pybootchartgui/samples.py
@@ -53,6 +53,17 @@ class MemSample:
         # discard incomplete samples
         return [v for v in MemSample.used_values if v not in keys] == []
 
+class DiskSpaceSample:
+    def __init__(self, time):
+        self.time = time
+        self.records = {}
+
+    def add_value(self, name, value):
+        self.records[name] = value
+
+    def valid(self):
+        return bool(self.records)
+
 class ProcessSample:
     def __init__(self, time, state, cpu_sample):
         self.time = time
-- 
2.1.4

[PATCH 09/11] pybootchartgui: simplify drawing of memory usage

[Patrick Ohly]

The internal representation after parsing now matches exactly
what the drawing code needs, thus speeding up drawing a bit.
However, the main motivation is to store exactly that required
information in a more compact file.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 scripts/pybootchartgui/pybootchartgui/draw.py    | 12 ++++++------
 scripts/pybootchartgui/pybootchartgui/parsing.py |  2 +-
 scripts/pybootchartgui/pybootchartgui/samples.py | 16 ++++++++++++++++
 3 files changed, 23 insertions(+), 7 deletions(-)

diff --git a/scripts/pybootchartgui/pybootchartgui/draw.py b/scripts/pybootchartgui/pybootchartgui/draw.py
index f0143ad..201ce45 100644
--- a/scripts/pybootchartgui/pybootchartgui/draw.py
+++ b/scripts/pybootchartgui/pybootchartgui/draw.py
@@ -463,25 +463,25 @@ def render_charts(ctx, options, clip, trace, curr_y, w, h, sec_w):
 	chart_rect = (off_x, curr_y+30, w, meminfo_bar_h)
 	mem_stats = trace.mem_stats
 	if mem_stats and clip_visible (clip, chart_rect):
-		mem_scale = max(sample.records['MemTotal'] - sample.records['MemFree'] for sample in mem_stats)
+		mem_scale = max(sample.buffers for sample in mem_stats)
 		draw_legend_box(ctx, "Mem cached (scale: %u MiB)" % (float(mem_scale) / 1024), MEM_CACHED_COLOR, off_x, curr_y+20, leg_s)
 		draw_legend_box(ctx, "Used", MEM_USED_COLOR, off_x + 240, curr_y+20, leg_s)
 		draw_legend_box(ctx, "Buffers", MEM_BUFFERS_COLOR, off_x + 360, curr_y+20, leg_s)
-		draw_legend_line(ctx, "Swap (scale: %u MiB)" % max([(sample.records['SwapTotal'] - sample.records['SwapFree'])/1024 for sample in mem_stats]), \
+		draw_legend_line(ctx, "Swap (scale: %u MiB)" % max([(sample.swap)/1024 for sample in mem_stats]), \
 				 MEM_SWAP_COLOR, off_x + 480, curr_y+20, leg_s)
 		draw_box_ticks(ctx, chart_rect, sec_w)
 		draw_annotations(ctx, proc_tree, trace.times, chart_rect)
 		draw_chart(ctx, MEM_BUFFERS_COLOR, True, chart_rect, \
-			   [(sample.time, sample.records['MemTotal'] - sample.records['MemFree']) for sample in trace.mem_stats], \
+			   [(sample.time, sample.buffers) for sample in trace.mem_stats], \
 			   proc_tree, [0, mem_scale])
 		draw_chart(ctx, MEM_USED_COLOR, True, chart_rect, \
-			   [(sample.time, sample.records['MemTotal'] - sample.records['MemFree'] - sample.records['Buffers']) for sample in mem_stats], \
+			   [(sample.time, sample.used) for sample in mem_stats], \
 			   proc_tree, [0, mem_scale])
 		draw_chart(ctx, MEM_CACHED_COLOR, True, chart_rect, \
-			   [(sample.time, sample.records['Cached']) for sample in mem_stats], \
+			   [(sample.time, sample.cached) for sample in mem_stats], \
 			   proc_tree, [0, mem_scale])
 		draw_chart(ctx, MEM_SWAP_COLOR, False, chart_rect, \
-			   [(sample.time, float(sample.records['SwapTotal'] - sample.records['SwapFree'])) for sample in mem_stats], \
+			   [(sample.time, float(sample.swap)) for sample in mem_stats], \
 			   proc_tree, None)
 
 		curr_y = curr_y + meminfo_bar_h
diff --git a/scripts/pybootchartgui/pybootchartgui/parsing.py b/scripts/pybootchartgui/pybootchartgui/parsing.py
index 301145a..1c8d8ef 100644
--- a/scripts/pybootchartgui/pybootchartgui/parsing.py
+++ b/scripts/pybootchartgui/pybootchartgui/parsing.py
@@ -503,7 +503,7 @@ def _parse_proc_meminfo_log(file):
             sample.add_value(match.group(1), int(match.group(2)))
 
         if sample.valid():
-            mem_stats.append(sample)
+            mem_stats.append(DrawMemSample(sample))
 
     return mem_stats
 
diff --git a/scripts/pybootchartgui/pybootchartgui/samples.py b/scripts/pybootchartgui/pybootchartgui/samples.py
index bedca41..9fc309b 100644
--- a/scripts/pybootchartgui/pybootchartgui/samples.py
+++ b/scripts/pybootchartgui/pybootchartgui/samples.py
@@ -53,6 +53,22 @@ class MemSample:
         # discard incomplete samples
         return [v for v in MemSample.used_values if v not in keys] == []
 
+class DrawMemSample:
+    """
+    Condensed version of a MemSample with exactly the values used by the drawing code.
+    Initialized either from a valid MemSample or
+    a tuple/list of buffer/used/cached/swap values.
+    """
+    def __init__(self, mem_sample):
+        self.time = mem_sample.time
+        if isinstance(mem_sample, MemSample):
+            self.buffers = mem_sample.records['MemTotal'] - mem_sample.records['MemFree']
+            self.used = mem_sample.records['MemTotal'] - mem_sample.records['MemFree'] - mem_sample.records['Buffers']
+            self.cached = mem_sample.records['Cached']
+            self.swap = mem_sample.records['SwapTotal'] - mem_sample.records['SwapFree']
+        else:
+            self.buffers, self.used, self.cached, self.swap = mem_sample
+
 class DiskSpaceSample:
     def __init__(self, time):
         self.time = time
-- 
2.1.4

[PATCH 10/11] buildstats: reduce amount of data stored for system utilization

[Patrick Ohly]

Pre-processing /proc data during the build considerably reduces the
amount of data written to disk: 176KB instead of 4.7MB for a 20
minuted build. Parsing also becomes faster.

The disk monitor log added another 16KB in that example build. The
overall buildstat was 20MB, so the overhead for monitoring system
utilization is small enough that it can be enabled by default.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 meta/lib/buildstats.py | 114 ++++++++++++++++++++++++++++++++++++++++++++-----
 1 file changed, 104 insertions(+), 10 deletions(-)

diff --git a/meta/lib/buildstats.py b/meta/lib/buildstats.py
index 2499fb1..3cd333c 100644
--- a/meta/lib/buildstats.py
+++ b/meta/lib/buildstats.py
@@ -3,6 +3,7 @@
 # like open log files and the time of the last sampling.
 
 import time
+import re
 import bb.event
 
 class SystemStats:
@@ -12,14 +13,18 @@ class SystemStats:
         bb.utils.mkdirhier(bsdir)
 
         self.proc_files = []
-        for filename in ('diskstats', 'meminfo', 'stat'):
+        for filename, handler in (
+                ('diskstats', self._reduce_diskstats),
+                ('meminfo', self._reduce_meminfo),
+                ('stat', self._reduce_stat),
+        ):
             # In practice, this class gets instantiated only once in
             # the bitbake cooker process.  Therefore 'append' mode is
             # not strictly necessary, but using it makes the class
             # more robust should two processes ever write
             # concurrently.
-            self.proc_files.append((filename,
-                                    open(os.path.join(bsdir, 'proc_%s.log' % filename), 'ab')))
+            destfile = os.path.join(bsdir, '%sproc_%s.log' % ('reduced_' if handler else '', filename))
+            self.proc_files.append((filename, open(destfile, 'ab'), handler))
         self.monitor_disk = open(os.path.join(bsdir, 'monitor_disk.log'), 'ab')
         # Last time that we sampled /proc data resp. recorded disk monitoring data.
         self.last_proc = 0
@@ -30,18 +35,107 @@ class SystemStats:
         # depends on the heartbeat event, which fires less often.
         self.min_seconds = 1
 
+        self.meminfo_regex = re.compile(b'^(MemTotal|MemFree|Buffers|Cached|SwapTotal|SwapFree):\s*(\d+)')
+        self.diskstats_regex = re.compile(b'^([hsv]d.|mtdblock\d|mmcblk\d|cciss/c\d+d\d+.*)$')
+        self.diskstats_ltime = None
+        self.diskstats_data = None
+        self.stat_ltimes = None
+
+    def _reduce_meminfo(self, time, data):
+        """
+        Extracts 'MemTotal', 'MemFree', 'Buffers', 'Cached', 'SwapTotal', 'SwapFree'
+        and writes their values into a single line, in that order.
+        """
+        values = {}
+        for line in data.split(b'\n'):
+            m = self.meminfo_regex.match(line)
+            if m:
+                values[m.group(1)] = m.group(2)
+        if len(values) == 6:
+            return (time,
+                    b' '.join([values[x] for x in
+                               (b'MemTotal', b'MemFree', b'Buffers', b'Cached', b'SwapTotal', b'SwapFree')]) + b'\n')
+
+    def _diskstats_is_relevant_line(self, linetokens):
+        if len(linetokens) != 14:
+            return False
+        disk = linetokens[2]
+        return self.diskstats_regex.match(disk)
+
+    def _reduce_diskstats(self, time, data):
+        relevant_tokens = filter(self._diskstats_is_relevant_line, map(lambda x: x.split(), data.split(b'\n')))
+        diskdata = [0] * 3
+        reduced = None
+        for tokens in relevant_tokens:
+            # rsect
+            diskdata[0] += int(tokens[5])
+            # wsect
+            diskdata[1] += int(tokens[9])
+            # use
+            diskdata[2] += int(tokens[12])
+        if self.diskstats_ltime:
+            # We need to compute information about the time interval
+            # since the last sampling and record the result as sample
+            # for that point in the past.
+            interval = time - self.diskstats_ltime
+            if interval > 0:
+                sums = [ a - b for a, b in zip(diskdata, self.diskstats_data) ]
+                readTput = sums[0] / 2.0 * 100.0 / interval
+                writeTput = sums[1] / 2.0 * 100.0 / interval
+                util = float( sums[2] ) / 10 / interval
+                util = max(0.0, min(1.0, util))
+                reduced = (self.diskstats_ltime, (readTput, writeTput, util))
+
+        self.diskstats_ltime = time
+        self.diskstats_data = diskdata
+        return reduced
+
+
+    def _reduce_nop(self, time, data):
+        return (time, data)
+
+    def _reduce_stat(self, time, data):
+        if not data:
+            return None
+        # CPU times {user, nice, system, idle, io_wait, irq, softirq} from first line
+        tokens = data.split(b'\n', 1)[0].split()
+        times = [ int(token) for token in tokens[1:] ]
+        reduced = None
+        if self.stat_ltimes:
+            user = float((times[0] + times[1]) - (self.stat_ltimes[0] + self.stat_ltimes[1]))
+            system = float((times[2] + times[5] + times[6]) - (self.stat_ltimes[2] + self.stat_ltimes[5] + self.stat_ltimes[6]))
+            idle = float(times[3] - self.stat_ltimes[3])
+            iowait = float(times[4] - self.stat_ltimes[4])
+
+            aSum = max(user + system + idle + iowait, 1)
+            reduced = (time, (user/aSum, system/aSum, iowait/aSum))
+
+        self.stat_ltimes = times
+        return reduced
+
     def sample(self, event, force):
         now = time.time()
         if (now - self.last_proc > self.min_seconds) or force:
-            for filename, output in self.proc_files:
+            for filename, output, handler in self.proc_files:
                 with open(os.path.join('/proc', filename), 'rb') as input:
                     data = input.read()
-                    # Unbuffered raw write, less overhead and useful
-                    # in case that we end up with concurrent writes.
-                    os.write(output.fileno(),
-                             ('%.0f\n' % now).encode('ascii') +
-                             data +
-                             b'\n')
+                    if handler:
+                        reduced = handler(now, data)
+                    else:
+                        reduced = (now, data)
+                    if reduced:
+                        if isinstance(reduced[1], bytes):
+                            # Use as it is.
+                            data = reduced[1]
+                        else:
+                            # Convert to a single line.
+                            data = (' '.join([str(x) for x in reduced[1]]) + '\n').encode('ascii')
+                        # Unbuffered raw write, less overhead and useful
+                        # in case that we end up with concurrent writes.
+                        os.write(output.fileno(),
+                                 ('%.0f\n' % reduced[0]).encode('ascii') +
+                                 data +
+                                 b'\n')
             self.last_proc = now
 
         if isinstance(event, bb.event.MonitorDiskEvent) and \
-- 
2.1.4

[PATCH 11/11] pybootchartgui: support reading reduced /proc logs

[Patrick Ohly]

Pre-processing /proc data during the build considerably reduces the
amount of data written to disk: 176KB instead of 4.7MB for a 20
minuted build. Parsing also becomes faster.

buildstats.bbclass only writes the reduced logs now, but support for
the full /proc files is kept around as reference.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>
---
 scripts/pybootchartgui/pybootchartgui/parsing.py | 31 ++++++++++++++++++++++++
 1 file changed, 31 insertions(+)

diff --git a/scripts/pybootchartgui/pybootchartgui/parsing.py b/scripts/pybootchartgui/pybootchartgui/parsing.py
index 1c8d8ef..bcfb2da 100644
--- a/scripts/pybootchartgui/pybootchartgui/parsing.py
+++ b/scripts/pybootchartgui/pybootchartgui/parsing.py
@@ -442,6 +442,12 @@ def _parse_proc_stat_log(file):
         # skip the rest of statistics lines
     return samples
 
+def _parse_reduced_log(file, sample_class):
+    samples = []
+    for time, lines in _parse_timed_blocks(file):
+        samples.append(sample_class(time, *[float(x) for x in lines[0].split()]))
+    return samples
+
 def _parse_proc_disk_stat_log(file):
     """
     Parse file for disk stats, but only look at the whole device, eg. sda,
@@ -483,6 +489,25 @@ def _parse_proc_disk_stat_log(file):
 
     return disk_stats
 
+def _parse_reduced_proc_meminfo_log(file):
+    """
+    Parse file for global memory statistics with
+    'MemTotal', 'MemFree', 'Buffers', 'Cached', 'SwapTotal', 'SwapFree' values
+    (in that order) directly stored on one line.
+    """
+    used_values = ('MemTotal', 'MemFree', 'Buffers', 'Cached', 'SwapTotal', 'SwapFree',)
+
+    mem_stats = []
+    for time, lines in _parse_timed_blocks(file):
+        sample = MemSample(time)
+        for name, value in zip(used_values, lines[0].split()):
+            sample.add_value(name, int(value))
+
+        if sample.valid():
+            mem_stats.append(DrawMemSample(sample))
+
+    return mem_stats
+
 def _parse_proc_meminfo_log(file):
     """
     Parse file for global memory statistics.
@@ -702,10 +727,16 @@ def _do_parse(writer, state, filename, file):
     name = os.path.basename(filename)
     if name == "proc_diskstats.log":
         state.disk_stats = _parse_proc_disk_stat_log(file)
+    elif name == "reduced_proc_diskstats.log":
+        state.disk_stats = _parse_reduced_log(file, DiskSample)
     elif name == "proc_stat.log":
         state.cpu_stats = _parse_proc_stat_log(file)
+    elif name == "reduced_proc_stat.log":
+        state.cpu_stats = _parse_reduced_log(file, CPUSample)
     elif name == "proc_meminfo.log":
         state.mem_stats = _parse_proc_meminfo_log(file)
+    elif name == "reduced_proc_meminfo.log":
+        state.mem_stats = _parse_reduced_proc_meminfo_log(file)
     elif name == "cmdline2.log":
         state.cmdline = _parse_cmdline_log(writer, file)
     elif name == "monitor_disk.log":
-- 
2.1.4