toaster: Update for buildstats changes

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.

index d63cff5..7af495e 100644
@@ -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)

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

Cheers

Belén

On 17/12/2015 14:54, "[email protected] on behalf of Richard Purdie" <[email protected] on behalf of

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

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

Thanks. I've opened an enhancement for this

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

Cheers

Belén