8842 2015-12-21 11:29:12 +0000 Update Toaster's build performance data 2016-03-15 11:43:29 +0000 1 1 7 Build System, Metadata & Runtime Toaster toaster 2.0 x86 Multiple RESOLVED FIXED Medium enhancement 2.1 M3 8571 1 belen.barros.pena elliot.smith belen.barros.pena brian.avery jessica.zhang richard.purdie stanciux.mihail stanciux.mihail --- --- Yes (doc changes required) oldest_to_newest 57404 0 belen.barros.pena 2015-12-21 11:29:12 +0000 RP has done a significant overhaul of buildstats, and has asked we incorporate the improvements to the build performance information in Toaster. This is his explanation about the changes (http://lists.openembedded.org/pipermail/openembedded-core/2015-December/114369.html): 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 57405 1 belen.barros.pena 2015-12-21 11:32:14 +0000 > 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. 57406 2 belen.barros.pena 2015-12-21 11:33:27 +0000 (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" 57593 3 brian.avery 2016-01-06 16:13:13 +0000 8571 has similar issues. 58347 4 elliot.smith 2016-01-29 17:12:31 +0000 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 58381 5 belen.barros.pena 2016-02-01 11:19:31 +0000 (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 :) 58961 6 elliot.smith 2016-02-12 16:49:00 +0000 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? 58963 7 elliot.smith 2016-02-12 17:06:49 +0000 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)? 58964 8 elliot.smith 2016-02-12 17:16:27 +0000 It's probably my maths or a problem with how I'm converting the values. I'll go back and check. 58965 9 brian.avery 2016-02-12 17:18:31 +0000 or it's a bug in the stats since they are newish. worth checking and tracking down. 58967 10 elliot.smith 2016-02-12 17:26:59 +0000 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? 59028 11 elliot.smith 2016-02-15 16:07:46 +0000 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. 59030 12 elliot.smith 2016-02-15 16:32:07 +0000 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%. 59033 13 richard.purdie 2016-02-15 16:44:22 +0000 (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. 59068 14 belen.barros.pena 2016-02-16 09:01:29 +0000 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. 59270 15 elliot.smith 2016-02-19 15:10:50 +0000 Submitted to Toaster mailing list for review: https://lists.yoctoproject.org/pipermail/toaster/2016-February/003844.html 59968 16 elliot.smith 2016-03-15 11:43:29 +0000 Upstreamed and in master.