Closed
Bug 1293688
Opened 8 years ago
Closed 8 years ago
Very bad slowness with fsmonitor extension when I use |hg| in local comm-central repository
Categories
(Developer Services :: Mercurial: hg.mozilla.org, defect)
Developer Services
Mercurial: hg.mozilla.org
Tracking
(Not tracked)
RESOLVED
WONTFIX
People
(Reporter: ishikawa, Unassigned)
References
Details
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
Comment 1•8 years ago
|
||
This is an upstream bug. I filed it at https://bz.mercurial-scm.org/show_bug.cgi?id=5322. As a workaround, have comm-central change the .hgignore entry for "^mozilla$" to just "mozilla".
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → WONTFIX
Reporter | ||
Comment 2•8 years ago
|
||
Oh thank you. I was about to report the following since I will be away from PC for several days. I edited my .hgignore under comm-central top-level directory to contain mozilla IN ADDITION TO ^mozilla$, and now hg identify finishes in a reasonable time. Thank you! --- I will be away from my computer starting tomorrow until Sunday evening so I add some information here: On my machine, the pertinent system setting for inotify is as follows: cat /proc/sys/fs/inotify/max_user_watches 524288 ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ cat /proc/sys/fs/inotify/max_user_instances 128 ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ cat /proc/sys/fs/inotify/max_queued_events 16384 ishikawa@ip030:/NREF-COMM-CENTRAL/comm-central$ My posting to dev-builds is at https://groups.google.com/forum/#!topic/mozilla.dev.builds/DGC-53pD9iM TIA
You need to log in
before you can comment on or make changes to this bug.
Description
•