This is an archive of the discontinued Mercurial Phabricator instance.

interfaceutil: module to stub out zope.interface
ClosedPublic

Authored by indygreg on Apr 22 2018, 3:59 PM.

Details

Summary

The startup time of hg increased during the 4.6 development cycle. A
cause of that was importing more modules and doing more work at module
import time.

The import of zope.interface and the declaring of various interfaces
is partially responsible for the startup time regression.

Our current usage of zope.interface doesn't do much at run time: we are
merely declaring interfaces and stating that certain types implement
various interfaces. Core Mercurial is not (yet) using of any of
zope.interface features that actually require that interface plumbing be
defined. The only place we actually need the interface metadata is in
test-check-interfaces.py.

This commit establishes a new interfaceutil module. It exposes the subset
of the zope.interface API that we currently use. By default, the APIs
no-op. But if an environment variable is set, we export the real
zope.interface APIs.

Existing importers of zope.interface have been converted to use the new
module. test-check-interfaces.py has been updated to define the
environment variable so the real zope.interface is used.

The net effect of this change is we stop importing 9 zope.interface.*
modules and we no longer perform interface bookkeeping when registering
interfaces.

On my i7-6700K on Linux, a shell loop that runs hg log -r . 300 times
on a repo with 1 commit shows a significant CPU time improvement
(average of 4 runs):

4.5: 14.814s
before: 19.028s
after: 16.945s

And with run-tests.py -j10 (single run):

4.5: ~3100s (~51.7m)
before: ~4450s (~74.2m)
after: ~3980s (~66.3m)

So this claws back about half of the regressions in 4.6.

Diff Detail

Repository
rHG Mercurial
Lint
Lint Skipped
Unit
Unit Tests Skipped

Event Timeline

indygreg created this revision.Apr 22 2018, 3:59 PM
durin42 accepted this revision.Apr 23 2018, 4:27 PM
This revision is now accepted and ready to land.Apr 23 2018, 4:27 PM
This revision was automatically updated to reflect the committed changes.

