Patchwork [3,of,3] lock: allow to configure when the lock messages are displayed

login
register
mail settings
Submitter Boris Feld
Date Nov. 27, 2017, 11:18 p.m.
Message ID <15b8fcffac4060771081.1511824691@FB>
Download mbox | patch
Permalink /patch/25775/
State Changes Requested
Headers show

Comments

Boris Feld - Nov. 27, 2017, 11:18 p.m.
# HG changeset patch
# User Boris Feld <boris.feld@octobus.net>
# Date 1511801811 18000
#      Mon Nov 27 11:56:51 2017 -0500
# Node ID 15b8fcffac40607710816a75217219b5668baba5
# Parent  f40e9671a53992359c622dd9c46050b4ff09c374
# EXP-Topic lock-message
# Available At https://bitbucket.org/octobus/mercurial-devel/
#              hg pull https://bitbucket.org/octobus/mercurial-devel/ -r 15b8fcffac40
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.
Yuya Nishihara - Nov. 29, 2017, 1:57 p.m.
On Mon, 27 Nov 2017 18:18:11 -0500, Boris Feld wrote:
> # HG changeset patch
> # User Boris Feld <boris.feld@octobus.net>
> # Date 1511801811 18000
> #      Mon Nov 27 11:56:51 2017 -0500
> # Node ID 15b8fcffac40607710816a75217219b5668baba5
> # Parent  f40e9671a53992359c622dd9c46050b4ff09c374
> # EXP-Topic lock-message
> # Available At https://bitbucket.org/octobus/mercurial-devel/
> #              hg pull https://bitbucket.org/octobus/mercurial-devel/ -r 15b8fcffac40
> lock: allow to configure when the lock messages are displayed

> diff --git a/mercurial/localrepo.py b/mercurial/localrepo.py
> --- a/mercurial/localrepo.py
> +++ b/mercurial/localrepo.py
> @@ -1609,16 +1609,38 @@ class localrepository(object):
>                  msg = _("waiting for lock on %s held by %r\n") % (desc, locker)
>              printer(msg)
>  
> +        delaywarning = self.ui.configint("ui", "timeout.warn")
> +        dowarn = True
> +        if delaywarning < 0:
> +            dowarn = False
> +            delaywarning = 0
> +        else:
> +            delaywarning = delaywarning if wait else 0
>          try:
> -            l = trylock(0)
> +            try:
> +                l = trylock(0)
> +            except error.LockHeld as inst:
> +                if not wait:
> +                    raise
> +                printwarning(self.ui.debug, inst.locker)
> +                if not delaywarning:
> +                    raise
> +                l = trylock(delaywarning)
> +                # We got the lock while warning were silent, inform debug output
> +                msg = _("got lock after %s seconds\n") % (l.delay)
> +                self.ui.debug(msg)
>          except error.LockHeld as inst:
>              if not wait:
>                  raise
> -            printwarning(self.ui.warn, inst.locker)
> +            if dowarn:
> +                printwarning(self.ui.warn, inst.locker)
>              # default to 600 seconds timeout
>              l = trylock(int(self.ui.config("ui", "timeout")))
> -            msg = _("got lock after %s seconds\n") % l.delay
> -            self.ui.warn(msg)
> +            msg = _("got lock after %s seconds\n") % (l.delay + delaywarning)
> +            if dowarn:
> +                self.ui.warn(msg)
> +            else:
> +                self.ui.debug(msg)

Looks okay, but seems unnecessarily complicated. I think it's better to factor
out the lock.lock() loop to a utility function which takes ui and timeouts.

  def lock(ui, ...):
      l = lockmod.lock(..., dolock=False)
      while True:
          try:
              l._trylock()
          except LockHeld:
              if delay >= timeout.warn:
                  ui.warn(...)
              sleep(1)
          ...

