1305134 - Windows artifact builds have an 80% of overhead on Buildbot

Status: RESOLVED WONTFIX

(Release Engineering :: General, defect)

Description

[Armen [:armenzg]]

This build job took 11 mins to build, however, the total time was 54 mins.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a47920a3a64b

On TaskCluster it took 44 mins (which is still a lot).

Comment 1

[Justin Wood (:Callek)]

Important here, is this is also *try* which clobbers completely every run.

The overhead is *all* within the mozharness run.

There is quite a bit of overhead (understandably?) with the repo clone itself:


 09:56:43     INFO - Running command: ['hg', '--config', 'ui.merge=internal:merge', '--config', 'extensions.robustcheckout=c:\\builds\\moz2_slave\\try-w64-0000000000000000000000\\scripts\\external_tools\\robustcheckout.py', 'robustcheckout', 'https://hg.mozilla.org/try', 'c:\\builds\\moz2_slave\\try-w64-0000000000000000000000\\build\\src', '--sharebase', 'C:/builds/hg-shared', '--purge', '--upstream', 'https://hg.mozilla.org/mozilla-central', '--revision', 'a47920a3a64b6caf4181baa4598c7543d3286f5f']
 09:56:43     INFO - Copy/paste: hg --config ui.merge=internal:merge --config extensions.robustcheckout=c:\builds\moz2_slave\try-w64-0000000000000000000000\scripts\external_tools\robustcheckout.py robustcheckout https://hg.mozilla.org/try c:\builds\moz2_slave\try-w64-0000000000000000000000\build\src --sharebase C:/builds/hg-shared --purge --upstream https://hg.mozilla.org/mozilla-central --revision a47920a3a64b6caf4181baa4598c7543d3286f5f
 09:58:37     INFO -  ensuring https://hg.mozilla.org/try@a47920a3a64b6caf4181baa4598c7543d3286f5f is available at c:\builds\moz2_slave\try-w64-0000000000000000000000\build\src
 09:58:37     INFO -  (cloning from upstream repo https://hg.mozilla.org/mozilla-central)
 09:58:37     INFO -  (sharing from existing pooled repository 8ba995b74e18334ab3707f27e9eb8f4e37ba3d29)
 09:58:37     INFO -  searching for changes
 09:58:37     INFO -  adding changesets
 09:58:37     INFO -  adding manifests
 09:58:37     INFO -  adding file changes
 09:58:37     INFO -  added 31 changesets with 70 changes to 66 files (-2 heads)
 09:59:20     INFO -  (pulling to obtain a47920a3a64b6caf4181baa4598c7543d3286f5f)
 09:59:20     INFO -  searching for changes
 09:59:20     INFO -  adding changesets
 09:59:20     INFO -  adding manifests
 09:59:20     INFO -  adding file changes
 09:59:20     INFO -  added 4 changesets with 6 changes to 6 files
 10:25:48     INFO -  147986 files updated, 0 files merged, 0 files removed, 0 files unresolved
 10:25:48     INFO -  updated to a47920a3a64b6caf4181baa4598c7543d3286f5f
 10:25:48 INFO - Return code: 0

Comment 2

[Gregory Szorc [:gps]]

The following line is important:

   09:58:37     INFO -  (sharing from existing pooled repository 8ba995b74e18334ab3707f27e9eb8f4e37ba3d29)

It means that most repo data has already been *cloned* to local disk. From the following lines:

   09:58:37     INFO -  searching for changes
   09:58:37     INFO -  adding changesets
   09:58:37     INFO -  adding manifests
   09:58:37     INFO -  adding file changes
   09:58:37     INFO -  added 31 changesets with 70 changes to 66 files (-2 heads)
   09:59:20     INFO -  (pulling to obtain a47920a3a64b6caf4181baa4598c7543d3286f5f)
   09:59:20     INFO -  searching for changes
   09:59:20     INFO -  adding changesets
   09:59:20     INFO -  adding manifests
   09:59:20     INFO -  adding file changes
   09:59:20     INFO -  added 4 changesets with 6 changes to 6 files

We only pulled down 35 new changesets. So 300,000+ changesets were already present in local storage.

What's taking all the time is this line:

  09:59:20     INFO -  added 4 changesets with 6 changes to 6 files
  10:25:48     INFO -  147986 files updated, 0 files merged, 0 files removed, 0 files unresolved

That's 26 minutes to effectively perform an `hg update` from a clean slate. That's horrible and seemingly indicates I/O on this instance is really bad.

Comment 3

[Gregory Szorc [:gps]]

The 26 minutes for `hg update` is almost certainly bug 1305174. Things should get better as a result of bug 1305485.