We also detected the regression in 4.6rc0 (http://perf.octobus.net/#basic_commands.DiscoveryTimeSuite.time_debugdiscovery?branch=stable) and can confirm locally that half the regression is fixed on stable (e82b137a8b4e).

Do you have any idea where the second half of regressions come from?

I'm not sure where the 2nd half of the start-up time regressions came from. I had a hacky test where I printed sys.modules keys after command execution. It resulted in the following:

46,68d45
< email
< email.Charset
< email.Encoders
< email.Errors
< email.FeedParser
< email.Generator
< email.Header
< email.Iterators
< email.MIMEAudio
< email.MIMEBase
< email.MIMEImage
< email.MIMEMessage
< email.MIMEMultipart
< email.MIMENonMultipart
< email.MIMEText
< email.Message
< email.Parser
< email.Utils
< email.base64MIME
< email.email
< email.mime
< email.quopriMIME
< email.sys
89a67
> inspect
101d78
< mercurial.cext.diffhelpers
124a102
> mercurial.logcmdutil
127a106
> mercurial.narrowspec
152a132
> mercurial.templatefuncs
153a134,135
> mercurial.templater
> mercurial.templateutil
160a143,152
> mercurial.thirdparty.concurrent
> mercurial.thirdparty.zope
> mercurial.thirdparty.zope.interface
> mercurial.thirdparty.zope.interface._compat
> mercurial.thirdparty.zope.interface._zope_interface_coptimizations
> mercurial.thirdparty.zope.interface.declarations
> mercurial.thirdparty.zope.interface.exceptions
> mercurial.thirdparty.zope.interface.interface
> mercurial.thirdparty.zope.interface.interfaces
> mercurial.thirdparty.zope.interface.ro
164a157,160
> mercurial.utils
> mercurial.utils.dateutil
> mercurial.utils.procutil
> mercurial.utils.stringutil

I'm not convinced the total number of modules is responsible: I think it has more to do with the volume of code being imported. But I could be wrong. These things are a bit challenging to profile.

And for reference, all modules that were imported in 4.6rc after running (I think it was hg log -r .):

Queue
UserDict
__builtin__
__future__
__main__
_abcoll
_codecs
_collections
_curses
_functools
_hashlib
_heapq
_locale
_socket
_sre
_ssl
_struct
_sysconfigdata
_warnings
_weakref
_weakrefset
abc
bdb
binascii
cStringIO
cmd
codecs
collections
contextlib
copy
copy_reg
curses
curses._curses
curses.curses
curses.wrapper
datetime
encodings
encodings.__builtin__
encodings.aliases
encodings.ascii
encodings.codecs
encodings.encodings
encodings.utf_8
errno
exceptions
fcntl
functools
gc
genericpath
getopt
gettext
grp
hashlib
heapq
hgdemandimport
hgdemandimport.demandimportpy2
imp
inspect
itertools
keyword
linecache
locale
mercurial
mercurial.__modulepolicy__
mercurial.bookmarks
mercurial.branchmap
mercurial.cext
mercurial.cext.base85
mercurial.cext.bdiff
mercurial.cext.mpatch
mercurial.cext.osutil
mercurial.cext.parsers
mercurial.changelog
mercurial.cmdutil
mercurial.color
mercurial.commands
mercurial.config
mercurial.configitems
mercurial.context
mercurial.debugcommands
mercurial.dirstate
mercurial.dispatch
mercurial.encoding
mercurial.error
mercurial.extensions
mercurial.fancyopts
mercurial.formatter
mercurial.hg
mercurial.hook
mercurial.i18n
mercurial.localrepo
mercurial.lock
mercurial.logcmdutil
mercurial.match
mercurial.mdiff
mercurial.namespaces
mercurial.narrowspec
mercurial.node
mercurial.obsolete
mercurial.obsutil
mercurial.parser
mercurial.patch
mercurial.pathutil
mercurial.phases
mercurial.policy
mercurial.posix
mercurial.profiling
mercurial.pure
mercurial.pycompat
mercurial.rcutil
mercurial.registrar
mercurial.repository
mercurial.repoview
mercurial.revlog
mercurial.revset
mercurial.revsetlang
mercurial.scmposix
mercurial.scmutil
mercurial.smartset
mercurial.store
mercurial.tags
mercurial.templatefilters
mercurial.templatefuncs
mercurial.templatekw
mercurial.templater
mercurial.templateutil
mercurial.thirdparty
mercurial.thirdparty.attr
mercurial.thirdparty.attr._compat
mercurial.thirdparty.attr._config
mercurial.thirdparty.attr._funcs
mercurial.thirdparty.attr._make
mercurial.thirdparty.attr.exceptions
mercurial.thirdparty.concurrent
mercurial.thirdparty.zope
mercurial.thirdparty.zope.interface
mercurial.thirdparty.zope.interface._compat
mercurial.thirdparty.zope.interface._zope_interface_coptimizations
mercurial.thirdparty.zope.interface.declarations
mercurial.thirdparty.zope.interface.exceptions
mercurial.thirdparty.zope.interface.interface
mercurial.thirdparty.zope.interface.interfaces
mercurial.thirdparty.zope.interface.ro
mercurial.txnutil
mercurial.ui
mercurial.urllibcompat
mercurial.util
mercurial.utils
mercurial.utils.dateutil
mercurial.utils.procutil
mercurial.utils.stringutil
mercurial.vfs
mercurial.zstd
operator
os
os.path
pdb
platform
posix
posixpath
pwd
re
repr
shlex
signal
site
socket
sre_compile
sre_constants
sre_parse
stat
string
strop
struct
sys
sysconfig
thread
time
traceback
types
urllib
urlparse
warnings
weakref
zipimport
zlib

I didn't record whether these are actually imported or our module proxy stub used by the custom module importer. Sorry.

I do have some patches to improve efficiency of the importer. I don't feel comfortable sending them to stable unless we commit to doing another 4.6 RC since they are API breaking. And since release is delayed by a week, maybe that is justified. @durin42?

I do have some patches to improve efficiency of the importer. I don't feel comfortable sending them to stable unless we commit to doing another 4.6 RC since they are API breaking. And since release is delayed by a week, maybe that is justified. @durin42?

I'd rather we reopen default and start doing normal development work there, and keep the 4.6 release as just rc1+security patches.

We saw a ~15ms regression hit on our performance benchmark for the incoming test between 4.5.3 and 4.6rc0. This regression is ~30ms when the test is over ssh.

We are still running tests against 4.6rc1 because it was available late on https://www.mercurial-scm.org/repo/hg/