[PATCH 0/5] Fix task buildstats gathering

[PATCH 0/5] Fix task buildstats gathering

[Elliot Smith]

Our buildstats gathering for tasks (CPU usage, Disk IO etc.) is broken, partly because of changes to how the data is organised in the buildstats files, and partly because tasks aren't being updated correctly anyway.

Clean up the code which collects the buildstats (it had lots of duplication), collect the stats from the new stat file format (some line leaders had changed), and correctly identify the Task objects to update in BuildInfoHelper.

To test:

1. Remove the content of the directories which cache tasks to see the best effects (I usually delete buildstats, tmp, sstate-cache, and cache, just to be safe).

2. Run a build against a local Yocto (as one patch is for toaster.bbclass).

3. When the build finishes, view the "Tasks" page for the build and enable the "Disk IO" and "CPU usage" columns. Note that some CPU usage percentages are > 100, as discussed in bug 8842.

Changes since c0fe43b (toaster-next) are in
git://git.yoctoproject.org/poky-contrib, elliot/toaster/build_data-8842
http://git.yoctoproject.org/cgit.cgi/poky-contrib/log/?h=elliot/toaster/build_data-8842

Related bug: https://bugzilla.yoctoproject.org/show_bug.cgi?id=8842

NOTE: The first commit in this patch series is for oe-core.

Elliot Smith (5):
  toaster.bbclass: improve how we gather buildstats for Toaster
  toaster: elapsed time for a task is calculated in toaster.bbclass
  toaster: when updating task stats, task must exist
  toaster: use a more straightforward query to find tasks to update
  toaster: clarify the units used for buildstats

 bitbake/lib/bb/ui/buildinfohelper.py    | 49 +++++++--------------
 bitbake/lib/toaster/orm/models.py       |  7 +++
 bitbake/lib/toaster/toastergui/views.py |  4 +-
 meta/classes/toaster.bbclass            | 76 ++++++++++++++++++++++-----------
 4 files changed, 77 insertions(+), 59 deletions(-)

--
Elliot Smith
Software Engineer
Intel OTC

---------------------------------------------------------------------
Intel Corporation (UK) Limited
Registered No. 1134945 (England)
Registered Office: Pipers Way, Swindon SN3 1RJ
VAT No: 860 2173 47

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

[PATCH 1/5] toaster.bbclass: improve how we gather buildstats for Toaster

[Elliot Smith]

Clean up the code which gathers buildstats for Toaster,
and modify the field names so that the correct parts of the
buildstats files are used to derive the CPU usage percentages.

Also derive elapsed time for the build here, rather than in
Toaster, as we have ready access to the data in the correct
format.

