lock: allow to configure when the lock messages are displayed
We add a new 'ui.timeout.warn' config to set a grace period before we display
lock related warning:
waiting for lock on PATH held by PROCESS
The config is based on 'ui.timeout' and expresses a number of seconds before
the warning is displayed. Negative values disable the warning altogether.
The messages go to the debug output to help people trouble-shooting deadlocks.
--- a/mercurial/configitems.py Wed Nov 29 20:36:29 2017 -0500
+++ b/mercurial/configitems.py Wed Nov 29 20:39:59 2017 -0500
@@ -1081,6 +1081,9 @@
coreconfigitem('ui', 'timeout',
default='600',
)
+coreconfigitem('ui', 'timeout.warn',
+ default=0,
+)
coreconfigitem('ui', 'traceback',
default=False,
)
--- a/mercurial/help/config.txt Wed Nov 29 20:36:29 2017 -0500
+++ b/mercurial/help/config.txt Wed Nov 29 20:39:59 2017 -0500
@@ -2215,6 +2215,10 @@
The timeout used when a lock is held (in seconds), a negative value
means no timeout. (default: 600)
+``timeout.warn``
+ Time (in seconds) before a warning is printed about held lock. A negative
+ value means no warning. (default: 0)
+
``traceback``
Mercurial always prints a traceback when an unknown exception
occurs. Setting this to True will make Mercurial print a traceback
--- a/mercurial/localrepo.py Wed Nov 29 20:36:29 2017 -0500
+++ b/mercurial/localrepo.py Wed Nov 29 20:39:59 2017 -0500
@@ -1594,10 +1594,12 @@
parentlock = encoding.environ.get(parentenvvar)
timeout = 0
+ warntimeout = 0
if wait:
timeout = self.ui.configint("ui", "timeout")
+ warntimeout = self.ui.configint("ui", "timeout.warn")
- l = lockmod.trylock(self.ui, vfs, lockname, timeout,
+ l = lockmod.trylock(self.ui, vfs, lockname, timeout, warntimeout,
releasefn=releasefn,
acquirefn=acquirefn, desc=desc,
inheritchecker=inheritchecker,
--- a/mercurial/lock.py Wed Nov 29 20:36:29 2017 -0500
+++ b/mercurial/lock.py Wed Nov 29 20:39:59 2017 -0500
@@ -41,11 +41,11 @@
raise
return result
-def trylock(ui, vfs, lockname, timeout, *args, **kwargs):
+def trylock(ui, vfs, lockname, timeout, warntimeout, *args, **kwargs):
"""return an acquired lock or raise an a LockHeld exception
- This function is responsible to issue warnings about the held lock while
- trying to acquires it."""
+ This function is responsible to issue warnings and or debug messages about
+ the held lock while trying to acquires it."""
def printwarning(printer, locker):
"""issue the usual "waiting on lock" message through any channel"""
@@ -60,9 +60,12 @@
l = lock(vfs, lockname, 0, *args, dolock=False, **kwargs)
+ debugidx = 0 if (warntimeout and timeout) else -1
warningidx = 0
if not timeout:
warningidx = -1
+ elif warntimeout:
+ warningidx = warntimeout
delay = 0
while True:
@@ -70,6 +73,8 @@
l._trylock()
break
except error.LockHeld as inst:
+ if delay == debugidx:
+ printwarning(ui.debug, inst.locker)
if delay == warningidx:
printwarning(ui.warn, inst.locker)
if timeout <= delay:
@@ -80,7 +85,10 @@
l.delay = delay
if l.delay:
- ui.warn(_("got lock after %s seconds\n") % l.delay)
+ if 0 <= warningidx <= l.delay:
+ ui.warn(_("got lock after %s seconds\n") % l.delay)
+ else:
+ ui.debug("got lock after %s seconds\n" % l.delay)
if l.acquirefn:
l.acquirefn()
return l
--- a/tests/test-lock-badness.t Wed Nov 29 20:36:29 2017 -0500
+++ b/tests/test-lock-badness.t Wed Nov 29 20:39:59 2017 -0500
@@ -57,14 +57,77 @@
$ echo b > b/b
$ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
$ hg -R b up -q --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
- > > preup 2>&1
+ > > preup-stdout 2>preup-stderr
$ wait
- $ cat preup
+ $ cat preup-stdout
+ $ cat preup-stderr
waiting for lock on working directory of b held by process '*' on host '*' (glob)
got lock after * seconds (glob)
$ cat stdout
adding b
+On processs waiting on another, warning after a long time.
+
+ $ echo b > b/c
+ $ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
+ $ hg -R b up -q --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
+ > --config ui.timeout.warn=250 \
+ > > preup-stdout 2>preup-stderr
+ $ wait
+ $ cat preup-stdout
+ $ cat preup-stderr
+ $ cat stdout
+ adding c
+
+On processs waiting on another, warning disabled.
+
+ $ echo b > b/d
+ $ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
+ $ hg -R b up -q --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
+ > --config ui.timeout.warn=-1 \
+ > > preup-stdout 2>preup-stderr
+ $ wait
+ $ cat preup-stdout
+ $ cat preup-stderr
+ $ cat stdout
+ adding d
+
+check we still print debug output
+
+On processs waiting on another, warning after a long time (debug output on)
+
+ $ echo b > b/e
+ $ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
+ $ hg -R b up --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
+ > --config ui.timeout.warn=250 --debug\
+ > > preup-stdout 2>preup-stderr
+ $ wait
+ $ cat preup-stdout
+ calling hook pre-update: hghook_pre-update.sleephalf
+ waiting for lock on working directory of b held by process '*' on host '*' (glob)
+ got lock after * seconds (glob)
+ 0 files updated, 0 files merged, 0 files removed, 0 files unresolved
+ $ cat preup-stderr
+ $ cat stdout
+ adding e
+
+On processs waiting on another, warning disabled, (debug output on)
+
+ $ echo b > b/f
+ $ hg -R b ci -A -m b --config hooks.precommit="python:`pwd`/hooks.py:sleepone" > stdout &
+ $ hg -R b up --config hooks.pre-update="python:`pwd`/hooks.py:sleephalf" \
+ > --config ui.timeout.warn=-1 --debug\
+ > > preup-stdout 2>preup-stderr
+ $ wait
+ $ cat preup-stdout
+ calling hook pre-update: hghook_pre-update.sleephalf
+ waiting for lock on working directory of b held by process '*' on host '*' (glob)
+ got lock after * seconds (glob)
+ 0 files updated, 0 files merged, 0 files removed, 0 files unresolved
+ $ cat preup-stderr
+ $ cat stdout
+ adding f
+
Pushing to a local read-only repo that can't be locked
$ chmod 100 a/.hg/store