This is an archive of the discontinued Mercurial Phabricator instance.

Differential D357

undo: add Scuba logging
ClosedPublic

Authored by felixmerk on Aug 11 2017, 7:18 PM.
Tags
None
Subscribers
stash, quark

Details

Reviewers
quark
Group Reviewers
Restricted Project
Commits
rFBHGX433ee7863fa7: undo: add Scuba logging
Summary

Adds scuba logging to dev command timers so we can see how often some seemingly
unlikely edge (error) cases happen. Once we are confident that hg undo is
stable we can get rid of these logs. This is specifically for things that
don't loudly fail (since the user shouldn't care about them) but we still would
like to know about. Note that
[sampling]
key.undo=perfpipe_dev_command_timers
is needed in an hgrc file for this to work.

Test: deleted gap file, ran undo and confirmed error was noted in dev command
timers

Diff Detail

Repository
rFBHGX Facebook Mercurial Extensions
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Event Timeline

felixmerk created this revision.Aug 11 2017, 7:18 PM
Herald added a reviewer: Restricted Project. · View Herald TranscriptAug 11 2017, 7:18 PM
quark accepted this revision.Aug 15 2017, 2:58 PM
quark added a subscriber: quark.

It seems we might want a general purposed framework to log all exceptions.

This revision is now accepted and ready to land.Aug 15 2017, 2:58 PM
stash added a subscriber: stash.Aug 16 2017, 3:26 AM
stash added inline comments.
hgext3rd/undo.py
126

Scuba is fb-internal, so I'd say that just using ui.log(...) is fine.

Closed by commit rFBHGX433ee7863fa7: undo: add Scuba logging (authored by felixmerk). · Explain WhyAug 16 2017, 11:18 AM
This revision was automatically updated to reflect the committed changes.

Revision Contents
Changeset List

PathPackages
Mhgext3rd/undo.py (14 lines)

Diff 994

hgext3rd/undo.py

with tr: with tr:
changes = log(repo.filtered('visible'), command, tr) changes = log(repo.filtered('visible'), command, tr)
if changes and not ("undo" == command[0] or "redo" == if changes and not ("undo" == command[0] or "redo" ==
command[0]): command[0]):
_delundoredo(repo) _delundoredo(repo)
except error.LockUnavailable: # no write permissions except error.LockUnavailable: # no write permissions
repo.ui.debug("undolog lacks write permission\n") repo.ui.debug("undolog lacks write permission\n")
except error.LockHeld: # timeout, not fatal: don't abort actual command except error.LockHeld: # timeout, not fatal: don't abort actual command
# TODO: log to Scuba. This shouldn't happen too often as it will # This shouldn't happen too often as it would
# create gaps in the undo log # create gaps in the undo log
repo.ui.debug("undolog lock timeout\n") repo.ui.debug("undolog lock timeout\n")
_logtoscuba(repo.ui, 'undolog lock timeout')
stashUnsubmitted
Not Done

Scuba is fb-internal, so I'd say that just using ui.log(...) is fine.

