1413760 - fsmonitor somehow doesn't seem to be enabled by default on Windows

Status: RESOLVED DUPLICATE of bug 1413360

(Developer Services :: Mercurial: configwizard, defect)

Description

[Xidorn Quan [:xidorn] UTC+10]

So... I've been confused for quite a while why my local mercurial repo is so slow given that I already have watchman installed and fsmonitor extension enabled.

So I did a profile, and see this:
> $ hg status --profile
> | 100.0%  dispatch.py:    _callcatch               line 45:  mercurial.dispatch.run()
> | 100.0%  scmutil.py:     callcatch                line 310:  return scmutil.callcatch(ui...
> | 100.0%  dispatch.py:    _runcatchfunc            line 150:  return func()
> | 100.0%  extensions.py:  loadall                  line 292:  return _dispatch(req)
> | 94.0%  commands.py:    status                    line 3546:  return orig(ui, repo, *args...
> | 94.0%  localrepo.py:   status                    line 4742:  opts.get('subrepos'))
> | 94.0%  context.py:     status                    line 2043:  listsubrepos)
> | 94.0%  context.py:     _buildstatus              line 357:  listunknown)
> | 93.6%  context.py:     _dirstatestatus           line 1782:  s = self._dirstatestatus(ma...
> | 93.1%  dirstate.py:    status                    line 1715:  listclean, listunknown)
> | 86.7%  dirstate.py:    walk                      line 1228:  full=full).iteritems():
> | 83.5%  dirstate.py:    traverse                  line 1134:  traverse([d], alreadynormed)
>  \ 30.7%  dirstate.py:    _normalizefile           line 1106:  True)
>    | 16.5%  windows.py:     normcase               line 689:  normed = util.normcase(path)
>    |  9.6%  encoding.py:    upper                  line 245:  return encoding.upper(path)...
>  \  6.4%  match.py:       __call__                 line 1111:  if not ignore(nf):
>    |  5.5%  match.py:       <lambda>               line 239:  return self.matchfn(fn)
> ---
> Sample count: 1579
> Total time: 3.406250 seconds

So lots of time is taken in traverse, which doesn't make sense at all.

Then I add
> [fsmonitor]
> mode = on
to my ~/.hgrc, and reprofile, it's now:
> $ hg status --profile
> | 100.0%  dispatch.py:    _callcatch               line 45:  mercurial.dispatch.run()
> | 100.0%  scmutil.py:     callcatch                line 310:  return scmutil.callcatch(ui...
> | 100.0%  dispatch.py:    _runcatchfunc            line 150:  return func()
> | 100.0%  profiling.py:   __enter__                line 292:  return _dispatch(req)
>  \ 63.9%  commands.py:    status                   line 3546:  return orig(ui, repo, *args...
>    | 63.9%  __init__.py:    status                 line 4742:  opts.get('subrepos'))
>    | 63.9%  __init__.py:    overridestatus         line 710:  return overridestatus(orig,...
>    | 61.1%  localrepo.py:   status                 line 493:  listsubrepos)
>    | 61.1%  context.py:     status                 line 2043:  listsubrepos)
>    | 61.1%  context.py:     _buildstatus           line 357:  listunknown)
>    | 61.1%  context.py:     _dirstatestatus        line 1782:  s = self._dirstatestatus(ma...
>      \ 30.6%  dirstate.py:    status               line 1715:  listclean, listunknown)
>        | 30.6%  __init__.py:    walk               line 1228:  full=full).iteritems():
>        | 30.6%  __init__.py:    overridewalk       line 551:  return overridewalk(orig, s...
>          \ 16.7%  __init__.py:    <genexpr>        line 357:  notefiles = set((normalize(...
>          \ 11.1%  state.py:       get              line 188:  clock, ignorehash, notefile...
>      \ 27.8%  context.py:     _poststatusfixup     line 1727:  self._poststatusfixup(s, fi...
>        \ 19.4%  dirstate.py:    identity           line 1678:  if self._repo.dirstate.iden...
>          | 19.4%  util.py:        __get__          line 773:  return self._identity
>          |  8.3%  dirstate.py:    _identity        line 823:  result = self.func(obj)
>          |  8.3%  dirstate.py:    _read            line 160:  self._read()
>        \  5.6%  __init__.py:    __call__           line 1692:  ps(self, status)
>          |  5.6%  state.py:       set              line 537:  wctx.repo()._fsmonitorstate...
>  \ 16.7%  extensions.py:  load                     line 216:  load(ui, name, path)
>    | 16.7%  extensions.py:  _importext             line 157:  mod = _importext(name, path...
>      \  8.3%  extensions.py:  loadpath             line 102:  mod = loadpath(path, 'hgext...
>        |  5.6%  client.py:      <module>           line 83:  return imp.load_source(modu...
>        |  5.6%  proto.py:       <module>           line 64:  import hgrb.proto
>        |  5.6%  xmlrpclib.py:   <module>           line 7:  import xmlrpclib
>        |  5.6%  httplib.py:     <module>           line 145:  import httplib
>      \  5.6%  extensions.py:  _importh             line 105:  mod = _importh("hgext.%s" %...
>        |  5.6%  demandimportpy2.py: _demandimport  line 91:  mod = __import__(pycompat.s...
>        |  5.6%  demandimportpy2.py: _hgextimport   line 168:  return _hgextimport(_origim...
>        |  5.6%  mq.py:          <module>           line 42:  return importfunc(name, glo...
>  \  5.6%  blackbox.py:    _openlogfile             line 167:  self._bbfp = self._openlogf...
>    |  5.6%  blackbox.py:    _openlog               line 135:  fp = _openlog(self._bbvfs)
>    |  5.6%  vfs.py:         __call__               line 82:  filehandles[path] = fp = vf...
>    |  5.6%  util.py:        checknlink             line 402:  self._trustnlink = nlink > ...
> ---
> Sample count: 155
> Total time: 0.562500 seconds

which really seems to be a reasonable time with fsmonitor enabled, then.

So it seems even if fsmonitor is listed in [extensions], it isn't enabled by default somehow. It is also possible that it runs in paranoid mode by default on Windows, which isn't really helpful for performance.

Maybe configwizard should add fsmonitor.mode=on for Windows, so that fsmonitor actually gets enabled and benefit developers.

(I had a look at the fsmonitor extension code in mercurial's repo, but didn't find anything which indicates this behavior, so I'm quite confused. But from experimental locally, it's clearly shows big difference with/without fsmonitor.mode getting set explicitly.)

Comment 1

[Gregory Szorc [:gps]]

RyanVM is going to fix this in the next MozillaBuild release.

RyanVM: what do you want to do with this bug?

Comment 2

[Xidorn Quan [:xidorn] UTC+10]

How is it related to MozillaBuild, actually? Isn't this related to mercurial settings?

Comment 3

[Ryan VanderMeulen [:RyanVM]]

Seems like a dupe of bug 1413360 to me unless there's something you want to do in the land of mercurial-setup. In the mean time, all the needs to be done to enable fsmonitor with MozillaBuild 3.0 is to change one line in mercurial.ini:
https://hg.mozilla.org/mozilla-build/rev/b7a025509390

Comment 4

[Xidorn Quan [:xidorn] UTC+10]

Oh, okay, so it was explicitly disabled in mercurial.ini... that makes sense.

Although that also makes me a bit confused that if fsmonitor is always disabled, why is watchman still running and taking lots of memory :/