[YOCTO #8842]

Signed-off-by: Elliot Smith <elliot.smith@intel.com>
---
 meta/classes/toaster.bbclass | 76 ++++++++++++++++++++++++++++++--------------
 1 file changed, 52 insertions(+), 24 deletions(-)

diff --git a/meta/classes/toaster.bbclass b/meta/classes/toaster.bbclass
index 51a4c74..280e901 100644
--- a/meta/classes/toaster.bbclass
+++ b/meta/classes/toaster.bbclass
@@ -202,25 +202,39 @@ python toaster_collect_task_stats() {
     import bb.utils
     import os
 
+    toaster_statlist_file = os.path.join(e.data.getVar('BUILDSTATS_BASE', True), "toasterstatlist")
+
     if not e.data.getVar('BUILDSTATS_BASE', True):
         return  # if we don't have buildstats, we cannot collect stats
 
+    def stat_to_float(value):
+        return float(value.strip('% \n\r'))
+
     def _append_read_list(v):
         lock = bb.utils.lockfile(e.data.expand("${TOPDIR}/toaster.lock"), False, True)
 
-        with open(os.path.join(e.data.getVar('BUILDSTATS_BASE', True), "toasterstatlist"), "a") as fout:
+        with open(toaster_statlist_file, "a") as fout:
             taskdir = e.data.expand("${BUILDSTATS_BASE}/${BUILDNAME}/${PF}")
             fout.write("%s::%s::%s::%s\n" % (e.taskfile, e.taskname, os.path.join(taskdir, e.task), e.data.expand("${PN}")))
 
         bb.utils.unlockfile(lock)
 
     def _read_stats(filename):
-        cpu_usage = 0
-        disk_io = 0
-        started = '0'
-        ended = '0'
-        pn = ''
+        cpu_time = 0
+        cpu_usage_percent = 0
+
+        # bytes
+        disk_io_read = 0
+        disk_io_write = 0
+
+        started = 0
+        ended = 0
+
+        # seconds
+        elapsed_time = 0
+
         taskname = ''
+
         statinfo = {}
 
         with open(filename, 'r') as task_bs:
@@ -228,41 +242,55 @@ python toaster_collect_task_stats() {
                 k,v = line.strip().split(": ", 1)
                 statinfo[k] = v
 
-        if "CPU usage" in statinfo:
-            cpu_usage = str(statinfo["CPU usage"]).strip('% \n\r')
+        if "Started" in statinfo:
+            started = stat_to_float(statinfo["Started"])
 
-        if "IO write_bytes" in statinfo:
-            disk_io = disk_io + int(statinfo["IO write_bytes"].strip('% \n\r'))
+        if "Ended" in statinfo:
+            ended = stat_to_float(statinfo["Ended"])
 
-        if "IO read_bytes" in statinfo:
-            disk_io = disk_io + int(statinfo["IO read_bytes"].strip('% \n\r'))
+        if "Child rusage ru_utime" in statinfo:
+            cpu_time = cpu_time + stat_to_float(statinfo["Child rusage ru_utime"])
 
-        if "Started" in statinfo:
-            started = str(statinfo["Started"]).strip('% \n\r')
+        if "Child rusage ru_stime" in statinfo:
+            cpu_time = cpu_time + stat_to_float(statinfo["Child rusage ru_stime"])
 
-        if "Ended" in statinfo:
-            ended = str(statinfo["Ended"]).strip('% \n\r')
+        if "IO write_bytes" in statinfo:
+            write_bytes = int(statinfo["IO write_bytes"].strip('% \n\r'))
+            disk_io_write = disk_io_write + write_bytes
+
+        if "IO read_bytes" in statinfo:
+            read_bytes = int(statinfo["IO read_bytes"].strip('% \n\r'))
+            disk_io_read = disk_io_read + read_bytes
 
-        elapsed_time = float(ended) - float(started)
+        elapsed_time = ended - started
 
-        cpu_usage = float(cpu_usage)
+        if elapsed_time > 0:
+            cpu_usage_percent = (cpu_time / elapsed_time) * 100
 
-        return {'cpu_usage': cpu_usage, 'disk_io': disk_io, 'elapsed_time': elapsed_time}
+        disk_io = disk_io_read + disk_io_write
 
+        return {
+            'stat_file': filename,
+            'cpu_usage': cpu_usage_percent,
+            'disk_io': disk_io,
+            'disk_io_read': disk_io_read,
+            'disk_io_write': disk_io_write,
+            'elapsed_time': elapsed_time
+        }
 
     if isinstance(e, (bb.build.TaskSucceeded, bb.build.TaskFailed)):
         _append_read_list(e)
         pass
 
-
-    if isinstance(e, bb.event.BuildCompleted) and os.path.exists(os.path.join(e.data.getVar('BUILDSTATS_BASE', True), "toasterstatlist")):
+    if isinstance(e, bb.event.BuildCompleted) and os.path.exists(toaster_statlist_file):
         events = []
-        with open(os.path.join(e.data.getVar('BUILDSTATS_BASE', True), "toasterstatlist"), "r") as fin:
+        with open(toaster_statlist_file, "r") as fin:
             for line in fin:
                 (taskfile, taskname, filename, recipename) = line.strip().split("::")
-                events.append((taskfile, taskname, _read_stats(filename), recipename))
+                stats = _read_stats(filename)
+                events.append((taskfile, taskname, stats, recipename))
         bb.event.fire(bb.event.MetadataEvent("BuildStatsList", events), e.data)
-        os.unlink(os.path.join(e.data.getVar('BUILDSTATS_BASE', True), "toasterstatlist"))
+        #os.unlink(toaster_statlist_file)
 }
 
 # dump relevant build history data as an event when the build is completed
-- 
Elliot Smith
Software Engineer
Intel OTC

---------------------------------------------------------------------
Intel Corporation (UK) Limited
Registered No. 1134945 (England)
Registered Office: Pipers Way, Swindon SN3 1RJ
VAT No: 860 2173 47

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

[PATCH 2/5] toaster: elapsed time for a task is calculated in toaster.bbclass

[Elliot Smith]

The elapsed time is now calculated in toaster.bbclass, so there's
no need to do it in BuildInfoHelper any more.

[YOCTO #8842]

Signed-off-by: Elliot Smith <elliot.smith@intel.com>
---
 bitbake/lib/bb/ui/buildinfohelper.py | 12 +++---------
 1 file changed, 3 insertions(+), 9 deletions(-)

diff --git a/bitbake/lib/bb/ui/buildinfohelper.py b/bitbake/lib/bb/ui/buildinfohelper.py
index 81abede..2b5d312 100644
--- a/bitbake/lib/bb/ui/buildinfohelper.py
+++ b/bitbake/lib/bb/ui/buildinfohelper.py
@@ -259,14 +259,6 @@ class ORMWrapper(object):
                 task_object.sstate_result = Task.SSTATE_FAILED
                 object_changed = True
 
-        # mark down duration if we have a start time and a current time
-        if 'start_time' in task_information.keys() and 'end_time' in task_information.keys():
-            duration = task_information['end_time'] - task_information['start_time']
-            task_object.elapsed_time = duration
-            object_changed = True
-            del task_information['start_time']
-            del task_information['end_time']
-
         if object_changed:
             task_object.save()
         return task_object
@@ -1091,7 +1083,9 @@ class BuildInfoHelper(object):
 
 
     def store_tasks_stats(self, event):
-        for (taskfile, taskname, taskstats, recipename) in BuildInfoHelper._get_data_from_event(event):
+        task_data = BuildInfoHelper._get_data_from_event(event)
+
+        for (taskfile, taskname, taskstats, recipename) in task_data:
             localfilepath = taskfile.split(":")[-1]
             assert localfilepath.startswith("/")
 
-- 
Elliot Smith
Software Engineer
Intel OTC

---------------------------------------------------------------------
Intel Corporation (UK) Limited
Registered No. 1134945 (England)
Registered Office: Pipers Way, Swindon SN3 1RJ
VAT No: 860 2173 47

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

[PATCH 3/5] toaster: when updating task stats, task must exist

[Elliot Smith]

Ensure that a task exists when we're updating its buildstats.
This is to prevent duplicate tasks being created when
updating buildstats (which is what was happening before,
causing the buildstats to be attached to tasks which weren't
associated with the build).

[YOCTO #8842]

Signed-off-by: Elliot Smith <elliot.smith@intel.com>
---
 bitbake/lib/bb/ui/buildinfohelper.py | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/bitbake/lib/bb/ui/buildinfohelper.py b/bitbake/lib/bb/ui/buildinfohelper.py
index 2b5d312..5f079d1 100644
--- a/bitbake/lib/bb/ui/buildinfohelper.py
+++ b/bitbake/lib/bb/ui/buildinfohelper.py
@@ -1109,7 +1109,8 @@ class BuildInfoHelper(object):
             task_information['disk_io'] = taskstats['disk_io']
             if 'elapsed_time' in taskstats:
                 task_information['elapsed_time'] = taskstats['elapsed_time']
-            self.orm_wrapper.get_update_task_object(task_information)
+
+            self.orm_wrapper.get_update_task_object(task_information, True)
 
     def update_and_store_task(self, event):
         assert 'taskfile' in vars(event)
-- 
Elliot Smith
Software Engineer
Intel OTC

---------------------------------------------------------------------
Intel Corporation (UK) Limited
Registered No. 1134945 (England)
Registered Office: Pipers Way, Swindon SN3 1RJ
VAT No: 860 2173 47

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

[PATCH 4/5] toaster: use a more straightforward query to find tasks to update

[Elliot Smith]

When we get buildstats data for a task (disk IO, CPU usage etc.)
we need to find a task already associated with the build and
amend its properties with values from that data.

The existing code uses an arcane mechanism for locating the task
to be updated, which was actually creating duplicate tasks against
the build. These tasks were then not displaying in the build's "Tasks"
page.

Modify how we locate the task in the build which needs to be updated,
so that we just filter the existing tasks for the build where the
recipe matches the one in the buildstats data.

[YOCTO #8842]

Signed-off-by: Elliot Smith <elliot.smith@intel.com>
---
 bitbake/lib/bb/ui/buildinfohelper.py | 40 +++++++++++++-----------------------
 1 file changed, 14 insertions(+), 26 deletions(-)

diff --git a/bitbake/lib/bb/ui/buildinfohelper.py b/bitbake/lib/bb/ui/buildinfohelper.py
index 5f079d1..89e4a08 100644
--- a/bitbake/lib/bb/ui/buildinfohelper.py
+++ b/bitbake/lib/bb/ui/buildinfohelper.py
@@ -1085,32 +1085,20 @@ class BuildInfoHelper(object):
     def store_tasks_stats(self, event):
         task_data = BuildInfoHelper._get_data_from_event(event)
 
-        for (taskfile, taskname, taskstats, recipename) in task_data:
-            localfilepath = taskfile.split(":")[-1]
-            assert localfilepath.startswith("/")
-
-            recipe_information = self._get_recipe_information_from_taskfile(taskfile)
-            try:
-                if recipe_information['file_path'].startswith(recipe_information['layer_version'].local_path):
-                    recipe_information['file_path'] = recipe_information['file_path'][len(recipe_information['layer_version'].local_path):].lstrip("/")
-
-                recipe_object = Recipe.objects.get(layer_version = recipe_information['layer_version'],
-                            file_path__endswith = recipe_information['file_path'],
-                            name = recipename)
-            except Recipe.DoesNotExist:
-                logger.error("Could not find recipe for recipe_information %s name %s" , pformat(recipe_information), recipename)
-                raise
-
-            task_information = {}
-            task_information['build'] = self.internal_state['build']
-            task_information['recipe'] = recipe_object
-            task_information['task_name'] = taskname
-            task_information['cpu_usage'] = taskstats['cpu_usage']
-            task_information['disk_io'] = taskstats['disk_io']
-            if 'elapsed_time' in taskstats:
-                task_information['elapsed_time'] = taskstats['elapsed_time']
-
-            self.orm_wrapper.get_update_task_object(task_information, True)
+        for (taskfile, task_name, taskstats, recipename) in task_data:
+            # find the task for this build which matches the task information
+            # we're storing
+            task_to_update = Task.objects.get(
+                build = self.internal_state['build'],
+                recipe__name = recipename,
+                task_name = task_name
+            )
+
+            task_to_update.cpu_usage = taskstats['cpu_usage']
+            task_to_update.disk_io = taskstats['disk_io']
+            task_to_update.elapsed_time = taskstats['elapsed_time']
+
+            task_to_update.save()
 
     def update_and_store_task(self, event):
         assert 'taskfile' in vars(event)
-- 
Elliot Smith
Software Engineer
Intel OTC

---------------------------------------------------------------------
Intel Corporation (UK) Limited
Registered No. 1134945 (England)
Registered Office: Pipers Way, Swindon SN3 1RJ
VAT No: 860 2173 47

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

[PATCH 5/5] toaster: clarify the units used for buildstats

[Elliot Smith]

The disk IO value for a task in buildstats is measured in bytes
rather than ms. Modify the "all builds" and "project builds" tables
to reflect this.

Add some notes to the Build model to make it clear which units
are used for each buildstats property.

[YOCTO #8842]

Signed-off-by: Elliot Smith <elliot.smith@intel.com>
---
 bitbake/lib/toaster/orm/models.py       | 7 +++++++
 bitbake/lib/toaster/toastergui/views.py | 4 ++--
 2 files changed, 9 insertions(+), 2 deletions(-)

diff --git a/bitbake/lib/toaster/orm/models.py b/bitbake/lib/toaster/orm/models.py
index ab6940f..255c586 100644
--- a/bitbake/lib/toaster/orm/models.py
+++ b/bitbake/lib/toaster/orm/models.py
@@ -712,9 +712,16 @@ class Task(models.Model):
     work_directory = models.FilePathField(max_length=255, blank=True)
     script_type = models.IntegerField(choices=TASK_CODING, default=CODING_NA)
     line_number = models.IntegerField(default=0)
+
+    # in bytes
     disk_io = models.IntegerField(null=True)
+
+    # as a percentage of the time taken by the build which triggered this task
     cpu_usage = models.DecimalField(max_digits=8, decimal_places=2, null=True)
+
+    # in seconds
     elapsed_time = models.DecimalField(max_digits=8, decimal_places=2, null=True)
+
     sstate_result = models.IntegerField(choices=SSTATE_RESULT, default=SSTATE_NA)
     message = models.CharField(max_length=240)
     logfile = models.FilePathField(max_length=255, blank=True)
diff --git a/bitbake/lib/toaster/toastergui/views.py b/bitbake/lib/toaster/toastergui/views.py
index 13489af..6efa131 100755
--- a/bitbake/lib/toaster/toastergui/views.py
+++ b/bitbake/lib/toaster/toastergui/views.py
@@ -1171,8 +1171,8 @@ def tasks_common(request, build_id, variant, task_anchor):
         tc_cache['hidden']='1'
 
     tc_diskio={
-        'name':'Disk I/O (ms)',
-        'qhelp':'Number of miliseconds the task spent doing disk input and output',
+        'name':'Disk I/O (bytes)',
+        'qhelp':'Number of bytes written to and read from the disk during the task',
         'orderfield': _get_toggle_order(request, "disk_io", True),
         'ordericon':_get_toggle_order_icon(request, "disk_io"),
         'orderkey' : 'disk_io',
-- 
Elliot Smith
Software Engineer
Intel OTC

---------------------------------------------------------------------
Intel Corporation (UK) Limited
Registered No. 1134945 (England)
Registered Office: Pipers Way, Swindon SN3 1RJ
VAT No: 860 2173 47

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

Re: [PATCH 0/5] Fix task buildstats gathering

[Barros Pena, Belen]

On 19/02/2016 15:49, "toaster-bounces@yoctoproject.org on behalf of Elliot
Smith" <toaster-bounces@yoctoproject.org on behalf of
elliot.smith@intel.com> wrote:

>Our buildstats gathering for tasks (CPU usage, Disk IO etc.) is broken,
>partly because of changes to how the data is organised in the buildstats
>files, and partly because tasks aren't being updated correctly anyway.
>
>Clean up the code which collects the buildstats (it had lots of
>duplication), collect the stats from the new stat file format (some line
>leaders had changed), and correctly identify the Task objects to update
>in BuildInfoHelper.
>
>To test:
>
>1. Remove the content of the directories which cache tasks to see the
>best effects (I usually delete buildstats, tmp, sstate-cache, and cache,
>just to be safe).
>
>2. Run a build against a local Yocto (as one patch is for
>toaster.bbclass).
>
>3. When the build finishes, view the "Tasks" page for the build and
>enable the "Disk IO" and "CPU usage" columns. Note that some CPU usage
>percentages are > 100, as discussed in bug 8842.
>
>Changes since c0fe43b (toaster-next) are in
>git://git.yoctoproject.org/poky-contrib, elliot/toaster/build_data-8842
>http://git.yoctoproject.org/cgit.cgi/poky-contrib/log/?h=elliot/toaster/bu
>ild_data-8842

So I ran a build following the steps above, and had a look at the data.
Information now shows, which is definitely an improvement :)

* Time and Disk I/O show for all executed tasks, which is what's supposed
to happen.
* CPU usage is missing from some executed tasks. This used to happen
before as well, but we never actually worked out why.

Regarding the numbers, I am not sure how useful is the Disk I/O figure
expressed in bytes. Should we convert it to something else? And then, our
big problem is definitely the CPU usage, which shows pretty crazy numbers.
The highest one in my build was for linux-yocto do_compile_kernelmodules
at a whopping 2455.15%

So, Richard Purdie pointed out to us that % over 100 are related to task
parallelism. And in fact, if I divide the CPU usage value of the compile
tasks by the value of PARALLEL_MAKE (36), I do get percentages below 100
for all of them. In the example of linux-yocto do_compile_kernelmodules,
we get 68.20%

If I divide the CPU usage value of all the install tasks by the value of
PARALLEL_MAKEINST (36), the same happens: % below 100.

However, we do get % over 100 for tasks that we have been told have no
parallelism at all. I see such values for unpack, patch, configure,
package and populate_sysroot tasks. So, the question is, why are those
happening? Because for tasks that we know have parallelism we might be
able to divide the value by the parallelism set, as I did for compile and
install tasks. But for the others, I genuinely have no answer, other that
there must be some kind of bug in the data collection.

Thoughts?

Cheers

Belén

>
>Related bug: https://bugzilla.yoctoproject.org/show_bug.cgi?id=8842
>
>NOTE: The first commit in this patch series is for oe-core.
>
>Elliot Smith (5):
>  toaster.bbclass: improve how we gather buildstats for Toaster
>  toaster: elapsed time for a task is calculated in toaster.bbclass
>  toaster: when updating task stats, task must exist
>  toaster: use a more straightforward query to find tasks to update
>  toaster: clarify the units used for buildstats
>
> bitbake/lib/bb/ui/buildinfohelper.py    | 49 +++++++--------------
> bitbake/lib/toaster/orm/models.py       |  7 +++
> bitbake/lib/toaster/toastergui/views.py |  4 +-
> meta/classes/toaster.bbclass            | 76
>++++++++++++++++++++++-----------
> 4 files changed, 77 insertions(+), 59 deletions(-)
>
>--
>Elliot Smith
>Software Engineer
>Intel OTC
>
>---------------------------------------------------------------------
>Intel Corporation (UK) Limited
>Registered No. 1134945 (England)
>Registered Office: Pipers Way, Swindon SN3 1RJ
>VAT No: 860 2173 47
>
>This e-mail and any attachments may contain confidential material for
>the sole use of the intended recipient(s). Any review or distribution
>by others is strictly prohibited. If you are not the intended
>recipient, please contact the sender and delete all copies.
>
>-- 
>_______________________________________________
>toaster mailing list
>toaster@yoctoproject.org
>https://lists.yoctoproject.org/listinfo/toaster

Re: [PATCH 0/5] Fix task buildstats gathering

[Richard Purdie]

On Sat, 2016-02-20 at 18:51 +0000, Barros Pena, Belen wrote:
> So I ran a build following the steps above, and had a look at the
> data.
> Information now shows, which is definitely an improvement :)
> 
> * Time and Disk I/O show for all executed tasks, which is what's
> supposed
> to happen.
> * CPU usage is missing from some executed tasks. This used to happen
> before as well, but we never actually worked out why.
> 
> Regarding the numbers, I am not sure how useful is the Disk I/O
> figure
> expressed in bytes. Should we convert it to something else? And then,
> our
> big problem is definitely the CPU usage, which shows pretty crazy
> numbers.
> The highest one in my build was for linux-yocto
> do_compile_kernelmodules
> at a whopping 2455.15%
> 
> So, Richard Purdie pointed out to us that % over 100 are related to
> task
> parallelism. And in fact, if I divide the CPU usage value of the
> compile
> tasks by the value of PARALLEL_MAKE (36), I do get percentages below
> 100
> for all of them. In the example of linux-yocto
> do_compile_kernelmodules,
> we get 68.20%
> 
> If I divide the CPU usage value of all the install tasks by the value
> of
> PARALLEL_MAKEINST (36), the same happens: % below 100.
> 
> However, we do get % over 100 for tasks that we have been told have
> no
> parallelism at all. I see such values for unpack, patch, configure,
> package and populate_sysroot tasks. 

FWIW, do_package does contain parallelism.
For unpack/patch/configure/populate_sysroot, there is some parallelism
too, in that the parent logging runs in parallel with the child
execution. Where these tasks run quickly, I think this could account
for the 'parallelism' we see there. Was it only for short running
tasks?

> So, the question is, why are those
> happening? Because for tasks that we know have parallelism we might 
> be able to divide the value by the parallelism set, as I did for 
> compile and install tasks. But for the others, I genuinely have no 
> answer, other that there must be some kind of bug in the data
> collection.

FWIW I'm very strongly against doing any kind of division by
PARALLEL_MAKE or similar numbers as it makes the end resulting number
much less meaningful. The idea behind showing these numbers in the UI
is to allow people to make decisions based on the numbers. If you do
that division, I can't think of useful decisions/actions I could then
make on it.

For example, "2455%" above tells me that we have a parallelism factor
of about 24 in the kernel build. From that I can conclude that whilst
the kernel is good, its not making full use of the hardware which would
have been a factor of 36 (although the system was likely also busy
doing other things unless the task was run in isolation).

The only proposal I have is to simply display these as parallelism
factors rather than percentage usages. I don't think the data collected
is wrong, it does require a certain about of thinking to interpret it
though. We're pulling this data direct from the kernel so its unlikely
we can get any "better" (easier to interpret?) data either.

Cheers,

Richard

Re: [PATCH 0/5] Fix task buildstats gathering

[Barros Pena, Belen]

On 21/02/2016 12:04, "Richard Purdie" <richard.purdie@linuxfoundation.org>
wrote:

>On Sat, 2016-02-20 at 18:51 +0000, Barros Pena, Belen wrote:
>> So I ran a build following the steps above, and had a look at the
>> data.
>> Information now shows, which is definitely an improvement :)
>> 
>> * Time and Disk I/O show for all executed tasks, which is what's
>> supposed
>> to happen.
>> * CPU usage is missing from some executed tasks. This used to happen
>> before as well, but we never actually worked out why.
>> 
>> Regarding the numbers, I am not sure how useful is the Disk I/O
>> figure
>> expressed in bytes. Should we convert it to something else? And then,
>> our
>> big problem is definitely the CPU usage, which shows pretty crazy
>> numbers.
>> The highest one in my build was for linux-yocto
>> do_compile_kernelmodules
>> at a whopping 2455.15%
>> 
>> So, Richard Purdie pointed out to us that % over 100 are related to
>> task
>> parallelism. And in fact, if I divide the CPU usage value of the
>> compile
>> tasks by the value of PARALLEL_MAKE (36), I do get percentages below
>> 100
>> for all of them. In the example of linux-yocto
>> do_compile_kernelmodules,
>> we get 68.20%
>> 
>> If I divide the CPU usage value of all the install tasks by the value
>> of
>> PARALLEL_MAKEINST (36), the same happens: % below 100.
>> 
>> However, we do get % over 100 for tasks that we have been told have
>> no
>> parallelism at all. I see such values for unpack, patch, configure,
>> package and populate_sysroot tasks.
>
>FWIW, do_package does contain parallelism.
>For unpack/patch/configure/populate_sysroot, there is some parallelism
>too, in that the parent logging runs in parallel with the child
>execution. Where these tasks run quickly, I think this could account
>for the 'parallelism' we see there. Was it only for short running
>tasks?

I am not sure what you'd consider a 'short running' task, so here are a
few examples:

Recipe			task			time (secs)	CPU usage
db			do_unpack		1.29		144.34%
linux-libc-headers 	do_unpack		9.81		134.64%

linux-yocto 		do_patch		16.40		141.12%

rpm-native		do_patch		4.84		117.13%
gcc-cross-i586		do_configure		3.25		125.24%

gcc-cross-initial-i586 	do_configure		3.27		120.50%

glibc-locale		do_populate_sysroot	2.80		192.74%

flex			do_populate_sysroot	1.98		157.74%

>
>> So, the question is, why are those
>> happening? Because for tasks that we know have parallelism we might
>> be able to divide the value by the parallelism set, as I did for
>> compile and install tasks. But for the others, I genuinely have no
>> answer, other that there must be some kind of bug in the data
>> collection.
>
>FWIW I'm very strongly against doing any kind of division by
>PARALLEL_MAKE or similar numbers as it makes the end resulting number
>much less meaningful. The idea behind showing these numbers in the UI
>is to allow people to make decisions based on the numbers. If you do
>that division, I can't think of useful decisions/actions I could then
>make on it.
>
>For example, "2455%" above tells me that we have a parallelism factor
>of about 24 in the kernel build. From that I can conclude that whilst
>the kernel is good, its not making full use of the hardware which would
>have been a factor of 36 (although the system was likely also busy
>doing other things unless the task was run in isolation).]

And what if we look at the other side of the data? What does a value of
7.32% mean, like the one we get for netbase do_compile?

>
>The only proposal I have is to simply display these as parallelism
>factors rather than percentage usages.

So, in the example of linux-yocto do_compile_kernelmodules, would we show
'24'? And for netbase do_compile? '0.07'?

Would it be just easier to show resource usage times, since they are
somehow a standard measure that users might be more likely to recognise?
So we could show either:

* Child rusage ru_utime + Child rusage ru_stime
* or we split CPU usage into 2 columns, one for ru_utime and the other for
ru_stime

> I don't think the data collected
>is wrong, it does require a certain about of thinking to interpret it
>though.
>We're pulling this data direct from the kernel so its unlikely
>we can get any "better" (easier to interpret?) data either.
>
>Cheers,
>
>Richard
>
>

Re: [PATCH 0/5] Fix task buildstats gathering

[Richard Purdie]

On Mon, 2016-02-22 at 10:25 +0000, Barros Pena, Belen wrote:
> I am not sure what you'd consider a 'short running' task, so here are
> a few examples:
> 
> Recipe			task			time (secs)	
> CPU usage
> db			do_unpack		1.29		
> 144.34%
> linux-libc-headers 	do_unpack		9.81		
> 134.64%
> 
> linux-yocto 		do_patch		16.40		
> 141.12%
> 
> rpm-native		do_patch		4.84		
> 117.13%
> gcc-cross-i586		do_configure		3.25	
> 	125.24%
> 
> gcc-cross-initial-i586 	do_configure		3.27	
> 	120.50%
> 
> glibc-locale		do_populate_sysroot	2.80		
> 192.74%
> 
> flex			do_populate_sysroot	1.98		
> 157.74%

I was thinking roughly "under 3 seconds", so some of these are higher
that I'd have expected. Could you share the parent utime/stime and
cumulative utime/stime for these please, just so we can get a better
idea of what was going on there.


> And what if we look at the other side of the data? What does a value 
> of 7.32% mean, like the one we get for netbase do_compile?
>
> So, in the example of linux-yocto do_compile_kernelmodules, would we
> show
> '24'? And for netbase do_compile? '0.07'?

Yes. 0.07 means it didn't really do much in parallel at all and wasn't
using much of a single processor. 

> Would it be just easier to show resource usage times, since they are
> somehow a standard measure that users might be more likely to
> recognise?
> So we could show either:
> 
> * Child rusage ru_utime + Child rusage ru_stime
> * or we split CPU usage into 2 columns, one for ru_utime and the
> other for
> ru_stime

Personally, I see a lot of value in showing these numbers separately.
As my question above kind of indicates, you really need several of the
numbers to understand exactly what may have been going on within the
task and there isn't one number you can show which tells you
everything.

This is a bit of an aside, but another "missing" piece of information
is "what was going on in the system at the same time as this task?". 
This is the kind of information that the bootchart graph shows really
well. If we could click on something and see which other tasks were
running at the time this task was, that would be information we can't
currently easily obtain.

That data is there, we know the start and end times of each of the
tasks, so something can compute which ones were running at time X, but
its not something that anything is currently doing as we don't have an
easy way to display that on the commandline.

Cheers,

Richard

Re: [PATCH 0/5] Fix task buildstats gathering

[Barros Pena, Belen]

[-- Attachment #1: Type: text/plain, Size: 792 bytes --]



On 22/02/2016 12:12, "Richard Purdie" <richard.purdie@linuxfoundation.org>
wrote:

>>Recipe			task			time (secs)	
>>CPU usage
>>db			do_unpack		1.29		
>>144.34%
>>linux-libc-headers 	do_unpack		9.81		
>>134.64%
>>linux-yocto 		do_patch		16.40		
>>141.12%
>>rpm-native		do_patch		4.84		
>>117.13%
>>gcc-cross-i586		do_configure		3.25	
>>	125.24%
>>gcc-cross-initial-i586 	do_configure		3.27	
>>	120.50%
>>glibc-locale		do_populate_sysroot	2.80		
>>192.74%
>>flex			do_populate_sysroot	1.98		
>>157.74%
>
>I was thinking roughly "under 3 seconds", so some of these are higher
>that I'd have expected. Could you share the parent utime/stime and
>cumulative utime/stime for these please, just so we can get a better
>idea of what was going on there.

Attached. 


[-- Attachment #2: sample_stats.ods --]
[-- Type: application/vnd.oasis.opendocument.spreadsheet, Size: 26683 bytes --]

Re: [PATCH 0/5] Fix task buildstats gathering

[Smith, Elliot]

[-- Attachment #1: Type: text/plain, Size: 1497 bytes --]

I've posted a v2 of this:
https://lists.yoctoproject.org/pipermail/toaster/2016-February/003879.html

Elliot

On 22 February 2016 at 12:25, Barros Pena, Belen <
belen.barros.pena@intel.com> wrote:

>
>
> On 22/02/2016 12:12, "Richard Purdie" <richard.purdie@linuxfoundation.org>
> wrote:
>
> >>Recipe                        task                    time (secs)
> >>CPU usage
> >>db                    do_unpack               1.29
> >>144.34%
> >>linux-libc-headers    do_unpack               9.81
> >>134.64%
> >>linux-yocto           do_patch                16.40
> >>141.12%
> >>rpm-native            do_patch                4.84
> >>117.13%
> >>gcc-cross-i586                do_configure            3.25
> >>      125.24%
> >>gcc-cross-initial-i586        do_configure            3.27
> >>      120.50%
> >>glibc-locale          do_populate_sysroot     2.80
> >>192.74%
> >>flex                  do_populate_sysroot     1.98
> >>157.74%
> >
> >I was thinking roughly "under 3 seconds", so some of these are higher
> >that I'd have expected. Could you share the parent utime/stime and
> >cumulative utime/stime for these please, just so we can get a better
> >idea of what was going on there.
>
> Attached.
>
>
> --
> _______________________________________________
> toaster mailing list
> toaster@yoctoproject.org
> https://lists.yoctoproject.org/listinfo/toaster
>
>


-- 
Elliot Smith
Software Engineer
Intel Open Source Technology Centre

[-- Attachment #2: Type: text/html, Size: 2593 bytes --]