1304791 - HG 3.9.1 Poor performance on Windows Builders

Status: RESOLVED FIXED

(Infrastructure & Operations :: RelOps: General, task)

Description

[Mark Cornmesser [:markco]]

As is with the current configuration files HG 3.9.1 is performing poorly on Windows 2008. 

Current config file: 
; This Source Code Form is subject to the terms of the Mozilla Public
; License, v. 2.0. If a copy of the MPL was not distributed with this
; file, You can obtain one at http://mozilla.org/MPL/2.0/.

[diff]
git=True
showfunc=True
ignoreblanklines=True

[format]
dotencode=False

[ui]
username = Mozilla Release Engineering <[e-mail]>
traceback = True

[worker]
backgroundclose=false

[extensions]
share=
rebase=
mq=
purge=

[hostfingerprints]
hg.mozilla.org = af:27:b9:34:47:4e:e5:98:01:f6:83:2b:51:c9:aa:d8:df:fb:1a:27
ftp-ssl.mozilla.org = 9d:8e:3e:7c:4a:33:6f:53:c6:64:a8:48:d3:ea:72:05:f0:73:a4:90

[web]
cacerts = /etc/mercurial/cacert/cacert.pem


First clone: 
C:\Users\Administrator>hg clone https://hg.mozilla.org/mozilla-central/ test01
applying clone bundle from https://s3-external-1.amazonaws.com/moz-hg-bundles-us
-east-1/mozilla-central/560b2c805bf7bebeb3ceebc495a81b2aa4c0c755.packed1.hg
264006 files to transfer, 1.78 GB of data
transferred 1.78 GB in 1489.3 seconds (1.22 MB/sec)
finished applying clone bundle
searching for changes
adding changesets
adding manifests
adding file changes
added 187 changesets with 983 changes to 680 files
updating to branch default
updating [===================>                          ]  65800/147960 10m39s


The default installation does not include the mercurial.ini file and relies on the  C:\mozilla-build\hg\hgrc.d\Mercurial.rc file for configuration. The default install in this case without the mercurial.ini file first clone is multiple times longer than with the ini file.

Comment 1

[Mark Cornmesser [:markco]]

GPS: Do you any suggestions?

Comment 2

[Gregory Szorc [:gps]]

Is this a regression? If so, can you quantify the regression?

Comment 3

[Mark Cornmesser [:markco]]

Regression version wise?  No, we are moving from version 3.7.3 to 3.9.1.

Comment 4

[Mark Cornmesser [:markco]]

There is a regression speed wise. Current instances running 3.7.3 takes about a third of the time:

C:\Users\Administrator>hg clone https://hg.mozilla.org/mozilla-central/ test0
applying clone bundle from https://s3-external-1.amazonaws.com/moz-hg-bundles-us
-east-1/mozilla-central/560b2c805bf7bebeb3ceebc495a81b2aa4c0c755.packed1.hg
264006 files to transfer, 1.78 GB of data
transferred 1.78 GB in 508.7 seconds (3.59 MB/sec)
finished applying clone bundle
searching for changes
adding changesets
adding manifests
adding file changes
added 213 changesets with 1070 changes to 737 files
updating to branch default
updating [===============>                               ]  50500/147960 2m01s

Comment 5

[Gregory Szorc [:gps]]

I'm unable to reproduce this performance regression on Windows 10.

I recall investigating a similar performance problem a few months ago. I think there's something about Windows Server 2008 on AWS that makes things especially bad. I think the I/O performance is just horrible. Now what I'm not sure of is why Mercurial 3.9 is slower than 3.7 in this scenario. I'd have to profile a running process to find out more.

Out of curiosity, does Windows Server 2012 exhibit the same regression?

Is there a public AMI I can use to reproduce? If not, can you give me remote desktop credentials to an instance (preferably in a us-west region)?

FWIW, as long as we're doing optimal repository cloning (using `hg robustclone` with a shared store), we won't have to clone repos that frequently. So hopefully this isn't a huge problem.

Comment 6

[Gregory Szorc [:gps]]

I suspect a lot of the perf issues are related to bug 1305174. And, depending on how the 3.7 versus 3.9 benchmark was conducted, that bug could fully account for performance discrepancies.

Comment 7

[Gregory Szorc [:gps]]

Bug 1305174 may not be the only source of Mercurial slowdown in Windows automation. It also appears our EBS IOPS are throttling Mercurial. I stood up my own EC2 instance. It appears that existing IOPS on a new EBS volume contribute to Mercurial operations that are *several minutes* slower than with higher IOPS.

An `hg update central` from a clean slate takes ~467s using existing IOPS. With a provisioned IOPS ssd @ 10000 IOPS, it takes ~144s.

Also, modern versions of Mercurial have a Windows-specific feature where they close written files on a background thread by default. This is because closing file handles is often slow on Windows. We disabled this behavior in bug 1259484 because it was measured to make things slower. However, on an instance with high enough IOPS for IOPS to not be the bottleneck, background file closing appears to have a negligible effect on performance. This makes sense: the big wins from background closing are when anti virus (such as Windows Defender) is running.

