[PATCH 6/7] toaster: Update for buildstats changes

[PATCH 6/7] toaster: Update for buildstats changes

[Richard Purdie]

This updates the toaster class to use the new data format from buildstats.
This does mean it will no longer read IO data from older builds, however
since that data is completely useless anyway, I don't consider that to be
an issue.

Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>

diff --git a/meta/classes/toaster.bbclass b/meta/classes/toaster.bbclass
index d63cff5..7af495e 100644
--- a/meta/classes/toaster.bbclass
+++ b/meta/classes/toaster.bbclass
@@ -199,8 +199,6 @@ python toaster_collect_task_stats() {
     def _read_stats(filename):
         cpu_usage = 0
         disk_io = 0
-        startio = '0'
-        endio = '0'
         started = '0'
         ended = '0'
         pn = ''
@@ -215,11 +213,11 @@ python toaster_collect_task_stats() {
         if "CPU usage" in statinfo:
             cpu_usage = str(statinfo["CPU usage"]).strip('% \n\r')
 
-        if "EndTimeIO" in statinfo:
-            endio = str(statinfo["EndTimeIO"]).strip('% \n\r')
+        if "IO write_bytes" in statinfo:
+            disk_io = disk_io + str(statinfo["IO write_bytes"]).strip('% \n\r')
 
-        if "StartTimeIO" in statinfo:
-            startio = str(statinfo["StartTimeIO"]).strip('% \n\r')
+        if "IO read_bytes" in statinfo:
+            disk_io = disk_io + str(statinfo["IO read_bytes"]).strip('% \n\r')
 
         if "Started" in statinfo:
             started = str(statinfo["Started"]).strip('% \n\r')
@@ -227,8 +225,6 @@ python toaster_collect_task_stats() {
         if "Ended" in statinfo:
             ended = str(statinfo["Ended"]).strip('% \n\r')
 
-        disk_io = int(endio) - int(startio)
-
         elapsed_time = float(ended) - float(started)
 
         cpu_usage = float(cpu_usage)

Re: [Toaster] FW: [PATCH 6/7] toaster: Update for buildstats changes

[Richard Purdie]

On Fri, 2015-12-18 at 09:21 +0000, Barros Pena, Belen wrote:
> I applied the buildstats series on top of toaster-next, ran a build,
> and
> checked the build stats info. I can see time per task coming in. I
> cannot
> see cpu usage or disk i/o data in the UI because of this
> 
> https://bugzilla.yoctoproject.org/show_bug.cgi?id=8571
> 
> But there is data for both in the database, and it looks sane. So I
> guess,
> from the UI standpoint, the patches are ok: things were as broken as
> they
> were before ;)

Thanks Belén!

I was asked what new data was available from buildstats. Right now you
show in toaster:

Task execution time
CPU usage
Some IO usage number

I'd note that CPU usage is no longer logged, the reason being that the
numbers were basically misleading and inaccurate. The raw data in
buildstats looks like:

Started: 1450427397.44 
quilt-0.64-r0: do_compile: Elapsed time: 0.37 seconds 
utime: 7
stime: 2
cutime: 16
cstime: 7
IO write_bytes: 1269760
IO read_bytes: 0
IO cancelled_write_bytes: 0
IO syscr: 6165
IO wchar: 1205445
IO rchar: 4465276
IO syscw: 1508
rusage ru_utime: 0.076
rusage ru_stime: 0.02
rusage ru_maxrss: 39684
rusage ru_minflt: 4618
rusage ru_majflt: 0
rusage ru_inblock: 0
rusage ru_oublock: 32
rusage ru_nvcsw: 53
rusage ru_nivcsw: 0
Child rusage ru_utime: 0.168
Child rusage ru_stime: 0.076
Child rusage ru_maxrss: 41180
Child rusage ru_minflt: 81640
Child rusage ru_majflt: 0
Child rusage ru_inblock: 0
Child rusage ru_oublock: 2448
Child rusage ru_nvcsw: 988
Child rusage ru_nivcsw: 352
Status: PASSED 
Ended: 1450427397.81 

In particular what you can do now is:

a) breakdown filesystem IO usage to reads and writes (read_bytes and
write_bytes)
b) show total IO (wchar and rchar)

