Project: chromium Issues People Development process History Sign in
New issue
Advanced search Search tips
Starred by 0 users
Status: Unconfirmed
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment
Very long delay between tests complete & stage end during bvt-inline stage
Project Member Reported by snanda@chromium.org, Jan 12 2017 Back to list
There's about a 48 minute delta between the tests completing and the bvt-inline stage being called done. This slowed the CQ down and would therefore be interesting to understand and improve if possible.

Not sure how prevalent the issue is, but here's one example log:

https://uberchromegw.corp.google.com/i/chromeos/builders/elm-paladin/builds/1536/steps/HWTest%20%5Bbvt-inline%5D/logs/stdio

Suite timings:
Downloads started at 2017-01-12 14:16:44
Payload downloads ended at 2017-01-12 14:16:52
Suite started at 2017-01-12 14:19:05
Artifact downloads ended (at latest) at 2017-01-12 14:19:08
Testing started at 2017-01-12 14:37:01
Testing ended at 2017-01-12 15:02:16


....
15:50:15: INFO: Running cidb query on pid 18024, repr(query) starts with <sqlalchemy.sql.expression.Insert object at 0x3ca1bd0>
15:50:20: INFO: cidb query succeeded after 1 retries
15:50:20: INFO: Running cidb query on pid 18024, repr(query) starts with <sqlalchemy.sql.expression.Update object at 0x3d80090>
************************************************************
** Finished Stage HWTest [bvt-inline] - Thu, 12 Jan 2017 15:50:20 -0800 (PST)
************************************************************
15:50:21: INFO: Running cidb query on pid 5276, repr(query) starts with <sqlalchemy.sql.expression.Select at 0x363e1d0; Select object>
15:50:26: INFO: cidb query succeeded after 1 retries
15:50:26: INFO: Running cidb query on pid 5276, repr(query) starts with <sqlalchemy.sql.expression.Insert object at 0x3d80710>



 
Comment 1 by xixuan@chromium.org, Jan 13 2017
After debugging, some post processing operations in the func create_suite_job after a suite job is actually finished are suspicious to me for spending too much time. 

A CL (https://chromium-review.googlesource.com/427487) is ready for adding timestamp in logging these operations to see whether it's their fault or something wrong with cbuildbot side.

Owner: xixuan@chromium.org
Cc: jrbarnette@chromium.org
Richard was asking lots of questions about this, so cc'ing him.
Components: Infra>Client>ChromeOS
Project Member Comment 5 by bugdroid1@chromium.org, Jan 19 2017
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/a96bd217d89ef6e66f91d12f603ba54cc953ae8f

commit a96bd217d89ef6e66f91d12f603ba54cc953ae8f
Author: xixuan <xixuan@google.com>
Date: Fri Jan 13 04:51:22 2017

autotest: Add logging for further debugging a suite job's time cost

There's suspection that post operations after a suite job is actually finished
cost too much time. This CL aims to add timestamp for all post operations.

BUG=chromium:680793
TEST=None

Change-Id: I31f6be9f8f8749160d4ad0511db2a8f39a3a2edb
Reviewed-on: https://chromium-review.googlesource.com/427487
Commit-Ready: Xixuan Wu <xixuan@chromium.org>
Tested-by: Xixuan Wu <xixuan@chromium.org>
Reviewed-by: Don Garrett <dgarrett@chromium.org>

[modify] https://crrev.com/a96bd217d89ef6e66f91d12f603ba54cc953ae8f/site_utils/run_suite.py

Comment 6 by snanda@chromium.org, Jan 30 2017
Any more insights into this?  These delays are potentially increasing CQ run time by 20-30 minutes.

Here's an example of a "slow" run where bvt-inline stage completed in 60 minutes:
https://luci-logdog.appspot.com/v/?s=chromeos%2Fbb%2Fchromeos%2Fwolf-paladin%2F13278%2F%2B%2Frecipes%2Fsteps%2FHWTest__bvt-inline_%2F0%2Fstdout

** Start Stage HWTest [bvt-inline] - Sun, 29 Jan 2017 17:50:10 -0800 (PST)
...
Suite timings:
Downloads started at 2017-01-29 17:54:03
Payload downloads ended at 2017-01-29 17:54:10
Suite started at 2017-01-29 17:54:55
Artifact downloads ended (at latest) at 2017-01-29 17:54:57
Testing started at 2017-01-29 18:04:42
Testing ended at 2017-01-29 18:18:01
...
<snanda>: notice the 20 minute gap between testing ended and "Gathering timing stats..." message below.
01-29-2017 [18:38:35] Gathering timing stats for the suite job.
...
 01-29-2017 [18:42:41] Output below this line is for buildbot consumption:
** Finished Stage HWTest [bvt-inline] - Sun, 29 Jan 2017 18:50:46 -0800 (PST)




Here's an example of a "fast" run where bvt-inline stage completed in 36 minutes:

https://luci-logdog.appspot.com/v/?s=chromeos%2Fbb%2Fchromeos%2Fwolf-paladin%2F13273%2F%2B%2Frecipes%2Fsteps%2FHWTest__bvt-inline_%2F0%2Fstdout

** Start Stage HWTest [bvt-inline] - Sat, 28 Jan 2017 22:08:00 -0800 (PST)
...
Suite timings:
Downloads started at 2017-01-28 22:12:05
Payload downloads ended at 2017-01-28 22:12:13
Suite started at 2017-01-28 22:12:31
Artifact downloads ended (at latest) at 2017-01-28 22:12:35
Testing started at 2017-01-28 22:24:12
Testing ended at 2017-01-28 22:35:39
...
01-28-2017 [22:41:50] Gathering timing stats for the suite job.
...
 01-28-2017 [22:42:10] Output below this line is for buildbot consumption:
...
** Finished Stage HWTest [bvt-inline] - Sat, 28 Jan 2017 22:44:20 -0800 (PST)

Sign in to add a comment