| Summary: | Update Toaster's build performance data | ||
|---|---|---|---|
| Product: | [Build System, Metadata & Runtime] Toaster | Reporter: | Belen Barros Pena <belen.barros.pena> |
| Component: | toaster | Assignee: | Elliot Smith <elliot.smith> |
| Status: | RESOLVED FIXED | QA Contact: | Mihail Stanciu <stanciux.mihail> |
| Severity: | enhancement | ||
| Priority: | Medium | CC: | belen.barros.pena, brian.avery, jessica.zhang, richard.purdie, stanciux.mihail |
| Version: | 2.0 | ||
| Target Milestone: | 2.1 M3 | ||
| Hardware: | x86 | ||
| OS: | Multiple | ||
| Whiteboard: | |||
| OS type for building Yocto: | --- | Type of Regression: | --- |
| Verified: | Documentation change: | Yes (doc changes required) | |
| Bug Depends on: | |||
| Bug Blocks: | 8571 | ||
|
Description
Belen Barros Pena
2015-12-21 11:29:12 UTC
> I'd note that CPU usage is no longer logged, the reason being that the
> numbers were basically misleading and inaccurate.
Not logged at all? If that's the case, it's kind of urgent that we remove that information from Toaster.
(In reply to comment #1) > > I'd note that CPU usage is no longer logged, the reason being that the > > numbers were basically misleading and inaccurate. > > Not logged at all? If that's the case, it's kind of urgent that we remove > that information from Toaster. Just replying to myself. Further down it's explained that "You could do a better CPU usage approximation by something like: (child(ru_stime + ru_utime) / elapsed time) * 100 = % CPU Usage" 8571 has similar issues. Belen, do we need any changes to design? Or are we just looking at changing how we show the values we already have, i.e. * Task execution time: elapsed time for the task * CPU usage: (child(ru_stime + ru_utime) / elapsed time) * 100 * Some IO usage number: wchar + rchar, or rchar / wchar (In reply to comment #4) > Belen, do we need any changes to design? Or are we just looking at changing > how we show the values we already have, i.e. > > * Task execution time: elapsed time for the task > * CPU usage: (child(ru_stime + ru_utime) / elapsed time) * 100 > * Some IO usage number: wchar + rchar, or rchar / wchar No design changes needed for the time being, I think. Let's get those numbers showing first :) I've implemented a first version of this where I'm deriving the following stats: * Elapsed time: taken from the line which reads "<recipe>: <task>: Elapsed time: <elapsed time> seconds" * CPU usage: (child(ru_stime + ru_utime) / elapsed time) * 100 * IO bytes written/read: "IO write_bytes" + "IO read_bytes" Note that we used to have a column called "Disk IO (ms)". I'm not sure how to derive this value from the new buildstats layout. Should we use "Disk IO (bytes)" instead? Or is there some way to derive the disk IO in ms? I also get some weird percentages (> 100) when I use (child(ru_stime + ru_utime) / elapsed time) * 100 for CPU usage. Is this expected? Should I round down to 100 (assuming the ru_stime and ru_utime are approximate)? It's probably my maths or a problem with how I'm converting the values. I'll go back and check. or it's a bug in the stats since they are newish. worth checking and tracking down. This is the content of the do_compile file for gmp-native:
Event: TaskStarted
Started: 1455296531.70
gmp-native-6.1.0-r0: do_compile: Elapsed time: 9.40 seconds
utime: 24
stime: 10
cutime: 7123
cstime: 3067
IO write_bytes: 19435520
IO read_bytes: 0
IO cancelled_write_bytes: 2797568
IO syscr: 227165
IO wchar: 18077604
IO rchar: 683027772
IO syscw: 40250
rusage ru_utime: 0.244901
rusage ru_stime: 0.103611
rusage ru_maxrss: 69328
rusage ru_minflt: 4887
rusage ru_majflt: 0
rusage ru_inblock: 0
rusage ru_oublock: 1616
rusage ru_nvcsw: 1779
rusage ru_nivcsw: 7
Child rusage ru_utime: 71.239207
Child rusage ru_stime: 30.670274
Child rusage ru_maxrss: 67792
Child rusage ru_minflt: 5555062
Child rusage ru_majflt: 0
Child rusage ru_inblock: 0
Child rusage ru_oublock: 36344
Child rusage ru_nvcsw: 39696
Child rusage ru_nivcsw: 18931
Status: PASSED
Ended: 1455296541.10
According to the comments above, I was expecting "Child rusage ru_utime" to be the child ru_utime and "Child rusage ru_stime" to be child ru_stime in seconds (as mentioned in RP's formula); then I was using the following to calculate CPU usage:
(("Child rusage ru_utime" + "Child rusage ru_stime") / "Elapsed time") * 100
However, this looks very wrong (1084%).
So which lines from build stats should I be using for this calculation?
RP clarified that this may be because some tasks are run in parallel. I tried another build with PARALLEL_MAKE="-j 1" (as suggested by RP). I had to set this in the bitbake/bin/toaster script, as any builds we do are performed by the server we start in that script. This does produce more sensible output, but some of the CPU percentages are still > 100. Here's an example for autoconf-native do_patch, which shouldn't be affected by parallelism: Event: TaskStarted Started: 1455552836.29 autoconf-native-2.69-r11: do_patch: Elapsed time: 1.06 seconds utime: 14 stime: 5 cutime: 26 cstime: 94 IO write_bytes: 720896 IO read_bytes: 0 IO cancelled_write_bytes: 4096 IO syscr: 4679 IO wchar: 721384 IO rchar: 2771953 IO syscw: 791 rusage ru_utime: 0.144221 rusage ru_stime: 0.053567 rusage ru_maxrss: 55584 rusage ru_minflt: 10307 rusage ru_majflt: 0 rusage ru_inblock: 0 rusage ru_oublock: 88 rusage ru_nvcsw: 40 rusage ru_nivcsw: 1 Child rusage ru_utime: 0.269655 Child rusage ru_stime: 0.947122 Child rusage ru_maxrss: 54020 Child rusage ru_minflt: 101600 Child rusage ru_majflt: 0 Child rusage ru_inblock: 0 Child rusage ru_oublock: 1320 Child rusage ru_nvcsw: 1883 Child rusage ru_nivcsw: 355 Status: PASSED Ended: 1455552837.35 Note that Child rusage ru_utime + Child rusage ru_stime = 1.216777, while elapsed time is 1.06, giving a CPU usage % of 115%. (In reply to comment #12) > Here's an example for autoconf-native do_patch, which shouldn't be affected > by parallelism: > > Event: TaskStarted > Started: 1455552836.29 > autoconf-native-2.69-r11: do_patch: Elapsed time: 1.06 seconds > utime: 14 > stime: 5 > cutime: 26 > cstime: 94 > IO write_bytes: 720896 > IO read_bytes: 0 > IO cancelled_write_bytes: 4096 > IO syscr: 4679 > IO wchar: 721384 > IO rchar: 2771953 > IO syscw: 791 > rusage ru_utime: 0.144221 > rusage ru_stime: 0.053567 > rusage ru_maxrss: 55584 > rusage ru_minflt: 10307 > rusage ru_majflt: 0 > rusage ru_inblock: 0 > rusage ru_oublock: 88 > rusage ru_nvcsw: 40 > rusage ru_nivcsw: 1 > Child rusage ru_utime: 0.269655 > Child rusage ru_stime: 0.947122 > Child rusage ru_maxrss: 54020 > Child rusage ru_minflt: 101600 > Child rusage ru_majflt: 0 > Child rusage ru_inblock: 0 > Child rusage ru_oublock: 1320 > Child rusage ru_nvcsw: 1883 > Child rusage ru_nivcsw: 355 > Status: PASSED > Ended: 1455552837.35 > > Note that Child rusage ru_utime + Child rusage ru_stime = 1.216777, while > elapsed time is 1.06, giving a CPU usage % of 115%. This does look a little odd however given the parent does handle logging of the children, its not totally off the wall, the short duration of the task likely makes the difference more pronounced. it doesn't look like we are going to reach a conclusion any time soon, so let's put the numbers in Toaster, with CPU usage as suggested initially by Richard (child(ru_stime + ru_utime) / elapsed time) * 100 = % CPU Usage Seeing the numbers in Toaster might help us better understand what's going on. Submitted to Toaster mailing list for review: https://lists.yoctoproject.org/pipermail/toaster/2016-February/003844.html Upstreamed and in master. |