I even benchmarked Git. It too is much slower with the existing IOPS. Both Git and Mercurial had similar working directory checkout times on Windows (~470s). This should not happen: Git should be faster because Git uses multiple threads for checkout whereas Mercurial doesn't on Windows (Mercurial does use multiple processes on Linux and OS X). Bumping the IOPS made `git clone --shared` take ~60s. (Mercurial only improved to ~144s.)

Comment 8

[Gregory Szorc [:gps]]

The numbers in comment #7 were from a Windows Server 2008 instance running on a c4.2xlarge.

On Windows Server 2012, I/O appears faster on the root EBS volume. `hg update central` from a clean slate takes ~227s. Contrast with ~467s on Windows Server 2008. Still not as good as ~144s on the provisioned IOPS ssd, but much more reasonable.

Comment 9

[Gregory Szorc [:gps]]

Ignore comment #8 for the moment: the root EBS volumes are different sizes and that means they may have different IOPS. I'll have to use better science.

Comment 10

[Gregory Szorc [:gps]]

I obtained a c4.xlarge instance and measured the performance of `hg debugapplystreamclonebundle` against a mozilla-unified bundle file with Mercurial version 3.7.4, 3.8.3, and 3.9.1. This command essentially performs the clone part of `hg robustcheckout` (not the update update). (This is the "transferred 1.78 GB in 1489.3 seconds (1.22 MB/sec)" message from logs.) It is a good measure of how fast we can write 100,000+ files to disk. I measured behavior on a fresh EBS volume so bug 1305174 didn't come into play. The EBS volume was a SSD with 10000 provisioned IOPS. I performed multiple measurements and took the best timings.

Mercurial versions 3.7.4, 3.8.3, and 3.9.1 *all exhibited the same time for `hg debugapplystreamclonebundle`*: ~100s.

This tells me that the "regression" against Mercurial 3.9 identified in this bug is not in Mercurial itself. Instead, I reckon it is related to bug 1305174. It is quite possible the perceived regression is due to looking at numbers from a freshly provisioned instance and comparing them to an initialized one - one whose root EBS has had time to warm up.

I believe there is no actual performance regression caused by Mercurial and that it is safe to roll out Mercurial 3.9 to our Windows automation.

Comment 11

[Mark Cornmesser [:markco]]

Excerpt from : http://buildbot-master75.bb.releng.use1.mozilla.com:8101/builders/WINNT%206.1%20x86-64%20try%20build/builds/1377/steps/run_script/logs/stdio

17:46:48     INFO -  checking Mercurial version (3.9.1)
17:46:48     INFO -  checking Mercurial custom build ()
17:46:48     INFO -  checking module policy (c)
17:46:48     INFO -  checking installed modules (c:\mozilla-build\hg\lib\library.zip\mercurial)...
17:46:48     INFO -  checking templates (c:\mozilla-build\hg\templates)...
17:46:48     INFO -  checking default template (c:\mozilla-build\hg\templates\map-cmdline.default)
17:46:48     INFO -  checking commit editor... (notepad)
17:46:48     INFO -  checking username (Mozilla Release Engineering <[e-mail]>)
17:46:48     INFO -  no problems detected
17:46:48     INFO - Return code: 0
17:46:48     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/build/tools', 'c:\\builds\\moz2_slave\\try-w64-0000000000000000000000\\build\\tools', '--sharebase', 'C:/builds/hg-shared', '--branch', 'default']
17:46:48     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/build/tools c:\builds\moz2_slave\try-w64-0000000000000000000000\build\tools --sharebase C:/builds/hg-shared --branch default
17:47:05     INFO -  
17:47:05     INFO - clone [>                                             ]   764050/28653606 1m17s
17:47:05     INFO - clone [==>                                             ]  1943698/28653606 43s
17:47:05     INFO - clone [======>                                         ]  4553586/28653606 23s
17:47:05     INFO - clone [===============>                                ]  9918291/28653606 11s
17:47:05     INFO - clone [=======================>                        ] 14738866/28653606 07s
17:47:05     INFO - clone [=============================>                  ] 18070226/28653606 05s
17:47:05     INFO - clone [=============================>                  ] 18076131/28653606 06s
17:47:05     INFO - clone [====================================>           ] 22156532/28653606 04s
17:47:05     INFO -                                                                                
17:47:05     INFO - ensuring https://hg.mozilla.org/build/tools@default is available at c:\builds\moz2_slave\try-w64-0000000000000000000000\build\tools
17:47:05     INFO -  (sharing from new pooled repository 7ae7fb134bf7aec6ec96a062ff47a69053dd2973)
17:47:05     INFO -  applying clone bundle from https://s3-external-1.amazonaws.com/moz-hg-bundles-us-east-1/build/tools/989dc087e8b355a3dd64f9da4f6002a0a363b156.packed1.hg
17:47:05     INFO -  2021 files to transfer, 27.3 MB of data
17:47:05     INFO -  transferred 27.3 MB in 10.7 seconds (2.55 MB/sec)
17:47:05     INFO -  finished applying clone bundle
17:47:05     INFO -  searching for changes
17:47:05     INFO -  adding changesets
17:47:05     INFO -  adding manifests
17:47:05     INFO -  adding file changes
17:47:05     INFO -  added 2 changesets with 2 changes to 2 files

Yes, I think we are good.