[difference between filesystem IO and total IO is that there are caches
in the middle, filesystem IO goes to the physical disk, total IO can be
from memory - all the reads above were from cache hence 0 read_bytes
but a large rchar]

c) break down task execution time into "system" (cstime) and "user"
(cutime) time. Divide those numbers by 100HZ to get seconds. This tells
us how much time was in the kernel in syscalls and how much doing
execution in userspace. 

d) break down times into parent and child processes (stime and utime
verses cstime and ustime). The latter includes all children so is a
total. This is probably less interesting to most users.

e) show the number of voluntary and involuntary context switches
(ru_nvcsw and ru_nivcsw). Again, the child numbers are totals, you can
also just get the parent value.

f) there is other data but the above is the pieces I've personally
found to be interesting/useful.

Some of the numbers are duplicates, e.g. ru_stime is stime/100 (convert
to seconds) in the parent and child cases. You could do a better CPU
usage approximation by something like:

(child(ru_stime + ru_utime) / elapsed time) * 100 = % CPU Usage

Hope that makes some kind of sense and that we could expose a bit more
of this to the user at some point!

Cheers,

Richard

Re: [Toaster] FW: [PATCH 6/7] toaster: Update for buildstats changes

[Richard Purdie]

On Fri, 2015-12-18 at 09:21 +0000, Barros Pena, Belen wrote:
> I applied the buildstats series on top of toaster-next, ran a build,
> and
> checked the build stats info. I can see time per task coming in. I
> cannot
> see cpu usage or disk i/o data in the UI because of this
> 
> https://bugzilla.yoctoproject.org/show_bug.cgi?id=8571
> 
> But there is data for both in the database, and it looks sane. So I
> guess,
> from the UI standpoint, the patches are ok: things were as broken as
> they
> were before ;)

Thanks Belén!

I was asked what new data was available from buildstats. Right now you
show in toaster:

Task execution time
CPU usage
Some IO usage number

I'd note that CPU usage is no longer logged, the reason being that the
numbers were basically misleading and inaccurate. The raw data in
buildstats looks like:

Started: 1450427397.44 
quilt-0.64-r0: do_compile: Elapsed time: 0.37 seconds 
utime: 7
stime: 2
cutime: 16
cstime: 7
IO write_bytes: 1269760
IO read_bytes: 0
IO cancelled_write_bytes: 0
IO syscr: 6165
IO wchar: 1205445
IO rchar: 4465276
IO syscw: 1508
rusage ru_utime: 0.076
rusage ru_stime: 0.02
rusage ru_maxrss: 39684
rusage ru_minflt: 4618
rusage ru_majflt: 0
rusage ru_inblock: 0
rusage ru_oublock: 32
rusage ru_nvcsw: 53
rusage ru_nivcsw: 0
Child rusage ru_utime: 0.168
Child rusage ru_stime: 0.076
Child rusage ru_maxrss: 41180
Child rusage ru_minflt: 81640
Child rusage ru_majflt: 0
Child rusage ru_inblock: 0
Child rusage ru_oublock: 2448
Child rusage ru_nvcsw: 988
Child rusage ru_nivcsw: 352
Status: PASSED 
Ended: 1450427397.81 

In particular what you can do now is:

a) breakdown filesystem IO usage to reads and writes (read_bytes and
write_bytes)
b) show total IO (wchar and rchar)

[difference between filesystem IO and total IO is that there are caches
in the middle, filesystem IO goes to the physical disk, total IO can be
from memory - all the reads above were from cache hence 0 read_bytes
but a large rchar]

c) break down task execution time into "system" (cstime) and "user"
(cutime) time. Divide those numbers by 100HZ to get seconds. This tells
us how much time was in the kernel in syscalls and how much doing
execution in userspace. 

d) break down times into parent and child processes (stime and utime
verses cstime and ustime). The latter includes all children so is a
total. This is probably less interesting to most users.

e) show the number of voluntary and involuntary context switches
(ru_nvcsw and ru_nivcsw). Again, the child numbers are totals, you can
also just get the parent value.

f) there is other data but the above is the pieces I've personally
found to be interesting/useful.

