Closed
Bug 1293993
Opened 7 years ago
Closed 7 years ago
A bandaid fix: Very bad slowness with fsmonitor extension when I use |hg| in local comm-central repository
Categories
(MailNews Core :: Build Config, defect)
MailNews Core
Build Config
Tracking
(Not tracked)
RESOLVED
FIXED
People
(Reporter: ishikawa, Assigned: ishikawa)
References
Details
Attachments
(1 file, 2 obsolete files)
+++ This bug was initially created as a clone of Bug #1293688 +++ We need to change "^mozilla$" in .hgignore to "mozilla" as a bandaid. The patch attached does exactly that. --- the original bug Hi, I first reported this issue in dev-builds mailing list, but was advised to report the issue according to https://mozilla-version-control-tools.readthedocs.io/en/latest/hgmozilla/issues.html So here it goes. The time spent by fsmonitor extension is insane under mysetup. I have a serious slowdown issue if I enable fsmonitor extension when I use |hg| command in local comm-central repository for mozilla thunderbird debugging. * This is under Debian GNU/Linux. ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ uname -a Linux ip030 3.19.5 #1 SMP Mon Apr 20 08:50:21 JST 2015 x86_64 GNU/Linux I installed |watchman| myself following the instruction in https://facebook.github.io/watchman/docs/install.html after it was suggested by mozilla's |mozilla/mach mercurial-setup|. * The versions of watchman and hg commands. ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ which watchman /usr/local/bin/watchman ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ watchman --version 4.6.0 ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ hg --version Mercurial Distributed SCM (version 3.8.4) (see https://mercurial-scm.org for more information) Copyright (C) 2005-2016 Matt Mackall and others This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. Symptom: With "fsmonitor=" in my ~/.hgrc, even a simple operation like "hg identify" becomes VERY SLOW. Here is the data. I was advised to use "hg --profile ..." to show the culprit. WITHOUT |fsmonitor=" extension in ~/.hgrc. hg --profile identify 2d461abc3b18 qtip/tip/trychooser.patch CallCount Recursive Total(s) Inline(s) module:lineno(function) 1 0 0.1254 0.1254 <mercurial.osutil.statfiles> 8941 0 0.0366 0.0366 mercurial.dirstate:230(_join) 1 0 0.2035 0.0362 mercurial.dirstate:931(walk) 1 0 0.2224 0.0138 mercurial.dirstate:1093(status) 8 0 0.0113 0.0113 <open> 54 36 0.0120 0.0061 <__import__> 125 0 0.0052 0.0052 <method 'sort' of 'list' objects> 1 0 0.0076 0.0037 mercurial.tags:155(_readtaghist) 242 0 0.0025 0.0018 mercurial.util:490(__setitem__) 612 0 0.0018 0.0018 <method 'append' of 'list' objects> 197 176 0.0143 0.0018 mercurial.demandimport:127(__getattribute__) 247 0 0.0026 0.0016 encodings.utf_8:15(decode) 247 0 0.0041 0.0015 <method 'decode' of 'str' objects> 1 0 0.0015 0.0015 <mercurial.parsers.parse_dirstate> 244 0 0.0055 0.0014 mercurial.encoding:98(tolocal) 1 0 0.0439 0.0013 mercurial.localrepo:781(nodetags) 247 0 0.0010 0.0010 <_codecs.utf_8_decode> 264 0 0.0009 0.0009 <method 'split' of 'str' objects> 1 0 0.0271 0.0009 mercurial.localrepo:727(_findtags) 43 22 0.0132 0.0009 mercurial.demandimport:93(_load) 1 0 0.0012 0.0008 weakref:6(<module>) 236 0 0.0008 0.0008 <binascii.unhexlify> 50 9 0.0036 0.0007 mercurial.demandimport:138(_demandimport) 2 0 0.0007 0.0007 <function seed at 0x7f688f17fde8> 211 0 0.0006 0.0006 <method 'strip' of 'str' objects> 122 0 0.0006 0.0006 mercurial.util:520(iteritems) 1 0 0.0014 0.0006 mercurial.bookmarks:25(_getbkfile) 7 0 0.0015 0.0005 mercurial.pathutil:48(__call__) 25 0 0.0010 0.0005 hgext.mq:444(parselines) 69 3 0.0005 0.0005 <len> The command finishes more or less instantly. WITH |fsextension|: The story changes completely. See below. |vi| was used to edit ~/.hgrc to introduce |fsmonitor| extension. ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ vi ~/.hgrc ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ hg --profile identify 2d461abc3b18 qtip/tip/trychooser.patch CallCount Recursive Total(s) Inline(s) module:lineno(function) 409115 0 6.1069 6.1069 <method 'match' of '_sre.SRE_Pattern' objects> 1 0 18.5871 4.9341 hgext.fsmonitor:160(overridewalk) 1 0 25.3266 3.7346 mercurial.dirstate:1093(status) 409115 0 9.5124 3.4055 mercurial.match:177(__call__) 451526 0 1.7757 1.7757 stat:24(S_IFMT) 407588 0 1.5606 1.5606 mercurial.match:255(exact) 89 0 1.5434 1.5434 <method 'recv' of '_socket.socket' objects> 409394 0 1.4361 1.4361 <method 'append' of 'list' objects> 125 0 0.7597 0.7597 <method 'sort' of 'list' objects> 5 0 0.4036 0.4036 <method 'read' of 'file' objects> 3 0 0.2331 0.2331 <hgext.fsmonitor.pywatchman.bser.loads> 16 0 0.0638 0.0638 <method 'join' of 'str' objects> 291 0 0.0612 0.0612 <method 'split' of 'str' objects> 1 0 26.2786 0.0467 hgext.fsmonitor:672(status) 1 0 26.2319 0.0298 hgext.fsmonitor:385(overridestatus) 2 0 0.0263 0.0263 <posix.read> 7 0 0.0224 0.0224 <method 'write' of 'file' objects> 1 0 0.0219 0.0179 mercurial.match:644(readpatternfile) 71 42 0.0259 0.0177 <__import__> 363 0 0.0135 0.0121 sre_parse:141(__getitem__) 1 0 0.4748 0.0108 hgext.fsmonitor.state:34(get) 1 0 18.5947 0.0076 hgext.fsmonitor:521(walk) 1 0 0.0068 0.0068 hgext.fsmonitor:355(<genexpr>) 33 31 0.0276 0.0063 sre_parse:395(_parse) 89 0 1.5489 0.0054 hgext.fsmonitor.pywatchman:255(readBytes) 2 0 1.8187 0.0048 hgext.fsmonitor.pywatchman:645(receive) 1 0 0.0048 0.0048 <mercurial.parsers.parse_dirstate> 48 46 0.0095 0.0041 sre_compile:64(_compile) 1 0 0.0080 0.0040 mercurial.tags:155(_readtaghist) 1016 20 0.0036 0.0035 <len> Note that a single call to hgext.fsmonitor:672(status) takes more than 25 seconds!? But it gets worse. I thought maybe the initial watchman call needs to scan file system, and maybe the second invocation is faster. WRONG! Take a look at the following command that was issued immediately after the above command. The command took close to 4 minutes to finish!? ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ hg --profile identify 12d461abc3b18 qtip/tip/trychooser.patch CallCount Recursive Total(s) Inline(s) module:lineno(function) 407597 0 186.8931 51.2473 mercurial.pathutil:48(__call__) 3345432 0 67.0851 40.4870 mercurial.pathutil:15(_lowerclean) 5875675 0 22.3970 22.3970 <method 'lower' of 'str' objects> 3345432 0 13.8192 13.8192 mercurial.encoding:35(hfsignoreclean) 146454 0 28.2175 7.3300 mercurial.pathutil:103(_checkfs) 407588 0 6.1264 6.1264 <method 'match' of '_sre.SRE_Pattern' objects> 407588 0 192.4188 5.5275 mercurial.pathutil:123(check) 553677 0 7.8320 5.4805 posixpath:61(join) 407589 0 16.1859 5.3591 hgext.fsmonitor:341(<genexpr>) 1 0 214.2396 5.3533 hgext.fsmonitor:160(overridewalk) 554442 0 7.6899 4.8255 mercurial.util:1324(splitpath) 406983 0 6.2637 4.5897 mercurial.error:19(__init__) 407595 0 5.7975 4.0094 mercurial.util:1320(endswithsep) 1 0 220.9317 3.5174 mercurial.dirstate:1093(status) 407588 0 9.3439 3.2175 mercurial.match:177(__call__) 555801 0 2.9520 2.9520 <method 'split' of 'str' objects> 702985 0 2.9420 2.9420 <method 'endswith' of 'str' objects> 292688 0 3.4433 2.3227 stat:40(S_ISDIR) 406982 0 2.2465 2.2465 mercurial.i18n:59(gettext) 146463 0 2.1134 2.1134 <posix.lstat> 146454 0 5.4152 1.9556 genericpath:46(isdir) 439144 0 1.8019 1.8019 stat:24(S_IFMT) 441451 20 1.7185 1.7184 <len> 146462 0 1.6964 1.6964 <posix.stat> 407588 0 1.6800 1.6800 mercurial.match:255(exact) 407131 0 1.6745 1.6745 <method 'get' of 'dict' objects> 407595 0 1.6421 1.6421 posixpath:104(splitdrive) 407597 0 1.5279 1.5279 mercurial.pathutil:46(<lambda>) 407598 0 1.5097 1.5097 mercurial.posix:215(localpath) 407588 0 1.4829 1.4829 mercurial.util:835(always) I got a hunch that if the string manipulation may be slow, then setting the LANG to C may help. No, it did not. ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ export LANG=C ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ hg --profile identify 2d461abc3b18 qtip/tip/trychooser.patch CallCount Recursive Total(s) Inline(s) module:lineno(function) 407597 0 181.2793 50.2605 mercurial.pathutil:48(__call__) 3345432 0 65.8815 39.7872 mercurial.pathutil:15(_lowerclean) 5875675 0 21.9855 21.9855 <method 'lower' of 'str' objects> 3345432 0 13.4810 13.4810 mercurial.encoding:35(hfsignoreclean) 146454 0 26.8025 7.3963 mercurial.pathutil:103(_checkfs) 407588 0 5.9577 5.9577 <method 'match' of '_sre.SRE_Pattern' objects> 407588 0 186.7606 5.4827 mercurial.pathutil:123(check) 407589 0 16.1939 5.4682 hgext.fsmonitor:341(<genexpr>) 1 0 208.5775 5.3970 hgext.fsmonitor:160(overridewalk) 553677 0 7.8095 5.2245 posixpath:61(join) 554442 0 7.1670 4.5070 mercurial.util:1324(splitpath) 406983 0 5.7726 4.1663 mercurial.error:19(__init__) 1 0 215.6398 3.7169 mercurial.dirstate:1093(status) 407595 0 5.3541 3.6426 mercurial.util:1320(endswithsep) 407588 0 9.2424 3.2847 mercurial.match:177(__call__) 702985 0 3.0562 3.0562 <method 'endswith' of 'str' objects> 555801 0 2.7379 2.7379 <method 'split' of 'str' objects> 292688 0 3.2929 2.2264 stat:40(S_ISDIR) 406982 0 2.1041 2.1041 mercurial.i18n:59(gettext) 146454 0 4.7700 1.9103 genericpath:46(isdir) 407588 0 1.7964 1.7964 mercurial.match:255(exact) 439144 0 1.7210 1.7210 stat:24(S_IFMT) 441451 20 1.6745 1.6744 <len> 146463 0 1.6579 1.6579 <posix.lstat> 407595 0 1.6362 1.6362 posixpath:104(splitdrive) 407131 0 1.6068 1.6068 <method 'get' of 'dict' objects> 409528 0 1.5234 1.5234 <method 'append' of 'list' objects> 407588 0 1.4833 1.4833 mercurial.util:835(always) 407598 0 1.4750 1.4750 mercurial.posix:215(localpath) 407597 0 1.4577 1.4577 mercurial.pathutil:46(<lambda>) As I mention in my post to dev-builds, the overlaid independent repository of C-C and M-C (M-C being in the top-level ./mozilla directory of C-C repostitory) may not work well with fsmonotir extension since |hg| for C-C has to scan the separate M-C repository (under ./mozilla subdirectory) although hg's C-C repository should not care about ./mozilla subdirectory at all! TIA
|
Assignee | |
Comment 1•7 years ago
|
||
Here is the bandaid. TIA
Attachment #8779721 -
Flags: review?(bugspam.Callek)
|
||
Comment 2•7 years ago
|
||
Comment on attachment 8779721 [details] [diff] [review] Bandaid fix: replace ^mozilla$ with mozilla Review of attachment 8779721 [details] [diff] [review]: ----------------------------------------------------------------- ::: .hgignore @@ +24,5 @@ > ^objdir- > > # directories we check out from other repositories > ^directory/c-sdk$ > +# ^mozilla$ <--- does not work and causes performance issue. See Bug Bug 1293993 nit: It works, but regex's are not cheap and this one is an easy win: # ^mozilla$ <--- causes regex perf issues when present with fsmonitor. See Bug 1293993.
Attachment #8779721 -
Flags: review?(bugspam.Callek) → review+
|
|
Assignee | |
Comment 3•7 years ago
|
||
This patch is carrying over r=:Callek+, Modified the comment line to reflect what was pointed out in previous message. I would put check-needed keyword. TIA
Assignee: nobody → ishikawa
Attachment #8779721 -
Attachment is obsolete: true
Attachment #8779737 -
Flags: review+
|
|
Assignee | |
Updated•7 years ago
|
Keywords: checkin-needed
|
||
Comment 4•7 years ago
|
||
+# ^mozilla$ <--- causes regex perf issues when present with fsmonitor. See Bug +1293993. Is that line break intended?
Flags: needinfo?(ishikawa)
|
|
||
Updated•7 years ago
|
Keywords: checkin-needed
|
|
Assignee | |
Comment 5•7 years ago
|
||
(In reply to Ryan VanderMeulen [:RyanVM] from comment #4) > +# ^mozilla$ <--- causes regex perf issues when present with fsmonitor. See > Bug > +1293993. > > Is that line break intended? NO! Thank you for spotting it. I am re-creating a quick fix.
Flags: needinfo?(ishikawa)
|
|
Assignee | |
Comment 6•7 years ago
|
||
Removed the unwanted newline. The newline did not cause any syntax break, etc. and the |hg| peformance improved with |fsmonitor| extension even if it did exisit. Thus I didn't realize it. Sorry about it. But this should be OK now.
Attachment #8779737 -
Attachment is obsolete: true
Attachment #8781405 -
Flags: review+
|
|
Assignee | |
Comment 7•7 years ago
|
||
I put checkin-needed keyword again. BTW, I have to look twice when I check the diff listing. the line is wrapped in the unfortunate place on my screen. The raw listing does show the newline is removed and the comment is one intact line now. TIA
Keywords: checkin-needed
|
|
||
Comment 8•7 years ago
|
||
https://hg.mozilla.org/comm-central/rev/9a21e0f90e41 This really doesn't feel like the right component for this bug, but oh well.
|
|
||
Comment 9•7 years ago
|
||
(In reply to Ryan VanderMeulen [:RyanVM] from comment #8) > https://hg.mozilla.org/comm-central/rev/9a21e0f90e41 > > This really doesn't feel like the right component for this bug, but oh well. Moving for where patch is
Component: Mercurial: hg.mozilla.org → Build Config
Product: Developer Services → MailNews Core
QA Contact: hwine
Version: unspecified → Trunk
You need to log in
before you can comment on or make changes to this bug.
Description
•