Most tryjob builders are building most of chromeos-chrome TWICE in BuildPackages |
|||
Issue descriptionI just noticed that most of the tryjob builders seem to have a lot of "refresh" error in the BuildPackages stage, with error messages of the form: 19:51:08: INFO: Refreshing due to a 401 (attempt 1/2) 19:51:09: INFO: Refreshing access_token This is a particular problem because this tends to happen during the build of chromeos-chrome. Often chromeos-chrome will have nearly finished building before the refresh error and will then start building all over again after the refresh, resulting in our building nearly all of chromeos-chrome TWICE in almost every tryjob (thus making BuildPackages take much longer than it should). Below is a link to the job where I happened to notice this. I have also pasted the important part of the log just below the URL: Notice that we have gotten all the way up to compiling item 39699 (out of 45864) before the refresh error, and after the refresh error we resume (start over!) with compiling item 952 (out of 45864). https://luci-logdog.appspot.com/v/?s=chromeos/buildbucket/cr-buildbucket.appspot.com/8939271946480426400/+/steps/BuildPackages__afdo_use_/0/stdout chromeos-chrome-70.0.3508.3_rc-r1: [39699/45864] CXX obj/third_party/blink/renderer/bindings/core/v8/bindings_core_impl/v8_svg_fe_specular_lighting_element.o[K chromeos-chrome-70.0.3508.3_rc-r1: [39699/45864] CXX obj/third_party/blink/renderer/bindings/core/v8/bindings_core_impl/v8_svg_text_positioning_element.o[K === Still running: job chromeos-chrome-70.0.3508.3_rc-r1 (180m16.7s) === Still building chromeos-chrome-70.0.3508.3_rc-r1 (181m16.8s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:10:37 | Elapsed 230m41.1s | Load 32.19 32.19 32.87] Still building chromeos-chrome-70.0.3508.3_rc-r1 (183m16.9s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:12:37 | Elapsed 232m41.2s | Load 32.11 32.16 32.77] Still building chromeos-chrome-70.0.3508.3_rc-r1 (185m17.0s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:14:38 | Elapsed 234m41.3s | Load 32.09 32.14 32.69] Still building chromeos-chrome-70.0.3508.3_rc-r1 (187m17.1s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:16:38 | Elapsed 236m41.3s | Load 32.01 32.09 32.6] Still building chromeos-chrome-70.0.3508.3_rc-r1 (189m17.2s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:18:38 | Elapsed 238m41.4s | Load 32.02 32.07 32.53] Still building chromeos-chrome-70.0.3508.3_rc-r1 (191m17.2s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:20:38 | Elapsed 240m41.5s | Load 32.0 32.04 32.46] Still building chromeos-chrome-70.0.3508.3_rc-r1 (193m17.3s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:22:38 | Elapsed 242m41.6s | Load 32.0 32.02 32.4] Still building chromeos-chrome-70.0.3508.3_rc-r1 (195m17.4s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:24:38 | Elapsed 244m41.7s | Load 32.15 32.07 32.36] Still building chromeos-chrome-70.0.3508.3_rc-r1 (197m17.5s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:26:38 | Elapsed 246m41.8s | Load 32.18 32.09 32.33] Still building chromeos-chrome-70.0.3508.3_rc-r1 (199m17.6s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:28:38 | Elapsed 248m41.9s | Load 32.02 32.05 32.29] Still building chromeos-chrome-70.0.3508.3_rc-r1 (201m17.7s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:30:38 | Elapsed 250m42.0s | Load 32.13 32.06 32.26] Still building chromeos-chrome-70.0.3508.3_rc-r1 (203m17.8s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:32:38 | Elapsed 252m42.1s | Load 32.13 32.08 32.24] Still building chromeos-chrome-70.0.3508.3_rc-r1 (205m17.9s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:34:39 | Elapsed 254m42.2s | Load 32.15 32.11 32.23] Still building chromeos-chrome-70.0.3508.3_rc-r1 (207m18.0s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:36:39 | Elapsed 256m42.3s | Load 32.1 32.08 32.2] Still building chromeos-chrome-70.0.3508.3_rc-r1 (209m18.1s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:38:39 | Elapsed 258m42.4s | Load 32.03 32.08 32.18] Still building chromeos-chrome-70.0.3508.3_rc-r1 (211m18.2s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:40:39 | Elapsed 260m42.5s | Load 32.12 32.13 32.18] Still building chromeos-chrome-70.0.3508.3_rc-r1 (213m18.3s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:42:39 | Elapsed 262m42.6s | Load 31.99 32.07 32.15] Still building chromeos-chrome-70.0.3508.3_rc-r1 (215m18.4s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:44:39 | Elapsed 264m42.7s | Load 32.01 32.05 32.14] Still building chromeos-chrome-70.0.3508.3_rc-r1 (217m18.5s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:46:39 | Elapsed 266m42.8s | Load 32.19 32.1 32.14] Still building chromeos-chrome-70.0.3508.3_rc-r1 (219m18.6s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:48:39 | Elapsed 268m42.9s | Load 32.06 32.08 32.12] Still building chromeos-chrome-70.0.3508.3_rc-r1 (221m18.7s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:50:39 | Elapsed 270m43.0s | Load 32.03 32.06 32.11] 19:51:08: INFO: Refreshing due to a 401 (attempt 1/2) 19:51:09: INFO: Refreshing access_token Still building chromeos-chrome-70.0.3508.3_rc-r1 (223m18.8s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK 19:52:22: INFO: Refreshing due to a 401 (attempt 1/2) 19:52:22: INFO: Refreshing access_token Pending 16/729, Building 1/1, [Time 19:52:39 | Elapsed 272m43.1s | Load 32.18 32.11 32.11] Still building chromeos-chrome-70.0.3508.3_rc-r1 (225m18.9s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK 19:54:02: INFO: Refreshing due to a 401 (attempt 1/2) 19:54:02: INFO: Refreshing access_token Pending 16/729, Building 1/1, [Time 19:54:39 | Elapsed 274m43.2s | Load 32.11 32.12 32.11] Still building chromeos-chrome-70.0.3508.3_rc-r1 (227m19.0s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:56:40 | Elapsed 276m43.3s | Load 32.07 32.1 32.1] Still building chromeos-chrome-70.0.3508.3_rc-r1 (229m19.1s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 19:58:40 | Elapsed 278m43.4s | Load 32.22 32.13 32.1] Still building chromeos-chrome-70.0.3508.3_rc-r1 (231m19.2s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 20:00:40 | Elapsed 280m43.5s | Load 32.03 32.08 32.09] Still building chromeos-chrome-70.0.3508.3_rc-r1 (233m19.3s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 20:02:40 | Elapsed 282m43.6s | Load 32.0 32.05 32.07] Still building chromeos-chrome-70.0.3508.3_rc-r1 (235m19.4s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 20:04:40 | Elapsed 284m43.7s | Load 32.0 32.03 32.06] Still building chromeos-chrome-70.0.3508.3_rc-r1 (237m19.5s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK Pending 16/729, Building 1/1, [Time 20:06:40 | Elapsed 286m43.8s | Load 32.01 32.03 32.06] Still building chromeos-chrome-70.0.3508.3_rc-r1 (239m19.6s). Logs in /tmp/chromeos-chrome-70.0.3508.3_rc-r1-0aQ2aK === Continue output for job chromeos-chrome-70.0.3508.3_rc-r1 (240m19.6s) === chromeos-chrome-70.0.3508.3_rc-r1: iver/embed_version_in_cpp.stamp[K chromeos-chrome-70.0.3508.3_rc-r1: [952/45864] STAMP obj/chrome/test/chromedriver/embed_version_in_cpp.stamp[K chromeos-chrome-70.0.3508.3_rc-r1: [952/45864] ACTION //chromeos/assistant:buildflags(//build/toolchain/cros:target)[K chromeos-chrome-70.0.3508.3_rc-r1: [953/45864] ACTION //chromeos/assistant:buildflags(//build/toolchain/cros:target)[K Just out of curiosity, I randomly chose two other trybot builds and I see the same kind of thing happening in both of them as well (the chromeos-chrome build being intertupted in the middle with a "Refreshing due to a 401 " message, and then resuming at a MUCH earlier stage (the second example below "only" loses about 3600 compilations, but the first one below is very similar to the one above, where we basically end up building all of chromeos-chrome a second time. https://luci-logdog.appspot.com/v/?s=chromeos/buildbucket/cr-buildbucket.appspot.com/8939502481198392368/+/steps/BuildPackages__afdo_use_/0/stdout https://luci-logdog.appspot.com/v/?s=chromeos/buildbucket/cr-buildbucket.appspot.com/8939502163394299824/+/steps/BuildPackages__afdo_use_/0/stdout And the log below shows an EXTREME case, where we end up re-build nearly all of chromeos-chrome ** 4 TIMES ** !!! It builds [0/45864] to [22654/45864], then hits a refresh, then builds from [923/45864 to 33923/45864], hits ANOTHER refresh, then builds from [923/45864] to [40348/45864], hits YET ANOTHER refresh, then builds from [924/45864] to [45864/45864]. This is an EXTREME waste of time/resources. Please investigate this. https://luci-logdog.appspot.com/v/?s=chromeos/buildbucket/cr-buildbucket.appspot.com/8939259760772495280/+/steps/BuildPackages__afdo_use_/0/stdout
,
Aug 3
Ok, maybe I'm mis-reading the logs, but...the release builders take an average of 3 hours to build all of chrome os. The tryjob builders take an average iof 7.5 to 8 hours to build all of Chrome OS. The BuildPackages phase of the log that looks like it's building Chrome 4 times took 5.5 hours, all by itself. That seems way too long. I was looking into the log to try to figure out why it was taking so very long, and the apparent multiple builds of pieces of Chrome was the best I could find...
,
Aug 3
Additional note: According to the time stamps in that log, it started first trying to build chromeos-chrome around 19:30 and it finished building chromeos-chrome around 00:00... 4.5 hours just to build Chrome is VERY long, unless something wonky is going on.
,
Aug 3
If this happens with "--latest-toolchain" only, then one reason for slow Chrome builds could be because of extra time consumed in goma local fallover handling to the compiler in chroot.
,
Aug 6
I'm not sure about the slowdown, generally, but indeed refresh is just log noise and has no impact on builds. Moving to the Build component and setting as P2 if you want to continue to investigate.
,
Aug 6
Actually I think comment #4 is correct; the tryjobs I looked at were not using goma, becasue of --latest-toolchain. I will close this. Sorry for the bother.
,
Aug 7
still 8 hours for a full is very slow. I think this used to take 4 or 5 hours. I assume this is because the builders are not as powerful as they used to be. Is there a way to force a tryjob to build on a more powerful builder?
,
Aug 9
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/toolchain-utils/+/f4799966c4c6639ffc619a02e3ccdd2a501379f9 commit f4799966c4c6639ffc619a02e3ccdd2a501379f9 Author: Luis A. Lozano <llozano@google.com> Date: Thu Aug 09 03:46:07 2018 Increase timeout for slower builders. Some of our slower builder (with latest_toolchain) are taking around 8 hours. This CL increases the timeout for such situations. BUG= chromium:870916 TESTS=None Change-Id: I8c15e4ecbd71f76bca65c6adcabd74df8da79660 Reviewed-on: https://chromium-review.googlesource.com/1167965 Commit-Ready: Luis Lozano <llozano@chromium.org> Tested-by: Luis Lozano <llozano@chromium.org> Reviewed-by: Manoj Gupta <manojgupta@chromium.org> [modify] https://crrev.com/f4799966c4c6639ffc619a02e3ccdd2a501379f9/cros_utils/buildbot_utils.py |
|||
►
Sign in to add a comment |
|||
Comment 1 by manojgupta@chromium.org
, Aug 3