Some of the numbers are duplicates, e.g. ru_stime is stime/100 (convert
to seconds) in the parent and child cases. You could do a better CPU
usage approximation by something like:

(child(ru_stime + ru_utime) / elapsed time) * 100 = % CPU Usage

Hope that makes some kind of sense and that we could expose a bit more
of this to the user at some point!

Cheers,

Richard

Re: [Toaster] FW: [PATCH 6/7] toaster: Update for buildstats changes

[Barros Pena, Belen]

On 18/12/2015 10:56, "Richard Purdie" <richard.purdie@linuxfoundation.org>
wrote:

>On Fri, 2015-12-18 at 09:21 +0000, Barros Pena, Belen wrote:
>> I applied the buildstats series on top of toaster-next, ran a build,
>> and
>> checked the build stats info. I can see time per task coming in. I
>> cannot
>> see cpu usage or disk i/o data in the UI because of this
>> 
>> https://bugzilla.yoctoproject.org/show_bug.cgi?id=8571
>> 
>> But there is data for both in the database, and it looks sane. So I
>> guess,
>> from the UI standpoint, the patches are ok: things were as broken as
>> they
>> were before ;)
>
>Thanks Belén!
>
>I was asked what new data was available from buildstats.

Thanks. I've opened an enhancement for this

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

Cheers

Belén

>Right now you
>show in toaster:
>
>Task execution time
>CPU usage
>Some IO usage number
>
>I'd note that CPU usage is no longer logged, the reason being that the
>numbers were basically misleading and inaccurate. The raw data in
>buildstats looks like:
>
>Started: 1450427397.44
>quilt-0.64-r0: do_compile: Elapsed time: 0.37 seconds
>utime: 7
>stime: 2
>cutime: 16
>cstime: 7
>IO write_bytes: 1269760
>IO read_bytes: 0
>IO cancelled_write_bytes: 0
>IO syscr: 6165
>IO wchar: 1205445
>IO rchar: 4465276
>IO syscw: 1508
>rusage ru_utime: 0.076
>rusage ru_stime: 0.02
>rusage ru_maxrss: 39684
>rusage ru_minflt: 4618
>rusage ru_majflt: 0
>rusage ru_inblock: 0
>rusage ru_oublock: 32
>rusage ru_nvcsw: 53
>rusage ru_nivcsw: 0
>Child rusage ru_utime: 0.168
>Child rusage ru_stime: 0.076
>Child rusage ru_maxrss: 41180
>Child rusage ru_minflt: 81640
>Child rusage ru_majflt: 0
>Child rusage ru_inblock: 0
>Child rusage ru_oublock: 2448
>Child rusage ru_nvcsw: 988
>Child rusage ru_nivcsw: 352
>Status: PASSED 
>Ended: 1450427397.81
>
>In particular what you can do now is:
>
>a) breakdown filesystem IO usage to reads and writes (read_bytes and
>write_bytes)
>b) show total IO (wchar and rchar)
>
>[difference between filesystem IO and total IO is that there are caches
>in the middle, filesystem IO goes to the physical disk, total IO can be
>from memory - all the reads above were from cache hence 0 read_bytes
>but a large rchar]
>
>c) break down task execution time into "system" (cstime) and "user"
>(cutime) time. Divide those numbers by 100HZ to get seconds. This tells
>us how much time was in the kernel in syscalls and how much doing
>execution in userspace.
>
>d) break down times into parent and child processes (stime and utime
>verses cstime and ustime). The latter includes all children so is a
>total. This is probably less interesting to most users.
>
>e) show the number of voluntary and involuntary context switches
>(ru_nvcsw and ru_nivcsw). Again, the child numbers are totals, you can
>also just get the parent value.
>
>f) there is other data but the above is the pieces I've personally
>found to be interesting/useful.
>
>Some of the numbers are duplicates, e.g. ru_stime is stime/100 (convert
>to seconds) in the parent and child cases. You could do a better CPU
>usage approximation by something like:
>
>(child(ru_stime + ru_utime) / elapsed time) * 100 = % CPU Usage
>
>Hope that makes some kind of sense and that we could expose a bit more
>of this to the user at some point!
>
>Cheers,
>
>Richard
>