HWTest duration on waterfall is misleading |
|||||||
Issue descriptionLooking at: https://uberchromegw.corp.google.com/i/chromeos/builders/elm-paladin/builds/1374/steps/HWTest%20%5Bbvt-inline%5D/logs/stdio ...for instance. Snippets from the log: ** Start Stage HWTest [bvt-inline] - Thu, 22 Dec 2016 05:28:32 -0800 (PST) ... ... ... ** Finished Stage HWTest [bvt-inline] - Thu, 22 Dec 2016 06:05:56 -0800 (PST) ... ... ... started: Thu Dec 22 05:51:32 2016 ended: Thu Dec 22 06:06:07 2016 duration: 14 mins, 34 secs status: SUCCESS === Maybe the "started" is reported as the time the last step finished even though things are happening in parallel? I just got a little confused thinking that maybe the HWTest stage was stuck since I did this: * Looked at build 1374 in the waterfall and saw that HWTest was supposed to take ~15 minutes. * Looked at build 1375 in the logs and saw the "Start Stage" was ~30 minutes ago. Anyway, don't know if this is important to do something about, but I figured I'd open a bug. Luigi: does this make sense? Do you know who might be interested in looking at it?
,
Dec 22 2016
,
Jan 4 2017
don - anything we can do here? nxia says some of these time stamps are controlled by build bot.
,
Jan 4 2017
This isn't the first time this issue has come up. The entire method that we use to render flexible steps (allowing cbuildbot to define its own structure) is a bit of a hack, and cbuildbot's employment of this method is further hacky. cbuildbot runs multiple steps in parallel, and then emits them to BuildBot with status results as each finishes. If one step has already finished, cbuildbot delays emitting it to BuildBot until all previous parallel steps have also finished so that the output is properly ordered. However, from BuildBot's perspective, this means that the step starts and them immediately finishes, resulting in the 0 duration and immediate start/stop times. There's no simple way to fix this, and any sort of fix would require additional BuildBot hacks and cbuildbot's cooperation. Two solutions come to mind: 1) Suppress per-step durations in BuildBot output. This is as simple as modifying the build template that BuildBot uses for ChromeOS 2) Have cbuildbot emit its times and duration explicitly as annotations.
,
Jan 4 2017
I like seeing the times, so I'd vote for #2.
,
Jan 4 2017
Note that they are not mutually exclusive. Combining #1 and #2 would actually still show you more accurate times without the misleading BuildBot times.
,
Jan 4 2017
The ReportStage links out to "Build stages timeline" and "Build details" both of which present an accurate and correct timeline. The stanza "started: Thu Dec 22 05:51:32 2016 ended: Thu Dec 22 06:06:07 2016 duration: 14 mins, 34 secs status: SUCCESS" that you see is generated by buildbot, and is incorrect because it doesn't know about stage parallelism (we have to linearize the stage history when we log it.
,
Apr 13 2017
I like the idea of adding during to our stage completion logs, and then turning off the buildbot stuff. IE, adding duration to: ************************************************************ ** Finished Stage SetupBoard - Thu, 13 Apr 2017 14:49:54 -0700 (PDT) ************************************************************
,
Mar 30 2018
,
Mar 30 2018
,
Apr 5 2018
The Legoland UI should have the correct timing in nearly all cases. |
|||||||
►
Sign in to add a comment |
|||||||
Comment 1 by semenzato@chromium.org
, Dec 22 2016Components: Infra>Client>ChromeOS
Labels: OS-Chrome
Owner: ----