New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 676663 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Last visit > 30 days ago
Closed: Apr 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 3
Type: Bug



Sign in to add a comment

HWTest duration on waterfall is misleading

Project Member Reported by diand...@chromium.org, Dec 22 2016

Issue description

Looking 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?
 
Cc: semenzato@chromium.org dshi@chromium.org jrbarnette@chromium.org sbasi@chromium.org
Components: Infra>Client>ChromeOS
Labels: OS-Chrome
Owner: ----
Yes, I've also often felt that there is confusion in the time stamps between something happening and something being reported, in other places too.  For instance, in the status.log file in the buckets.  (Which makes me guilty of not opening a similar bug earlier, but never mind---thank you for opening this.)

Comment 2 by dshi@chromium.org, Dec 22 2016

Cc: akes...@chromium.org
Cc: -dshi@chromium.org -sbasi@chromium.org d...@chromium.org
Owner: dgarr...@chromium.org
don - anything we can do here? nxia says some of these time stamps are controlled by build bot. 

Comment 4 by d...@chromium.org, 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.
I like seeing the times, so I'd vote for #2.

Comment 6 by d...@chromium.org, 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.
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.
Labels: Hotlist-Fixit
Status: Available (was: Untriaged)
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)
************************************************************

Components: Infra>Client>ChromeOS>CI
Components: -Infra>Client>ChromeOS
Owner: jinjingl@chromium.org
Status: Fixed (was: Available)
The Legoland UI should have the correct timing in nearly all cases.

Sign in to add a comment