stash: Scuba is fb-internal, so I'd say that just using ui.log(...) is fine.
return changes return changes
def lighttransaction(repo): def lighttransaction(repo):
# full fledged transactions have two serious issues: # full fledged transactions have two serious issues:
# 1. they may cause infite loops through hooks # 1. they may cause infite loops through hooks
# that run commands # that run commands
# 2. they are really expensive performance wise # 2. they are really expensive performance wise
# #
if kvpair[0]: if kvpair[0]:
indexdict[kvpair[0]] = kvpair[1] indexdict[kvpair[0]] = kvpair[1]
return indexdict return indexdict
def _readnode(repo, filename, hexnode): def _readnode(repo, filename, hexnode):
rlog = _getrevlog(repo, filename) rlog = _getrevlog(repo, filename)
return rlog.revision(bin(hexnode)) return rlog.revision(bin(hexnode))
def _gapcheck(repo, reverseindex): def _logtoscuba(ui, message):
ui.log('undo', message, undo=message)
def _gapcheck(ui, repo, reverseindex):
rlog = _getrevlog(repo, 'index.i') rlog = _getrevlog(repo, 'index.i')
absoluteindex = _invertindex(rlog, reverseindex) absoluteindex = _invertindex(rlog, reverseindex)
path = 'undolog' + '/' + 'gap' path = 'undolog' + '/' + 'gap'
result = False
try: try:
result = absoluteindex >= int(repo.vfs.read(path)) result = absoluteindex >= int(repo.vfs.read(path))
except IOError: except IOError:
# recreate file # recreate file
repo.ui.debug("failed to read gap file in %s, attempting recreation\n" repo.ui.debug("failed to read gap file in %s, attempting recreation\n"
% path) % path)
_logtoscuba(ui, "gap file corruption")
rlog = _getrevlog(repo, 'index.i') rlog = _getrevlog(repo, 'index.i')
i = 0 i = 0
while i < (len(rlog)): while i < (len(rlog)):
indexdict = _readindex(repo, i, rlog) indexdict = _readindex(repo, i, rlog)
if "" == _readnode(repo, "command.i", indexdict["command"]): if "" == _readnode(repo, "command.i", indexdict["command"]):
break break
i += 1 i += 1
# defaults to before oldest command # defaults to before oldest command
return return
elif preview: elif preview:
_preview(ui, repo, reverseindex) _preview(ui, repo, reverseindex)
return return
with repo.wlock(), repo.lock(), repo.transaction("undo"): with repo.wlock(), repo.lock(), repo.transaction("undo"):
cmdutil.checkunfinished(repo) cmdutil.checkunfinished(repo)
cmdutil.bailifchanged(repo) cmdutil.bailifchanged(repo)
if not (opts.get("force") or _gapcheck(repo, reverseindex)): if not (opts.get("force") or _gapcheck(ui, repo, reverseindex)):
raise error.Abort(_("attempted risky undo across" raise error.Abort(_("attempted risky undo across"
" missing history")) " missing history"))
_undoto(ui, repo, reverseindex, keep=keep, branch=branch) _undoto(ui, repo, reverseindex, keep=keep, branch=branch)
# store undo data # store undo data
# for absolute undos, think of this as a reset # for absolute undos, think of this as a reset
# for relative undos, think of this as an update # for relative undos, think of this as an update
_logundoredoindex(repo, reverseindex, branch) _logundoredoindex(repo, reverseindex, branch)
return len(rlog) - 1 - indexorreverseindex return len(rlog) - 1 - indexorreverseindex
def _getrevlog(repo, filename): def _getrevlog(repo, filename):
path = 'undolog/' + filename path = 'undolog/' + filename
try: try:
return revlog.revlog(repo.vfs, path) return revlog.revlog(repo.vfs, path)
except error.RevlogError: except error.RevlogError:
# corruption: for now, we can simply nuke all files # corruption: for now, we can simply nuke all files
# TODO: log to Scuba
repo.ui.debug("caught revlog error. %s was probably corrupted\n" % path) repo.ui.debug("caught revlog error. %s was probably corrupted\n" % path)
_logtoscuba(repo.ui, 'revlog error')
repo.vfs.rmtree('undolog') repo.vfs.rmtree('undolog')
repo.vfs.makedirs('undolog') repo.vfs.makedirs('undolog')
# if we get the error a second time # if we get the error a second time
# then someone is actively messing with these files # then someone is actively messing with these files
return revlog.revlog(repo.vfs, path) return revlog.revlog(repo.vfs, path)
def tohexnode(repo, spec): def tohexnode(repo, spec):
revs = repo.revs(spec) revs = repo.revs(spec)
tonode = repo.changelog.node tonode = repo.changelog.node
hexnodes = [hex(tonode(x)) for x in revs] hexnodes = [hex(tonode(x)) for x in revs]
return hexnodes return hexnodes