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.

Richard was asking lots of questions about this, so cc'ing him.

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

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)

Issue has not been modified or commented on in the last 365 days, please re-open or file a new bug if this is still an issue.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot