[PATCH 4 of 8 v3] ui: log time spent blocked on stdio

Simon Farnsworth simonfar at fb.com
Fri Feb 10 16:15:37 EST 2017


On 10/02/2017 21:06, Simon Farnsworth wrote:
> # HG changeset patch
> # User Simon Farnsworth <simonfar at fb.com>
> # Date 1486760435 28800
> #      Fri Feb 10 13:00:35 2017 -0800
> # Node ID dbe4c89f86d75130fabcde8ac2f4ce18ef6d356e
> # Parent  838c119320b457e9dfcc45d3d8a50a48d5ea5243
> ui: log time spent blocked on stdio
>
> We use a wrapper around Mercurial at Facebook that logs key statistics (like
> elpased time) to our standard performance tooling.
>
> This is less useful than it could be, because we currently can't tell when a
> command is slow because we need to fix Mercurial versus when a command is
> slow because the user isn't interacting quickly.
>
> Teach Mercurial to log the time it spends blocked, so that our tooling can
> pick it up and submit it with the elapsed time - we can then do the math in
> our tooling to see if Mercurial is slow, or if the user simply failed to
> interact.
>
> Combining this with the command duration log means that we can ensure that
> we concentrate performance efforts on the things that bite Facebook users.
>
> The perf microbenchmark regresses marginally on Linux:
> ! wall 0.000007 comb 0.000000 user 0.000000 sys 0.000000 (best of 87366)
>
> However, on my Mac, the timing remains at:
> ! wall 0.000000 comb 0.000000 user 0.000000 sys 0.000000 (best of 190351)

If this regression is too high, I can open-code ui.write's timings, to 
get the Linux microbenchmark to:

! wall 0.000004 comb 0.000000 user 0.000000 sys 0.000000 (best of 84701)
>
> diff --git a/mercurial/ui.py b/mercurial/ui.py
> --- a/mercurial/ui.py
> +++ b/mercurial/ui.py
> @@ -729,31 +729,34 @@
>              self._buffers[-1].extend(a for a in args)
>          else:
>              self._progclear()
> -            for a in args:
> -                self.fout.write(a)
> +            with self.timeblockedsection('stdio'):
> +                for a in args:
> +                    self.fout.write(a)
>
>      def write_err(self, *args, **opts):
>          self._progclear()
>          try:
>              if self._bufferstates and self._bufferstates[-1][0]:
>                  return self.write(*args, **opts)
> -            if not getattr(self.fout, 'closed', False):
> -                self.fout.flush()
> -            for a in args:
> -                self.ferr.write(a)
> -            # stderr may be buffered under win32 when redirected to files,
> -            # including stdout.
> -            if not getattr(self.ferr, 'closed', False):
> -                self.ferr.flush()
> +            with self.timeblockedsection('stdio'):
> +                if not getattr(self.fout, 'closed', False):
> +                    self.fout.flush()
> +                for a in args:
> +                    self.ferr.write(a)
> +                # stderr may be buffered under win32 when redirected to files,
> +                # including stdout.
> +                if not getattr(self.ferr, 'closed', False):
> +                    self.ferr.flush()
>          except IOError as inst:
>              if inst.errno not in (errno.EPIPE, errno.EIO, errno.EBADF):
>                  raise
>
>      def flush(self):
> -        try: self.fout.flush()
> -        except (IOError, ValueError): pass
> -        try: self.ferr.flush()
> -        except (IOError, ValueError): pass
> +        with self.timeblockedsection('stdio'):
> +            try: self.fout.flush()
> +            except (IOError, ValueError): pass
> +            try: self.ferr.flush()
> +            except (IOError, ValueError): pass
>
>      def _isatty(self, fh):
>          if self.configbool('ui', 'nontty', False):
> @@ -915,7 +918,8 @@
>          sys.stdout = self.fout
>          # prompt ' ' must exist; otherwise readline may delete entire line
>          # - https://urldefense.proofpoint.com/v2/url?u=http-3A__bugs.python.org_issue12833&d=DwIGaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=mEgSWILcY4c4W3zjApBQLA&m=byeEYQ5ueUROmXC9lICVJ6CPDtc6rBPaQHOOM7Qujo8&s=zVsdjS0qwtGopELUdHYZ1hF5QTnnB8EwaOnuvoI2zSc&e=
> -        line = raw_input(' ')
> +        with self.timeblockedsection('stdio'):
> +            line = raw_input(' ')
>          sys.stdin = oldin
>          sys.stdout = oldout
>
> @@ -995,13 +999,14 @@
>              self.write_err(self.label(prompt or _('password: '), 'ui.prompt'))
>              # disable getpass() only if explicitly specified. it's still valid
>              # to interact with tty even if fin is not a tty.
> -            if self.configbool('ui', 'nontty'):
> -                l = self.fin.readline()
> -                if not l:
> -                    raise EOFError
> -                return l.rstrip('\n')
> -            else:
> -                return getpass.getpass('')
> +            with self.timeblockedsection('stdio'):
> +                if self.configbool('ui', 'nontty'):
> +                    l = self.fin.readline()
> +                    if not l:
> +                        raise EOFError
> +                    return l.rstrip('\n')
> +                else:
> +                    return getpass.getpass('')
>          except EOFError:
>              raise error.ResponseExpected()
>      def status(self, *msg, **opts):
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel at mercurial-scm.org
> https://urldefense.proofpoint.com/v2/url?u=https-3A__www.mercurial-2Dscm.org_mailman_listinfo_mercurial-2Ddevel&d=DwIGaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=mEgSWILcY4c4W3zjApBQLA&m=byeEYQ5ueUROmXC9lICVJ6CPDtc6rBPaQHOOM7Qujo8&s=aXkVFjc4Yn5TXzgpWpcoSDIAn9aIULo4Nt3govVg778&e=
>

-- 
Simon Farnsworth


More information about the Mercurial-devel mailing list