This is an archive of the discontinued Mercurial Phabricator instance.

Differential D739

undo: do not run undolog for every command
ClosedPublic

Authored by quark on Sep 19 2017, 9:44 PM.
Tags
None
Subscribers
stash

Details

Reviewers
stash
Group Reviewers
Restricted Project
Commits
rFBHGXd48e30ce2b64: undo: do not run undolog for every command
Summary

Previously, undolog runs for every command, which sometimes adds unwanted
noticeable overhead like hg status with a large obsstore. This patch makes
undo smarter to only log commands that actually write things.

This is done by making undolog only run for transactions, updates (legacy
code that does not require a transaction). Tests are changed to reflect
hg status does not trigger undolog, and the new code seems to work better
with chg.

Diff Detail

Repository
rFBHGX Facebook Mercurial Extensions
Lint
Lint Skipped
Unit
Unit Tests Skipped

Event Timeline

quark created this revision.Sep 19 2017, 9:44 PM
Herald added a reviewer: Restricted Project. · View Herald TranscriptSep 19 2017, 9:44 PM
quark updated this revision to Diff 1908.Sep 19 2017, 9:45 PM
quark updated this revision to Diff 1910.Sep 19 2017, 10:19 PM
quark updated this revision to Diff 1911.Sep 19 2017, 10:32 PM
quark updated this revision to Diff 1912.Sep 19 2017, 10:35 PM
quark updated this revision to Diff 1913.
stash accepted this revision.Sep 21 2017, 4:17 AM
stash added a subscriber: stash.
stash added inline comments.
hgext3rd/undo.py
92

You are checking if repo is not None below, but you are not checking it here. It shouldn't cause problems, but it'd be good for consistency to check it there too. Or even check it in the beginning of _runcommandwrapper() function

tests/test-undo.t
235–238

So the idea is that previous hg noop still holding the lock while new hg noop starts?
And you test that second hg noop will wait for some time before start?

BTW, are you sure that 2 secs is always enough? Is it possible that we get sporadic failures?

434–436

Was this chg issue fixed?

This revision is now accepted and ready to land.Sep 21 2017, 4:17 AM
quark marked 2 inline comments as done.Sep 21 2017, 5:12 PM
quark added inline comments.
tests/test-undo.t
235–238

There are different locks:

  • repo.lock, not interesting to the test, but I was trying to trigger undolog by using an empty transaction
  • undolog lock, which is what being tested here

hg noop triggers both locks. But we are only interested in undolog lock here. We don't want this to be blocked by repo.lock.

In fact, since merge.update also triggers undolog, I can probably remove repo.lock. That will make this cleaner.

"sleep 2" is probably fine unless "hg status" takes around 1.8 seconds.

434–436

Yes. I ran the test with --chg.

quark marked an inline comment as done.Sep 21 2017, 5:54 PM
Closed by commit rFBHGXd48e30ce2b64: undo: do not run undolog for every command (authored by quark). · Explain Why
This revision was automatically updated to reflect the committed changes.

Revision Contents
Changeset List

PathPackages
Mhgext3rd/undo.py (74 lines)
Mtests/test-undo.t (36 lines)

Diff 1910

hgext3rd/undo.py

commands, commands,
dispatch, dispatch,
error, error,
extensions, extensions,
fancyopts, fancyopts,
hg, hg,
localrepo, localrepo,
lock as lockmod, lock as lockmod,
merge,
obsolete, obsolete,
obsutil, obsutil,
phases, phases,
registrar, registrar,
revlog, revlog,
revset, revset,
revsetlang, revsetlang,
smartset, smartset,
# Wrappers # Wrappers
def _runcommandwrapper(orig, lui, repo, cmd, fullargs, *args): def _runcommandwrapper(orig, lui, repo, cmd, fullargs, *args):
# For chg, do not wrap the "serve" runcommand call # For chg, do not wrap the "serve" runcommand call
if 'CHGINTERNALMARK' in os.environ: if 'CHGINTERNALMARK' in os.environ:
return orig(lui, repo, cmd, fullargs, *args) return orig(lui, repo, cmd, fullargs, *args)
# This wrapper executes whenever a command is run.
# Some commands (eg hg sl) don't actually modify anything
# ie can't be undone, but the command doesn't know this.
command = [cmd] + fullargs command = [cmd] + fullargs
# Whether undolog has been triggered or not (so we record the *before*
# state of the command). If it is, that means we also want to record the
# *after* state of the command.
triggered = []
# If this hg process is started by another hg process, do not log from the
# inner one, since the inner one is expected to be part of the outer one.
# Note: chg server's case is handled above so "hg serve" won't reach here.
if '_undologactive' in os.environ:
triggered.append(True)
def log(orig, *args, **kwargs):
# trigger a log of the initial state of a repo before a command tries
# to modify that state.
if not triggered:
triggered.append(True)
os.environ['_undologactive'] = "active"
# Check wether undolog is consistent # Check wether undolog is consistent
# ie check wether the undo ext was # ie check wether the undo ext was
# off before this command # off before this command
if '_undologactive' not in os.environ:
changes = safelog(repo, [""]) changes = safelog(repo, [""])
if changes: if changes:
_recordnewgap(repo) _recordnewgap(repo)
stashUnsubmitted
Done

You are checking if repo is not None below, but you are not checking it here. It shouldn't cause problems, but it'd be good for consistency to check it there too. Or even check it in the beginning of _runcommandwrapper() function

stash: You are checking if repo is not None below, but you are not checking it here. It shouldn't…
# prevent nested calls return orig(*args, **kwargs)
if '_undologactive' not in os.environ:
os.environ['_undologactive'] = "active"
rootlog = True
else:
rootlog = False
# Only write undo log if we know a command is going to do some writes. This
# saves time calculating visible heads if the command is read-only (ex.
# status).
#
# To detect a write command, wrap all possible entries:
# - transaction.__init__
# - merge.update
w = extensions.wrappedfunction
with w(merge, 'update', log), w(transaction.transaction, '__init__', log):
try: try:
result = orig(lui, repo, cmd, fullargs, *args) result = orig(lui, repo, cmd, fullargs, *args)
finally: finally:
# record changes to repo
if triggered:
if repo is not None: if repo is not None:
# mercurial is bad with caches # mercurial is bad with caches
# eg update to hidden commit will leave false cache # eg update to hidden commit will leave false cache
repo.invalidatevolatilesets() repo.invalidatevolatilesets()
# record changes to repo
if rootlog:
safelog(repo, command) safelog(repo, command)
del os.environ['_undologactive'] del os.environ['_undologactive']
return result return result
# Write: Log control # Write: Log control
def safelog(repo, command): def safelog(repo, command):
'''boilerplate for log command '''boilerplate for log command

tests/test-undo.t

| a2 | a2
| |
o 0 df4fd610a3d6 1970-01-01 00:00 +0000 test o 0 df4fd610a3d6 1970-01-01 00:00 +0000 test
a1 a1
$ hg log -G -r 'olddraft(1) and public()' -T compact $ hg log -G -r 'olddraft(1) and public()' -T compact
Test undolog lock Test undolog lock
$ hg log --config hooks.duringundologlock="sleep 1" > /dev/null & $ cat > $TESTTMP/noop.py <<EOF
$ sleep 0.1 > from __future__ import absolute_import
$ hg st --time > from mercurial import registrar
time: real [1-9]*\..* (re) > cmdtable = {}
> command = registrar.command(cmdtable)
> @command('noop')
> def noop(ui, repo):
> with repo.lock(), repo.transaction('noop'):
> # transaction triggers undolog
> pass
> EOF
$ cat >> $HGRCPATH <<EOF
> [extensions]
> noop=$TESTTMP/noop.py
> EOF
$ hg noop --config hooks.duringundologlock="sleep 2" > /dev/null &
$ sleep 0.2
"hg status" does not trigger undo log writing
$ hg status --time
time: real 0* (glob)
remove lock intentionally to test the undolog lock during transaction init
$ rm -f .hg/store/lock
$ hg noop --time
time: real [1-9]\..* (re)
stashUnsubmitted
Not Done

So the idea is that previous hg noop still holding the lock while new hg noop starts?
And you test that second hg noop will wait for some time before start?

BTW, are you sure that 2 secs is always enough? Is it possible that we get sporadic failures?

stash: So the idea is that previous `hg noop` still holding the lock while new `hg noop` starts? And…
quarkAuthorUnsubmitted
Not Done

There are different locks:

  • repo.lock, not interesting to the test, but I was trying to trigger undolog by using an empty transaction
  • undolog lock, which is what being tested here

hg noop triggers both locks. But we are only interested in undolog lock here. We don't want this to be blocked by repo.lock.

In fact, since merge.update also triggers undolog, I can probably remove repo.lock. That will make this cleaner.

"sleep 2" is probably fine unless "hg status" takes around 1.8 seconds.

quark: There are different locks: - repo.lock, not interesting to the test, but I was trying to…
hg undo command tests hg undo command tests
$ hg undo $ hg undo
undone to *, before ci -ma5 (glob) undone to *, before ci -ma5 (glob)
$ hg log -G -T compact -l2 $ hg log -G -T compact -l2
@ 8[tip][master] 1dafc0b43612 1970-01-01 00:00 +0000 test @ 8[tip][master] 1dafc0b43612 1970-01-01 00:00 +0000 test
| cmiss | cmiss
| |
> [extensions] > [extensions]
> smartlog =! > smartlog =!
> tweakdefaults =! > tweakdefaults =!
> fbamend =! > fbamend =!
> EOF > EOF
File corruption handling File corruption handling
$ echo 111corruptedrevlog > .hg/undolog/index.i $ echo 111corruptedrevlog > .hg/undolog/index.i
#if chg $ hg noop --debug
(note: chg has issues with the below test)
#else
stashUnsubmitted
Done

Was this chg issue fixed?

stash: Was this chg issue fixed?
quarkAuthorUnsubmitted
Not Done

Yes. I ran the test with --chg.

quark: Yes. I ran the test with `--chg`.
$ hg st --debug
caught revlog error. undolog/index.i was probably corrupted caught revlog error. undolog/index.i was probably corrupted
#endif
$ hg debugundohistory -l $ hg debugundohistory -l
0: -- gap in log -- 0: -- gap in log --
_localbranch revset tests _localbranch revset tests
$ hg log -r '_localbranch(75f63379f12b)' $ hg log -r '_localbranch(75f63379f12b)'
changeset: 0:df4fd610a3d6 changeset: 0:df4fd610a3d6
user: test user: test
date: Thu Jan 01 00:00:00 1970 +0000 date: Thu Jan 01 00:00:00 1970 +0000