Very bad slowness with fsmonitor extension when I use |hg| in local comm-central repository

RESOLVED WONTFIX

Status

Developer Services
Mercurial: hg.mozilla.org
RESOLVED WONTFIX
2 years ago
2 years ago

People

(Reporter: ISHIKAWA, Chiaki, Unassigned)

Tracking

Details

(Reporter)

Description

2 years ago
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
(Reporter)

Updated

2 years ago
See Also: → bug 1277442

Comment 1

2 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
Last Resolved: 2 years ago
Resolution: --- → WONTFIX
(Reporter)

Comment 2

2 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
(Reporter)

Updated

2 years ago
Blocks: 1293993
You need to log in before you can comment on or make changes to this bug.