Thoughts?
Boris Feld - Nov. 29, 2017, 4:21 p.m.
On Wed, 2017-11-29 at 22:57 +0900, Yuya Nishihara wrote:
> On Mon, 27 Nov 2017 18:18:11 -0500, Boris Feld wrote:
> > # HG changeset patch
> > # User Boris Feld <boris.feld@octobus.net>
> > # Date 1511801811 18000
> > #      Mon Nov 27 11:56:51 2017 -0500
> > # Node ID 15b8fcffac40607710816a75217219b5668baba5
> > # Parent  f40e9671a53992359c622dd9c46050b4ff09c374
> > # EXP-Topic lock-message
> > # Available At https://bitbucket.org/octobus/mercurial-devel/
> > #              hg pull https://bitbucket.org/octobus/mercurial-deve
> > l/ -r 15b8fcffac40
> > lock: allow to configure when the lock messages are displayed
> > diff --git a/mercurial/localrepo.py b/mercurial/localrepo.py
> > --- a/mercurial/localrepo.py
> > +++ b/mercurial/localrepo.py
> > @@ -1609,16 +1609,38 @@ class localrepository(object):
> >                  msg = _("waiting for lock on %s held by %r\n") %
> > (desc, locker)
> >              printer(msg)
> >  
> > +        delaywarning = self.ui.configint("ui", "timeout.warn")
> > +        dowarn = True
> > +        if delaywarning < 0:
> > +            dowarn = False
> > +            delaywarning = 0
> > +        else:
> > +            delaywarning = delaywarning if wait else 0
> >          try:
> > -            l = trylock(0)
> > +            try:
> > +                l = trylock(0)
> > +            except error.LockHeld as inst:
> > +                if not wait:
> > +                    raise
> > +                printwarning(self.ui.debug, inst.locker)
> > +                if not delaywarning:
> > +                    raise
> > +                l = trylock(delaywarning)
> > +                # We got the lock while warning were silent,
> > inform debug output
> > +                msg = _("got lock after %s seconds\n") % (l.delay)
> > +                self.ui.debug(msg)
> >          except error.LockHeld as inst:
> >              if not wait:
> >                  raise
> > -            printwarning(self.ui.warn, inst.locker)
> > +            if dowarn:
> > +                printwarning(self.ui.warn, inst.locker)
> >              # default to 600 seconds timeout
> >              l = trylock(int(self.ui.config("ui", "timeout")))
> > -            msg = _("got lock after %s seconds\n") % l.delay
> > -            self.ui.warn(msg)
> > +            msg = _("got lock after %s seconds\n") % (l.delay +
> > delaywarning)
> > +            if dowarn:
> > +                self.ui.warn(msg)
> > +            else:
> > +                self.ui.debug(msg)
> 
> Looks okay, but seems unnecessarily complicated. I think it's better
> to factor
> out the lock.lock() loop to a utility function which takes ui and
> timeouts.
> 
>   def lock(ui, ...):
>       l = lockmod.lock(..., dolock=False)
>       while True:
>           try:
>               l._trylock()
>           except LockHeld:
>               if delay >= timeout.warn:
>                   ui.warn(...)
>               sleep(1)
>           ...
> 
> Thoughts?

Looks like a good idea, we will give it a shot.

Patch

diff --git a/mercurial/configitems.py b/mercurial/configitems.py
--- a/mercurial/configitems.py
+++ b/mercurial/configitems.py
@@ -985,6 +985,9 @@  coreconfigitem('ui', 'textwidth',
 coreconfigitem('ui', 'timeout',
     default='600',
 )
+coreconfigitem('ui', 'timeout.warn',
+    default=0,
+)
 coreconfigitem('ui', 'traceback',
     default=False,
 )
diff --git a/mercurial/help/config.txt b/mercurial/help/config.txt
--- a/mercurial/help/config.txt
+++ b/mercurial/help/config.txt
@@ -2215,6 +2215,10 @@  User interface controls.
     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
diff --git a/mercurial/localrepo.py b/mercurial/localrepo.py
--- a/mercurial/localrepo.py
+++ b/mercurial/localrepo.py
@@ -1609,16 +1609,38 @@  class localrepository(object):
                 msg = _("waiting for lock on %s held by %r\n") % (desc, locker)
             printer(msg)
 
+        delaywarning = self.ui.configint("ui", "timeout.warn")
+        dowarn = True
+        if delaywarning < 0:
+            dowarn = False
+            delaywarning = 0
+        else:
+            delaywarning = delaywarning if wait else 0
         try:
-            l = trylock(0)
+            try:
+                l = trylock(0)
+            except error.LockHeld as inst:
+                if not wait:
+                    raise
+                printwarning(self.ui.debug, inst.locker)
+                if not delaywarning:
+                    raise
+                l = trylock(delaywarning)
+                # We got the lock while warning were silent, inform debug output
+                msg = _("got lock after %s seconds\n") % (l.delay)
+                self.ui.debug(msg)
         except error.LockHeld as inst:
             if not wait:
                 raise
-            printwarning(self.ui.warn, inst.locker)
+            if dowarn:
+                printwarning(self.ui.warn, inst.locker)
             # default to 600 seconds timeout
             l = trylock(int(self.ui.config("ui", "timeout")))
-            msg = _("got lock after %s seconds\n") % l.delay
-            self.ui.warn(msg)
+            msg = _("got lock after %s seconds\n") % (l.delay + delaywarning)
+            if dowarn:
+                self.ui.warn(msg)
+            else:
+                self.ui.debug(msg)
         return l
 
     def _afterlock(self, callback):
diff --git a/tests/test-lock-badness.t b/tests/test-lock-badness.t
--- a/tests/test-lock-badness.t
+++ b/tests/test-lock-badness.t
@@ -57,14 +57,77 @@  One process waiting for another
   $ 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