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

RESOLVED FIXED

Status

defect
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: ishikawa, Assigned: ishikawa)

Tracking

Trunk
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 2 obsolete attachments)

Assignee

Description

3 years ago
+++ 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

3 years ago
Here is the bandaid.
TIA
Attachment #8779721 - Flags: review?(bugspam.Callek)
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

3 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

3 years ago
Keywords: checkin-needed
+# ^mozilla$ <--- causes regex perf issues when present with fsmonitor. See Bug
+1293993.

Is that line break intended?
Flags: needinfo?(ishikawa)
Assignee

Comment 5

3 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

3 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

3 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
https://hg.mozilla.org/comm-central/rev/9a21e0f90e41

This really doesn't feel like the right component for this bug, but oh well.
Status: NEW → RESOLVED
Closed: 3 years ago
Keywords: checkin-needed
Resolution: --- → FIXED
(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.