This is an archive of the discontinued Mercurial Phabricator instance.

Differential D1721

debug: customizable timestamp when printing ui.debug text
AbandonedPublic

Authored by spectral on Dec 18 2017, 8:48 PM.

Details

Reviewers
None
Group Reviewers
hg-reviewers
Summary

Sometimes users report "X is slow", where X is usually something that has
some debug output, like hg push. Having timestamps as part of the ui.debug()
output will help identify what they're seeing. The timestamp is customizable
using [ui]debugtimestampfmt, which accepts any timestamp that
datetime.strftime() can handle. I'm using datetime.strftime() since it provides
the %f format, at least on some platforms, and time.strftime() does not; having
sub-second precision is pretty useful for these messages.

Diff Detail

Repository
rHG Mercurial
Lint
Lint Skipped
Unit
Unit Tests Skipped

Event Timeline

spectral created this revision.Dec 18 2017, 8:48 PM
spectral added a comment.Dec 19 2017, 2:45 PM

Someone pointed me at https://bitbucket.org/octobus/mercurial-devel/commits/668806cb43a0 and mentioned discussions on the devel mailing list that I haven't tracked down yet. Theirs is more complete and probably better than mine, so it would be nice to unify them if possible, at least in configuration.

Since this patch is only touching 'ui.debug()', it's easy to identify places where we write 'ui.debug(' and don't have a \n['"] in the line, and go and check them to see if they're actually attempting single-line output in multiple invocations. Most of the cases I found were my grep being very simplistic, some I sent patches for in this series because they *should* have had a \n or weren't doing anything, and in the end there was only this one in histedit.py:1189 that I wasn't sure about and didn't touch:

ui.debug('histedit: %s is replaced by %s\n' % (
    node.short(prec), node.short(succs[0])))
if len(succs) > 1:
    m = 'histedit:                            %s'
    for n in succs[1:]:
        ui.debug(m % node.short(n))

I'll try to track down those mailing list conversations now

spectral added a comment.Dec 19 2017, 2:50 PM

https://www.mercurial-scm.org/pipermail/mercurial-devel/2017-April/096617.html is the mailing list thread. Sounds like core is generally negative on the idea, which is disappointing, but OK. I can drop it easily :)

quark added a subscriber: quark.EditedDec 19 2017, 3:05 PM

FWIW, if you don't have ts installed. That's 4 lines in Ruby:

#!/usr/bin/env ruby
start = Time.now.to_f
STDIN.each_line do |l|
  puts "#{'%.3f' % (Time.now.to_f - start)} #{l}"
end

Besides, I believe --profile is the more correct way to do profiling.

spectral added a comment.EditedDec 19 2017, 3:16 PM

I'm not going to recommend to users to "see if you can reproduce the slowness issues while running with PYTHONUNBUFFERED=1 /usr/bin/hg --debug | ruby -e'start = Time.now.to_f' -e'STDIN.each_line do |l|' -e" puts \"#{'%.3f' % (Time.now.to_f - start)} #{l}\"" -e'end'" :) Yes, we can make a wrapper for that I suppose.

Regarding profiling: --profile is CPU profiling, right? It doesn't actually tell you *when something happened*. If you're trying to match up things in the blackbox.log with what the user saw on the screen, it doesn't help much. If you're trying to identify when the user saw pauses, it's a more complicated mechanism than just looking at the output the user saw but having timestamps. :/

Maybe that's what I should be doing instead, though. A flag/option to make it so that if debugflag is set, the blackbox gets the output in addition to the screen...

quark added a comment.EditedDec 19 2017, 4:34 PM

--profile is wall time by default. If the callgraph is more complete (ex. traceprof's case), it does tell you when something happens.

While chg does print timestamps its debug output, I think in a Python world, using a proper profiling API is cleaner than abusing ui.debug. As for now, it seems most ui.debugs are used for revealing internal states for tests to verify, less about profiling.

spectral abandoned this revision.Mar 21 2018, 5:06 PM

Revision Contents
Changeset List

Diff 4537

mercurial/configitems.py

default=False, default=False,
) )
coreconfigitem('ui', 'debug', coreconfigitem('ui', 'debug',
default=False, default=False,
) )
coreconfigitem('ui', 'debugger', coreconfigitem('ui', 'debugger',
default=None, default=None,
) )
coreconfigitem('ui', 'debugtimestampfmt',
default=None,
)
coreconfigitem('ui', 'editor', coreconfigitem('ui', 'editor',
default=dynamicdefault, default=dynamicdefault,
) )
coreconfigitem('ui', 'fallbackencoding', coreconfigitem('ui', 'fallbackencoding',
default=None, default=None,
) )
coreconfigitem('ui', 'forcecwd', coreconfigitem('ui', 'forcecwd',
default=None, default=None,

mercurial/ui.py

# ui.py - user interface bits for mercurial # ui.py - user interface bits for mercurial
# #
# Copyright 2005-2007 Matt Mackall <mpm@selenic.com> # Copyright 2005-2007 Matt Mackall <mpm@selenic.com>
# #
# This software may be used and distributed according to the terms of the # This software may be used and distributed according to the terms of the
# GNU General Public License version 2 or any later version. # GNU General Public License version 2 or any later version.
from __future__ import absolute_import from __future__ import absolute_import
import collections import collections
import contextlib import contextlib
import datetime
import errno import errno
import getpass import getpass
import inspect import inspect
import os import os
import re import re
import signal import signal
import socket import socket
import subprocess import subprocess
self.verbose = self.debugflag or self.configbool('ui', 'verbose') self.verbose = self.debugflag or self.configbool('ui', 'verbose')
self.quiet = not self.debugflag and self.configbool('ui', 'quiet') self.quiet = not self.debugflag and self.configbool('ui', 'quiet')
if self.verbose and self.quiet: if self.verbose and self.quiet:
self.quiet = self.verbose = False self.quiet = self.verbose = False
self._reportuntrusted = self.debugflag or self.configbool("ui", self._reportuntrusted = self.debugflag or self.configbool("ui",
"report_untrusted") "report_untrusted")
self.tracebackflag = self.configbool('ui', 'traceback') self.tracebackflag = self.configbool('ui', 'traceback')
self.logblockedtimes = self.configbool('ui', 'logblockedtimes') self.logblockedtimes = self.configbool('ui', 'logblockedtimes')
self.debugtimestampfmt = self.config('ui', 'debugtimestampfmt',
None)
if section in (None, 'trusted'): if section in (None, 'trusted'):
# update trust information # update trust information
self._trustusers.update(self.configlist('trusted', 'users')) self._trustusers.update(self.configlist('trusted', 'users'))
self._trustgroups.update(self.configlist('trusted', 'groups')) self._trustgroups.update(self.configlist('trusted', 'groups'))
def backupconfig(self, section, item): def backupconfig(self, section, item):
return (self._ocfg.backup(section, item), return (self._ocfg.backup(section, item),
self.write(*msg, **opts) self.write(*msg, **opts)
def debug(self, *msg, **opts): def debug(self, *msg, **opts):
'''write debug message to output (if ui.debugflag is True) '''write debug message to output (if ui.debugflag is True)
This adds an output label of "ui.debug". This adds an output label of "ui.debug".
''' '''
if self.debugflag: if self.debugflag:
opts[r'label'] = opts.get(r'label', '') + ' ui.debug' opts[r'label'] = opts.get(r'label', '') + ' ui.debug'
if self.debugtimestampfmt:
now = datetime.datetime.now()
self.write(now.strftime(self.debugtimestampfmt), ' ', **opts)
self.write(*msg, **opts) self.write(*msg, **opts)
def edit(self, text, user, extra=None, editform=None, pending=None, def edit(self, text, user, extra=None, editform=None, pending=None,
repopath=None, action=None): repopath=None, action=None):
if action is None: if action is None:
self.develwarn('action is None but will soon be a required ' self.develwarn('action is None but will soon be a required '
'parameter to ui.edit()') 'parameter to ui.edit()')
extra_defaults = { extra_defaults = {