mirror of
https://github.com/facebook/sapling.git
synced 2024-12-28 23:54:12 +03:00
blackbox: clean up blackbox logging and log more during rage
Summary: Clean up some of the calls to `ui.log` and how they appear in blackbox logging. * Make the names of the events consistently use `snake_case`. * For watchman, only log once for each watchman command. Include whether or not it failed. * Unify `fsmonitor` logging under the `fsmonitor` event. * Omit the second argument when it is empty - it is optional and does nothing when empty. * Increase the number of blackbox lines included in rage to 100. Reviewed By: quark-zju Differential Revision: D14949868 fbshipit-source-id: a9aa8251e71ae7ca556c08116f8f7c61ff472218
This commit is contained in:
Mark Thomas
Facebook Github Bot
parent
a13df01b7a
commit
94257a258b
@ -48,7 +48,7 @@ def correlator(ui):
|
||||
global _correlator
|
||||
if _correlator is None:
|
||||
_correlator = util.makerandomidentifier()
|
||||
ui.log("clienttelemetry", "", client_correlator=_correlator)
|
||||
ui.log("clienttelemetry", client_correlator=_correlator)
|
||||
return _correlator
|
||||
|
||||
|
||||
@ -59,7 +59,7 @@ _clienttelemetrydata = {}
|
||||
def _clienttelemetry(repo, proto, args):
|
||||
"""Handle received client telemetry"""
|
||||
logargs = {"client_%s" % key: value for key, value in args.items()}
|
||||
repo.ui.log("clienttelemetry", "", **logargs)
|
||||
repo.ui.log("clienttelemetry", **logargs)
|
||||
# Make them available to other extensions
|
||||
repo.clienttelemetry = logargs
|
||||
return socket.gethostname()
|
||||
@ -94,7 +94,7 @@ def _peersetup(ui, peer):
|
||||
logargs = {name: f(ui) for name, f in _clienttelemetryfuncs.items()}
|
||||
logargs.update(_clienttelemetrydata)
|
||||
peername = peer._call("clienttelemetry", **logargs)
|
||||
ui.log("clienttelemetry", "", server_realhostname=peername)
|
||||
ui.log("clienttelemetry", server_realhostname=peername)
|
||||
ann = ui.configbool("clienttelemetry", "announceremotehostname", None)
|
||||
if ann is None:
|
||||
ann = not ui.plain() and ui._isatty(ui.ferr)
|
||||
|
||||
@ -426,7 +426,7 @@ def reposetup(ui, repo):
|
||||
|
||||
try:
|
||||
# Record nodemap lag.
|
||||
ui.log("nodemap_lag", "", nodemap_lag=repo.changelog.nodemap.lag)
|
||||
ui.log("nodemap_lag", nodemap_lag=repo.changelog.nodemap.lag)
|
||||
except AttributeError:
|
||||
pass
|
||||
|
||||
|
||||
@ -50,7 +50,7 @@ def _handlecommandexception(orig, ui):
|
||||
trace = traceback.format_exc()
|
||||
|
||||
# let blackbox log it (if it is configured to do so)
|
||||
ui.log("commandexception", "%s\n%s\n", warning, trace)
|
||||
ui.log("command_exception", "%s\n%s\n", warning, trace)
|
||||
exctype = sys.exc_info()[0]
|
||||
exctypename = "None" if exctype is None else exctype.__name__
|
||||
ui.log(
|
||||
|
||||
@ -115,13 +115,8 @@ class client(object):
|
||||
|
||||
def _command(self, *args):
|
||||
watchmanargs = (args[0], self._resolved_root) + args[1:]
|
||||
self._ui.log(
|
||||
"watchman-command",
|
||||
"watchman command %r started with timeout = %s",
|
||||
watchmanargs,
|
||||
self._timeout,
|
||||
)
|
||||
try:
|
||||
starttime = util.timer()
|
||||
if self._watchmanclient is None:
|
||||
self._firsttime = False
|
||||
self._watchmanclient = pywatchman.client(
|
||||
@ -133,12 +128,19 @@ class client(object):
|
||||
)
|
||||
result = self._watchmanclient.query(*watchmanargs)
|
||||
self._ui.log(
|
||||
"watchman-command", "watchman command %r completed", watchmanargs
|
||||
"watchman",
|
||||
"command %r completed in %0.2f seconds",
|
||||
watchmanargs,
|
||||
util.timer() - starttime,
|
||||
)
|
||||
return result
|
||||
except pywatchman.CommandError as ex:
|
||||
if "unable to resolve root" in ex.msg:
|
||||
self._ui.log(
|
||||
"watchman", "command %r failed - unable to resolve root", args
|
||||
)
|
||||
raise WatchmanNoRoot(self._resolved_root, ex.msg)
|
||||
self._ui.log("watchman", "command %r failed - %s", watchmanargs, ex.msg)
|
||||
raise Unavailable(ex.msg)
|
||||
except pywatchman.SocketConnectError as ex:
|
||||
# If fsmonitor.sockpath was specified in the configuration, we will
|
||||
@ -151,6 +153,7 @@ class client(object):
|
||||
if not self._ui.config("fsmonitor", "sockpath") or self._sockpath is None:
|
||||
# Either sockpath wasn't configured, or we already tried clearing
|
||||
# it out, so let's propagate this error.
|
||||
self._ui.log("watchman", "command %r failed - %s", watchmanargs, ex)
|
||||
raise Unavailable(str(ex))
|
||||
# Recurse and retry the command, and hopefully it will
|
||||
# start the server this time.
|
||||
@ -158,6 +161,7 @@ class client(object):
|
||||
self._watchmanclient = None
|
||||
return self._command(*args)
|
||||
except pywatchman.WatchmanError as ex:
|
||||
self._ui.log("watchman", "command %r failed - %s", watchmanargs, ex)
|
||||
raise Unavailable(str(ex))
|
||||
|
||||
@util.timefunction("watchmanquery", 0, "_ui")
|
||||
@ -170,7 +174,7 @@ class client(object):
|
||||
# Ideally we wouldn't let this happen, but if it does happen,
|
||||
# record it in the log and retry the command.
|
||||
self._ui.log(
|
||||
"watchman-command",
|
||||
"watchman",
|
||||
"UseAfterFork detected, re-establish a client connection",
|
||||
)
|
||||
self._watchmanclient = None
|
||||
@ -286,9 +290,8 @@ class state_update(object):
|
||||
metadata.update(self.metadata)
|
||||
client.command(cmd, {"name": self.name, "metadata": metadata})
|
||||
return True
|
||||
except Exception as e:
|
||||
except Exception:
|
||||
# Swallow any errors; fire and forget
|
||||
self.repo.ui.log("watchman", "Exception %s while running %s\n", e, cmd)
|
||||
return False
|
||||
|
||||
|
||||
|
||||
@ -169,7 +169,7 @@ from edenscm.mercurial import (
|
||||
)
|
||||
from edenscm.mercurial.i18n import _
|
||||
|
||||
from . import state
|
||||
from . import fsmonitorutil, state
|
||||
from ..extlib import pywatchman, watchmanclient
|
||||
|
||||
|
||||
@ -205,11 +205,11 @@ def _handleunavailable(ui, state, ex):
|
||||
ui.warn(str(ex) + "\n")
|
||||
if ex.invalidate:
|
||||
state.invalidate(reason="exception")
|
||||
ui.log("fsmonitor", "Watchman unavailable: %s\n", ex.msg)
|
||||
ui.log("fsmonitor_status", "", fsmonitor_status="unavailable")
|
||||
ui.log("fsmonitor", "watchman unavailable: %s\n", ex.msg)
|
||||
ui.log("fsmonitor_status", fsmonitor_status="unavailable")
|
||||
else:
|
||||
ui.log("fsmonitor", "Watchman exception: %s\n", ex)
|
||||
ui.log("fsmonitor_status", "", fsmonitor_status="exception")
|
||||
ui.log("fsmonitor", "watchman exception: %s\n", ex)
|
||||
ui.log("fsmonitor_status", fsmonitor_status="exception")
|
||||
|
||||
|
||||
def _hashignore(ignore):
|
||||
@ -381,9 +381,7 @@ def overridewalk(orig, self, match, unknown, ignored, full=True):
|
||||
nonnormalset = self._map.nonnormalsetfiltered(dirfilter)
|
||||
else:
|
||||
nonnormalset = self._map.nonnormalset
|
||||
self._ui.log(
|
||||
"fsmonitor", "clock = %r len(nonnormal) = %d" % (clock, len(nonnormalset))
|
||||
)
|
||||
self._ui.log("fsmonitor", "clock=%r len(nonnormal)=%d" % (clock, len(nonnormalset)))
|
||||
|
||||
copymap = self._map.copymap
|
||||
getkind = stat.S_IFMT
|
||||
@ -457,13 +455,13 @@ def overridewalk(orig, self, match, unknown, ignored, full=True):
|
||||
notefiles = []
|
||||
|
||||
if fresh_instance:
|
||||
self._ui.log("fsmonitor_status", "", fsmonitor_status="fresh")
|
||||
self._ui.log("fsmonitor_status", fsmonitor_status="fresh")
|
||||
else:
|
||||
self._ui.log("fsmonitor_status", "", fsmonitor_status="normal")
|
||||
if "fsmonitor_details" in getattr(self._ui, "track", ()):
|
||||
self._ui.log("fsmonitor_status", fsmonitor_status="normal")
|
||||
if "fsmonitor" in getattr(self._ui, "track", ()):
|
||||
filelist = [e["name"] for e in result["files"]]
|
||||
self._ui.log(
|
||||
"fsmonitor_details", "watchman returned %s" % _reprshort(filelist)
|
||||
"fsmonitor", "watchman returned %s" % fsmonitorutil.reprshort(filelist)
|
||||
)
|
||||
state.setwatchmanchangedfilecount(len(result["files"]))
|
||||
|
||||
@ -1031,11 +1029,3 @@ def debugrefreshwatchmanclock(ui, repo):
|
||||
ui.status(_("updating watchman clock from %r to %r\n") % (ds.getclock(), clock))
|
||||
ds.setclock(clock)
|
||||
ds.write(tr)
|
||||
|
||||
|
||||
def _reprshort(filelist, limit=20):
|
||||
"""Like repr(filelist). But truncate it if it is too long"""
|
||||
if len(filelist) <= limit:
|
||||
return repr(filelist)
|
||||
else:
|
||||
return "%r and %s more entries" % (filelist[:limit], len(filelist) - limit)
|
||||
|
||||
14
edenscm/hgext/fsmonitor/fsmonitorutil.py
Normal file
14
edenscm/hgext/fsmonitor/fsmonitorutil.py
Normal file
@ -0,0 +1,14 @@
|
||||
# util.py - fsmonitor utilities
|
||||
#
|
||||
# Copyright 2013-2019 Facebook, Inc.
|
||||
#
|
||||
# This software may be used and distributed according to the terms of the
|
||||
# GNU General Public License version 2 or any later version.
|
||||
|
||||
|
||||
def reprshort(filelist, limit=20):
|
||||
"""Like repr(filelist). But truncate it if it is too long"""
|
||||
if len(filelist) <= limit:
|
||||
return repr(filelist)
|
||||
else:
|
||||
return "%r and %s more entries" % (filelist[:limit], len(filelist) - limit)
|
||||
@ -15,6 +15,8 @@ import struct
|
||||
from edenscm.mercurial import pathutil, util
|
||||
from edenscm.mercurial.i18n import _
|
||||
|
||||
from . import fsmonitorutil
|
||||
|
||||
|
||||
_version = 4
|
||||
_versionformat = ">I"
|
||||
@ -111,13 +113,10 @@ class state(object):
|
||||
finally:
|
||||
file.close()
|
||||
|
||||
if "fsmonitor_details" in getattr(self._ui, "track", ()):
|
||||
from . import _reprshort
|
||||
|
||||
self._ui.log(
|
||||
"fsmonitor_details",
|
||||
"clock, notefiles = %r, %s" % (clock, _reprshort(notefiles)),
|
||||
)
|
||||
self._ui.log(
|
||||
"fsmonitor",
|
||||
"get clock=%r notefiles=%s" % (clock, fsmonitorutil.reprshort(notefiles)),
|
||||
)
|
||||
|
||||
return clock, ignorehash, notefiles
|
||||
|
||||
@ -135,13 +134,10 @@ class state(object):
|
||||
self._ignorelist = ignorelist
|
||||
|
||||
def set(self, clock, ignorehash, notefiles):
|
||||
if "fsmonitor_details" in getattr(self._ui, "track", ()):
|
||||
from . import _reprshort
|
||||
|
||||
self._ui.log(
|
||||
"fsmonitor_details",
|
||||
"set clock, notefiles = %r, %s" % (clock, _reprshort(notefiles)),
|
||||
)
|
||||
self._ui.log(
|
||||
"fsmonitor",
|
||||
"set clock=%r notefiles=%s" % (clock, fsmonitorutil.reprshort(notefiles)),
|
||||
)
|
||||
|
||||
if self._usetreestate:
|
||||
ds = self._repo.dirstate
|
||||
@ -197,23 +193,19 @@ class state(object):
|
||||
except OSError as inst:
|
||||
if inst.errno != errno.ENOENT:
|
||||
raise
|
||||
if "fsmonitor_details" in getattr(self._ui, "track", ()):
|
||||
self._ui.log("fsmonitor_details", "fsmonitor state invalidated")
|
||||
self._ui.log("fsmonitor", "state invalidated")
|
||||
|
||||
def setlastclock(self, clock):
|
||||
if "fsmonitor_details" in getattr(self._ui, "track", ()):
|
||||
self._ui.log("fsmonitor_details", "setlastclock: %r" % clock)
|
||||
self._ui.log("fsmonitor", "setlastclock %r" % clock)
|
||||
self._lastclock = clock
|
||||
|
||||
def setlastisfresh(self, isfresh):
|
||||
if "fsmonitor_details" in getattr(self._ui, "track", ()):
|
||||
self._ui.log("fsmonitor_details", "setlastisfresh: %r" % isfresh)
|
||||
self._ui.log("fsmonitor", "setlastisfresh %r" % isfresh)
|
||||
self._lastisfresh = isfresh
|
||||
|
||||
def setwatchmanchangedfilecount(self, filecount):
|
||||
self._lastchangedfilecount = filecount
|
||||
|
||||
def getlastclock(self):
|
||||
if "fsmonitor_details" in getattr(self._ui, "track", ()):
|
||||
self._ui.log("fsmonitor_details", "getlastclock: %r" % self._lastclock)
|
||||
self._ui.log("fsmonitor", "getlastclock %r" % self._lastclock)
|
||||
return self._lastclock
|
||||
|
||||
@ -46,7 +46,7 @@ def _writeerr(orig, self, *args, **opts):
|
||||
|
||||
def _handlecommandexception(orig, ui):
|
||||
trace = traceback.format_exc()
|
||||
ui.log("commandexception", "%s\n", trace)
|
||||
ui.log("command_exception", "%s\n", trace)
|
||||
ui.write_err(_colorizetraceback(ui, trace))
|
||||
return True # do not re-raise the exception
|
||||
|
||||
|
||||
@ -299,7 +299,7 @@ def _makerage(ui, repo, **opts):
|
||||
'first 20 lines of "hg status"',
|
||||
lambda: "\n".join(hgcmd("status").splitlines()[:20]),
|
||||
),
|
||||
("hg blackbox -l60", lambda: hgcmd("blackbox", limit=60)),
|
||||
("hg blackbox -l100", lambda: hgcmd("blackbox", limit=100)),
|
||||
("hg summary", lambda: hgcmd("summary")),
|
||||
("hg debugprocesstree", lambda: hgcmd("debugprocesstree")),
|
||||
("hg config (local)", lambda: "\n".join(localconfig(ui))),
|
||||
|
||||
@ -445,7 +445,6 @@ class rebaseruntime(object):
|
||||
# a rebase may run multiple updates, so that value might be not be accurate.
|
||||
repo.ui.log(
|
||||
"rebase_size",
|
||||
"",
|
||||
rebase_commitcount=commitcount,
|
||||
rebase_distance=distance - commitcount,
|
||||
)
|
||||
@ -462,9 +461,7 @@ class rebaseruntime(object):
|
||||
else:
|
||||
self.wctx = self.repo[None]
|
||||
self.repo.ui.debug("rebasing on disk\n")
|
||||
self.repo.ui.log(
|
||||
"rebase", "", rebase_imm_used=str(self.wctx.isinmemory()).lower()
|
||||
)
|
||||
self.repo.ui.log("rebase", rebase_imm_used=str(self.wctx.isinmemory()).lower())
|
||||
|
||||
def _performrebase(self, tr):
|
||||
self._assignworkingcopy()
|
||||
@ -585,7 +582,6 @@ class rebaseruntime(object):
|
||||
)
|
||||
ui.log(
|
||||
"rebase",
|
||||
"",
|
||||
rebase_imm_new_restart=str(True).lower(),
|
||||
rebase_imm_restart=str(True).lower(),
|
||||
)
|
||||
@ -1249,7 +1245,7 @@ def _definedestmap(
|
||||
destmap = {r: destrev for r in rebaseset} # {srcrev: destrev}
|
||||
|
||||
rbsrt.rebasingwcp = destmap is not None and repo["."].rev() in destmap
|
||||
ui.log("rebase", "", rebase_rebasing_wcp=rbsrt.rebasingwcp)
|
||||
ui.log("rebase", rebase_rebasing_wcp=rbsrt.rebasingwcp)
|
||||
if rbsrt.inmemory and rbsrt.rebasingwcp:
|
||||
# Require a clean working copy if rebasing the current commit, as the
|
||||
# last step of the rebase is an update.
|
||||
|
||||
@ -152,8 +152,8 @@ def prefixkeys(dict, prefix):
|
||||
|
||||
def reportpackmetrics(ui, prefix, *stores):
|
||||
dicts = [s.getmetrics() for s in stores]
|
||||
dict = prefixkeys(sumdicts(*dicts), prefix + "_")
|
||||
ui.log(prefix + "_packsizes", "", **dict)
|
||||
data = prefixkeys(sumdicts(*dicts), prefix + "_")
|
||||
ui.log(prefix + "_packsizes", **data)
|
||||
|
||||
|
||||
def _parsepackmeta(metabuf):
|
||||
|
||||
@ -447,7 +447,7 @@ def _trackdirstatesizes(runcommand, lui, repo, *args):
|
||||
# Treestate and treedirstate.
|
||||
dirstatesize = len(dirstate._map)
|
||||
if dirstatesize is not None:
|
||||
lui.log("dirstate_size", "", dirstate_size=dirstatesize)
|
||||
lui.log("dirstate_size", dirstate_size=dirstatesize)
|
||||
if (
|
||||
repo.ui.configbool("sparse", "largecheckouthint")
|
||||
and dirstatesize >= repo.ui.configint("sparse", "largecheckoutcount")
|
||||
|
||||
@ -1400,7 +1400,7 @@ class dirstate(object):
|
||||
prefix + "wdirparent1": parents[0],
|
||||
prefix + "wdirparent2": parents[1],
|
||||
}
|
||||
ui.log("dirstate_info", "", **data)
|
||||
ui.log("dirstate_info", **data)
|
||||
|
||||
|
||||
class dirstatemap(object):
|
||||
|
||||
@ -401,11 +401,7 @@ def dispatch(req):
|
||||
def logatexit():
|
||||
ui = req.ui
|
||||
if ui.logmeasuredtimes:
|
||||
ui.log(
|
||||
"measuredtimes",
|
||||
"measured times",
|
||||
**pycompat.strkwargs(ui._measuredtimes)
|
||||
)
|
||||
ui.log("measuredtimes", **pycompat.strkwargs(ui._measuredtimes))
|
||||
if ui.metrics.stats:
|
||||
# Re-arrange metrics so "a_b_c", "a_b_d", "a_c" becomes
|
||||
# {'a': {'b': {'c': ..., 'd': ...}, 'c': ...}
|
||||
@ -467,7 +463,7 @@ def dispatch(req):
|
||||
duration = util.timer() - starttime
|
||||
req.ui.flush()
|
||||
req.ui.log(
|
||||
"commandfinish",
|
||||
"command_finish",
|
||||
"%s exited %d after %0.2f seconds\n",
|
||||
msg,
|
||||
ret or 0,
|
||||
@ -895,7 +891,7 @@ class cmdalias(object):
|
||||
raise error.Abort(self.badalias, hint=hint)
|
||||
|
||||
ui.log(
|
||||
"commandalias", "alias '%s' expands to '%s'\n", self.name, self.definition
|
||||
"command_alias", "alias '%s' expands to '%s'\n", self.name, self.definition
|
||||
)
|
||||
if util.safehasattr(self, "shell"):
|
||||
return self.fn(ui, *args, **opts)
|
||||
@ -1452,7 +1448,7 @@ def handlecommandexception(ui):
|
||||
this function returns False, ignored otherwise.
|
||||
"""
|
||||
warning = _exceptionwarning(ui)
|
||||
ui.log("commandexception", "%s\n%s\n", warning, traceback.format_exc())
|
||||
ui.log("command_exception", "%s\n%s\n", warning, traceback.format_exc())
|
||||
ui.warn(warning)
|
||||
return False # re-raise the exception
|
||||
|
||||
|
||||
@ -2337,7 +2337,7 @@ class localrepository(object):
|
||||
)
|
||||
mutation.recordentries(self, [entry], skipexisting=False)
|
||||
tr.close()
|
||||
self.ui.log("commit_info", "", node=hex(n), author=user, **ctx.loginfo())
|
||||
self.ui.log("commit_info", node=hex(n), author=user, **ctx.loginfo())
|
||||
return n
|
||||
finally:
|
||||
if tr:
|
||||
|
||||
@ -533,7 +533,7 @@ class mergestate(object):
|
||||
else:
|
||||
actx = None
|
||||
self._repo.ui.log(
|
||||
"merge-resolve", "resolving %s, preresolve = %s", dfile, preresolve
|
||||
"merge_resolve", "resolving %s, preresolve = %s", dfile, preresolve
|
||||
)
|
||||
fcd = self._filectxorabsent(hash, wctx, dfile)
|
||||
fco = self._filectxorabsent(onode, octx, ofile)
|
||||
@ -1945,7 +1945,7 @@ def _logupdatedistance(ui, repo, node, branchmerge):
|
||||
|
||||
try:
|
||||
distance = len(repo.revs("(%s %% .) + (. %% %s)", node, node))
|
||||
repo.ui.log("update_size", "", update_distance=distance)
|
||||
repo.ui.log("update_size", update_distance=distance)
|
||||
except Exception:
|
||||
# error may happen like: RepoLookupError: unknown revision '-1'
|
||||
pass
|
||||
@ -2293,7 +2293,7 @@ def update(
|
||||
repo.hook("update", parent1=xp1, parent2=xp2, error=stats[3])
|
||||
|
||||
# Log the number of files updated.
|
||||
repo.ui.log("update_size", "", update_filecount=sum(stats))
|
||||
repo.ui.log("update_size", update_filecount=sum(stats))
|
||||
|
||||
return stats
|
||||
|
||||
|
||||
@ -424,7 +424,7 @@ class treedirstatemap(object):
|
||||
repackthreshold = max(self._packedsize * repackfactor, minrepackthreshold)
|
||||
if self._rmap.storeoffset() > repackthreshold:
|
||||
self._ui.note(_("auto-repacking treedirstate\n"))
|
||||
self._ui.log("treedirstate_repacking", "", treedirstate_repacking=True)
|
||||
self._ui.log("treedirstate_repacking", treedirstate_repacking=True)
|
||||
self._repacked = True
|
||||
self._treeid = None
|
||||
self._gc()
|
||||
|
||||
@ -72,7 +72,7 @@ class visibleheads(object):
|
||||
raise
|
||||
self.heads = _convertfromobsolete(repo)
|
||||
self.dirty = True
|
||||
ui.log("visibility", "", visibility_headcount=len(self.heads))
|
||||
ui.log("visibility", visibility_headcount=len(self.heads))
|
||||
|
||||
def _write(self, fp):
|
||||
fp.write("%s\n" % FORMAT_VERSION)
|
||||
|
||||
@ -5,7 +5,7 @@
|
||||
> [experimental]
|
||||
> evolution = all
|
||||
> [blackbox]
|
||||
> track = command, commandfinish, commandexception,
|
||||
> track = command, command_finish, command_exception,
|
||||
> pinnednodes
|
||||
> EOF
|
||||
|
||||
|
||||
@ -317,7 +317,7 @@ blackbox should work if repo.ui.log is not called (issue5518)
|
||||
|
||||
$ cat >> $HGRCPATH << EOF
|
||||
> [blackbox]
|
||||
> track = commandexception
|
||||
> track = command_exception
|
||||
> [extensions]
|
||||
> raise=$TESTTMP/raise.py
|
||||
> EOF
|
||||
|
||||
@ -9,7 +9,7 @@ Commit and Amend
|
||||
$ echo base > base
|
||||
$ hg commit -Am base
|
||||
adding base
|
||||
commit_info: (author=test checkoutidentifier= node=d20a80d4def38df63a4b330b7fb688f3d4cae1e3)
|
||||
commit_info (author=test checkoutidentifier= node=d20a80d4def38df63a4b330b7fb688f3d4cae1e3)
|
||||
|
||||
$ hg debugcheckoutidentifier
|
||||
0000000000000000
|
||||
@ -18,20 +18,20 @@ Commit and Amend
|
||||
$ hg debugcheckoutidentifier
|
||||
0000000000000000
|
||||
$ hg commit -m 1
|
||||
commit_info: (author=test checkoutidentifier=0000000000000000 node=f0161ad23099c690115006c21e96f780f5d740b6)
|
||||
commit_info (author=test checkoutidentifier=0000000000000000 node=f0161ad23099c690115006c21e96f780f5d740b6)
|
||||
|
||||
$ hg debugcheckoutidentifier
|
||||
0000000000000001
|
||||
$ echo 1b > 1
|
||||
$ hg amend -m 1b
|
||||
commit_info: (author=test checkoutidentifier=0000000000000001 mutation=amend node=edbfe685c913f3cec015588dbc0f1e03f5146d80 predecessors=f0161ad23099c690115006c21e96f780f5d740b6)
|
||||
commit_info (author=test checkoutidentifier=0000000000000001 mutation=amend node=edbfe685c913f3cec015588dbc0f1e03f5146d80 predecessors=f0161ad23099c690115006c21e96f780f5d740b6)
|
||||
|
||||
$ hg debugcheckoutidentifier
|
||||
0000000000000002
|
||||
$ echo 2 > 2
|
||||
$ hg commit -Am 2
|
||||
adding 2
|
||||
commit_info: (author=test checkoutidentifier=0000000000000002 node=155c3fe008ceed8a313cbb9358999d850a57a06f)
|
||||
commit_info (author=test checkoutidentifier=0000000000000002 node=155c3fe008ceed8a313cbb9358999d850a57a06f)
|
||||
|
||||
Absorb
|
||||
$ hg debugcheckoutidentifier
|
||||
@ -51,8 +51,8 @@ Absorb
|
||||
2 changesets affected
|
||||
155c3fe 2
|
||||
edbfe68 1b
|
||||
commit_info: (author=test checkoutidentifier=0000000000000003 node=f84ddfee68927d4ebfe4344520adb71ccb173c4f)
|
||||
commit_info: (author=test checkoutidentifier=0000000000000003 node=e911dd548c90906d9f6733aa1612274865a7dfd2)
|
||||
commit_info (author=test checkoutidentifier=0000000000000003 node=f84ddfee68927d4ebfe4344520adb71ccb173c4f)
|
||||
commit_info (author=test checkoutidentifier=0000000000000003 node=e911dd548c90906d9f6733aa1612274865a7dfd2)
|
||||
2 of 2 chunks applied
|
||||
|
||||
Rebase with conflict resolution
|
||||
@ -64,13 +64,13 @@ Rebase with conflict resolution
|
||||
$ echo 2z > 2
|
||||
$ hg commit -Am 2z
|
||||
adding 2
|
||||
commit_info: (author=test checkoutidentifier=0000000000000005 node=78930e916793ff11b38f4f89f92221c180f922a3)
|
||||
commit_info (author=test checkoutidentifier=0000000000000005 node=78930e916793ff11b38f4f89f92221c180f922a3)
|
||||
$ hg debugcheckoutidentifier
|
||||
0000000000000006
|
||||
$ echo 3 > 3
|
||||
$ hg commit -Am 3
|
||||
adding 3
|
||||
commit_info: (author=test checkoutidentifier=0000000000000006 node=27fd2733660ce0233ef4603cebe6328681aa598d)
|
||||
commit_info (author=test checkoutidentifier=0000000000000006 node=27fd2733660ce0233ef4603cebe6328681aa598d)
|
||||
$ hg debugcheckoutidentifier
|
||||
0000000000000007
|
||||
$ hg rebase -s 6 -d 5
|
||||
@ -89,15 +89,15 @@ Rebase with conflict resolution
|
||||
0000000000000008
|
||||
$ hg rebase --continue
|
||||
rebasing 6:78930e916793 "2z"
|
||||
commit_info: (author=test checkoutidentifier=0000000000000008 mutation=rebase node=2a9f3f40eebf9d189f51eeba40f6d45935255c3e predecessors=78930e916793ff11b38f4f89f92221c180f922a3)
|
||||
commit_info (author=test checkoutidentifier=0000000000000008 mutation=rebase node=2a9f3f40eebf9d189f51eeba40f6d45935255c3e predecessors=78930e916793ff11b38f4f89f92221c180f922a3)
|
||||
rebasing 7:27fd2733660c "3" (tip)
|
||||
commit_info: (author=test checkoutidentifier=0000000000000009 mutation=rebase node=b42c49c8c650d6040d4a4003a30c82e1cde21c50 predecessors=27fd2733660ce0233ef4603cebe6328681aa598d)
|
||||
commit_info (author=test checkoutidentifier=0000000000000009 mutation=rebase node=b42c49c8c650d6040d4a4003a30c82e1cde21c50 predecessors=27fd2733660ce0233ef4603cebe6328681aa598d)
|
||||
$ hg debugcheckoutidentifier
|
||||
0000000000000010
|
||||
|
||||
Fold has no checkoutidentifier, but does log other commit info
|
||||
$ hg fold --from ".~2"
|
||||
commit_info: (author=test mutation=fold node=39938ad744a3c4695743296607b5786b8e1437c6 predecessors=e911dd548c90906d9f6733aa1612274865a7dfd2 2a9f3f40eebf9d189f51eeba40f6d45935255c3e b42c49c8c650d6040d4a4003a30c82e1cde21c50)
|
||||
commit_info (author=test mutation=fold node=39938ad744a3c4695743296607b5786b8e1437c6 predecessors=e911dd548c90906d9f6733aa1612274865a7dfd2 2a9f3f40eebf9d189f51eeba40f6d45935255c3e b42c49c8c650d6040d4a4003a30c82e1cde21c50)
|
||||
3 changesets folded
|
||||
1 files updated, 0 files merged, 0 files removed, 0 files unresolved
|
||||
$ hg debugcheckoutidentifier
|
||||
|
||||
@ -7,25 +7,25 @@
|
||||
|
||||
$ echo base > base
|
||||
$ hg commit -Am base
|
||||
dirstate_info: (precheckoutidentifier= prewdirparent1= prewdirparent2=)
|
||||
dirstate_info (precheckoutidentifier= prewdirparent1= prewdirparent2=)
|
||||
adding base
|
||||
dirstate_info: (postcheckoutidentifier=0000000000000000 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=)
|
||||
dirstate_info (postcheckoutidentifier=0000000000000000 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=)
|
||||
|
||||
$ hg debugcheckoutidentifier
|
||||
dirstate_info: (precheckoutidentifier=0000000000000000 prewdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 prewdirparent2=)
|
||||
dirstate_info (precheckoutidentifier=0000000000000000 prewdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 prewdirparent2=)
|
||||
0000000000000000
|
||||
dirstate_info: (postcheckoutidentifier=0000000000000000 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=)
|
||||
dirstate_info (postcheckoutidentifier=0000000000000000 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=)
|
||||
|
||||
$ echo 1 > 1
|
||||
$ hg commit -Am 1
|
||||
dirstate_info: (precheckoutidentifier=0000000000000000 prewdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 prewdirparent2=)
|
||||
dirstate_info (precheckoutidentifier=0000000000000000 prewdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 prewdirparent2=)
|
||||
adding 1
|
||||
dirstate_info: (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=)
|
||||
dirstate_info (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=)
|
||||
|
||||
$ hg debugcheckoutidentifier
|
||||
dirstate_info: (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=)
|
||||
dirstate_info (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=)
|
||||
0000000000000001
|
||||
dirstate_info: (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=)
|
||||
dirstate_info (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=)
|
||||
|
||||
An extension which makes the log command slow
|
||||
$ cat > $TESTTMP/slowlog.py <<EOF
|
||||
@ -45,12 +45,12 @@ The log process's post-run information shouldn't have changed.
|
||||
$ hg log -r . -T "{node}\n" --config extensions.slowlog=$TESTTMP/slowlog.py > $TESTTMP/log.out &
|
||||
$ sleep 1
|
||||
$ hg prev
|
||||
dirstate_info: (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=)
|
||||
dirstate_info (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=)
|
||||
0 files updated, 0 files merged, 1 files removed, 0 files unresolved
|
||||
[d20a80] base
|
||||
dirstate_info: (postcheckoutidentifier=0000000000000002 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=)
|
||||
dirstate_info (postcheckoutidentifier=0000000000000002 postwdirparent1=d20a80d4def38df63a4b330b7fb688f3d4cae1e3 postwdirparent2=)
|
||||
$ wait
|
||||
$ cat $TESTTMP/log.out
|
||||
dirstate_info: (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=)
|
||||
dirstate_info (precheckoutidentifier=0000000000000001 prewdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 prewdirparent2=)
|
||||
f0161ad23099c690115006c21e96f780f5d740b6
|
||||
dirstate_info: (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=)
|
||||
dirstate_info (postcheckoutidentifier=0000000000000001 postwdirparent1=f0161ad23099c690115006c21e96f780f5d740b6 postwdirparent2=)
|
||||
|
||||
@ -58,7 +58,7 @@ Traces are logged in blackbox
|
||||
> [extensions]
|
||||
> blackbox=
|
||||
> [blackbox]
|
||||
> track = command, commandexception
|
||||
> track = command, command_exception
|
||||
> logsource = 1
|
||||
> EOF
|
||||
|
||||
@ -70,5 +70,5 @@ Traces are logged in blackbox
|
||||
$ hg blackbox -l 12 | grep '\[command'
|
||||
* @0000000000000000000000000000000000000000 (*) [command]> blackbox -l 2 (glob)
|
||||
* @0000000000000000000000000000000000000000 (*) [command]> crash* (glob)
|
||||
* @0000000000000000000000000000000000000000 (*) [commandexception]> * (glob)
|
||||
* @0000000000000000000000000000000000000000 (*) [command_exception]> * (glob)
|
||||
* @0000000000000000000000000000000000000000 (*) [command]> blackbox -l 12 (glob)
|
||||
|
||||
@ -71,18 +71,18 @@ Do a couple of commits. We expect to log two messages per call to repo.commit.
|
||||
... assert len(parsedrecord["data"]) == 4
|
||||
... elif parsedrecord['category'] == 'measuredtimes':
|
||||
... print('atexit_measured: ', repr(sorted(parsedrecord['data'])))
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (no-fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'stdio_blocked'] (no-fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'stdio_blocked'] (fsmonitor !)
|
||||
match filter commit_table
|
||||
message string commit_table
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (no-fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (no-fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'msg', u'stdio_blocked', u'watchmanquery_time'] (fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'stdio_blocked'] (no-fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'stdio_blocked'] (no-fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'stdio_blocked', u'watchmanquery_time'] (fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'stdio_blocked'] (fsmonitor !)
|
||||
match filter commit_table
|
||||
message string commit_table
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'msg', u'stdio_blocked'] (no-fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'msg', u'stdio_blocked', u'watchmanquery_time'] (fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'dirstatewalk_time', u'metrics_type', u'stdio_blocked'] (no-fsmonitor !)
|
||||
atexit_measured: [u'atexit_measured', u'command_duration', u'fsmonitorwalk_time', u'metrics_type', u'stdio_blocked', u'watchmanquery_time'] (fsmonitor !)
|
||||
|
||||
Test topdir logging:
|
||||
$ setconfig sampling.logtopdir=True
|
||||
|
||||
@ -2,7 +2,7 @@
|
||||
|
||||
$ newrepo
|
||||
$ enable blackbox
|
||||
$ setconfig blackbox.track=fsmonitor_details
|
||||
$ setconfig blackbox.track=fsmonitor
|
||||
$ hg status
|
||||
$ touch x
|
||||
$ hg status
|
||||
@ -38,7 +38,7 @@
|
||||
$ grep returned .hg/blackbox.log
|
||||
*> watchman returned ['x'] (glob)
|
||||
*> watchman returned [*] and 5 more entries (glob)
|
||||
$ grep 'set clock, notefiles' .hg/blackbox.log
|
||||
*> set clock, notefiles = '*', [] (glob)
|
||||
*> set clock, notefiles = '*', ['x'] (glob)
|
||||
*> set clock, notefiles = '*', [*] and 6 more entries (glob)
|
||||
$ grep 'set clock' .hg/blackbox.log
|
||||
*> set clock='*' notefiles=[] (glob)
|
||||
*> set clock='*' notefiles=['x'] (glob)
|
||||
*> set clock='*' notefiles=[*] and 6 more entries (glob)
|
||||
|
||||
@ -30,12 +30,12 @@ many files:
|
||||
$ hg status
|
||||
|
||||
$ hg blackbox | sed "s/^[^>]*> //;s/c:[0-9][0-9:]*/c:x/"
|
||||
clock = 'c:x' len(nonnormal) = 0
|
||||
setlastclock: 'c:x'
|
||||
setlastisfresh: False
|
||||
clock='c:x' len(nonnormal)=0
|
||||
setlastclock 'c:x'
|
||||
setlastisfresh False
|
||||
watchman returned ['a', 'b', 'c', 'd', 'e', 'f']
|
||||
getlastclock: 'c:x'
|
||||
set clock, notefiles = 'c:x', []
|
||||
getlastclock 'c:x'
|
||||
set clock='c:x' notefiles=[]
|
||||
status exited 0 after 0.00 seconds
|
||||
|
||||
The watchman clock remains unchanged. Watchman still returns 4 files, which
|
||||
|
||||
@ -13,7 +13,7 @@
|
||||
> EOS
|
||||
|
||||
$ enable blackbox fsmonitor rebase hgevents
|
||||
$ setconfig blackbox.track=merge-resolve,watchman-command
|
||||
$ setconfig blackbox.track=merge_resolve,watchman blackbox.logsource=true
|
||||
|
||||
$ hg rebase -s B -d C --tool=false
|
||||
rebasing 1:65f3e88a53bc "B" (B)
|
||||
@ -24,12 +24,12 @@
|
||||
[1]
|
||||
|
||||
$ hg blackbox -l 100 | egrep '(watchman.*state.*completed|resolving)' | python $RUNTESTDIR/sortdictfilter.py
|
||||
*> watchman command ('state-enter', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': False, 'partial': False, 'rev': '0000000000000000000000000000000000000000', 'status': 'ok'}, 'name': 'hg.update'}) completed (glob)
|
||||
*> watchman command ('state-leave', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': False, 'partial': False, 'rev': '2e2f27616b65209eecd4710c454df0f678f271d9', 'status': 'ok'}, 'name': 'hg.update'}) completed (glob)
|
||||
*> watchman command ('state-enter', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': True, 'partial': False, 'rev': '2e2f27616b65209eecd4710c454df0f678f271d9', 'status': 'ok'}, 'name': 'hg.update'}) completed (glob)
|
||||
*> command ('state-enter', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': False, 'partial': False, 'rev': '0000000000000000000000000000000000000000', 'status': 'ok'}, 'name': 'hg.update'}) completed in 0.00 seconds (glob)
|
||||
*> command ('state-leave', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': False, 'partial': False, 'rev': '2e2f27616b65209eecd4710c454df0f678f271d9', 'status': 'ok'}, 'name': 'hg.update'}) completed in 0.00 seconds (glob)
|
||||
*> command ('state-enter', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': True, 'partial': False, 'rev': '2e2f27616b65209eecd4710c454df0f678f271d9', 'status': 'ok'}, 'name': 'hg.update'}) completed in 0.00 seconds (glob)
|
||||
*> resolving 2, preresolve = True (glob)
|
||||
*> resolving A, preresolve = True (glob)
|
||||
*> resolving 2, preresolve = False (glob)
|
||||
*> watchman command ('state-enter', '$TESTTMP/repo1', {'metadata': {'path': '2'}, 'name': 'hg.filemerge'}) completed (glob)
|
||||
*> watchman command ('state-leave', '$TESTTMP/repo1', {'metadata': {'path': '2'}, 'name': 'hg.filemerge'}) completed (glob)
|
||||
*> watchman command ('state-leave', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': True, 'partial': False, 'rev': '65f3e88a53bc0f5183deea0cdbc46738777ec005', 'status': 'ok'}, 'name': 'hg.update'}) completed (glob)
|
||||
*> command ('state-enter', '$TESTTMP/repo1', {'metadata': {'path': '2'}, 'name': 'hg.filemerge'}) completed in 0.00 seconds (glob)
|
||||
*> command ('state-leave', '$TESTTMP/repo1', {'metadata': {'path': '2'}, 'name': 'hg.filemerge'}) completed in 0.00 seconds (glob)
|
||||
*> command ('state-leave', '$TESTTMP/repo1', {'metadata': {'distance': 3, 'merge': True, 'partial': False, 'rev': '65f3e88a53bc0f5183deea0cdbc46738777ec005', 'status': 'ok'}, 'name': 'hg.update'}) completed in 0.00 seconds (glob)
|
||||
|
||||
Loading…
Reference in New Issue
Block a user