This is an archive of the discontinued Mercurial Phabricator instance.

Differential D1049

remotefilelog: add logging for prefetch during commit
AbandonedPublic

Authored by stash on Oct 13 2017, 5:37 AM.
Tags
None
Subscribers
durham, quark

Details

Reviewers
quark
Group Reviewers
Restricted Project
Summary

Prefetch during commit means that commit may fail offline.
Unfortunately we don't know why it happens. Let's log these events to
investigate.

Test Plan

Run unit-tests

Diff Detail

Repository
rFBHGX Facebook Mercurial Extensions
Branch
default
Lint
Lint OK
Unit
Unit Tests OK

Event Timeline

stash created this revision.Oct 13 2017, 5:37 AM
quark accepted this revision.Oct 16 2017, 6:30 PM
quark added a subscriber: quark.

I guess prefetch could happen when linkrev is incorrect.

remotefilelog/__init__.py
136

Is there a reason to wrap runcommand? I think you can just change fileservice directly?

This revision is now accepted and ready to land.Oct 16 2017, 6:30 PM
quark added inline comments.Oct 17 2017, 1:04 PM
remotefilelog/__init__.py
138

I see. You're checking if the command is commit. That has to be done via runcommand unfortunately.

durham added a subscriber: durham.Oct 31 2017, 12:29 PM
durham added inline comments.
remotefilelog/__init__.py
138

Instead of putting fileserver logging code up here, can we put the command name somewhere that the fileserver can read? Like temporary attribute on the ui object? Then the fileserver can have it's own logic check that. Other parts of the code might want to know the current command as well, so it would help them too.

stash abandoned this revision.Nov 30 2017, 5:08 AM

It's not that necessary now, and requires more work to get it done. I'm going to abandon the diff.

Revision Contents
Changeset List

Diff 2666

remotefilelog/__init__.py

templatekw, templatekw,
util, util,
) )
import os import os
import time import time
import traceback import traceback
from functools import partial
# ensures debug commands are registered # ensures debug commands are registered
hgdebugcommands.command hgdebugcommands.command
try: try:
from mercurial import streamclone from mercurial import streamclone
streamclone._walkstreamfiles streamclone._walkstreamfiles
hasstreamclone = True hasstreamclone = True
except Exception: except Exception:
if lfsmod: if lfsmod:
lfsmod.wrapfilelog(remotefilelog.remotefilelog) lfsmod.wrapfilelog(remotefilelog.remotefilelog)
fileserverclient._lfsmod = lfsmod fileserverclient._lfsmod = lfsmod
extensions.afterloaded('lfs', _lfsloaded) extensions.afterloaded('lfs', _lfsloaded)
# debugdata needs remotefilelog.len to work # debugdata needs remotefilelog.len to work
extensions.wrapcommand(commands.table, 'debugdata', debugdatashallow) extensions.wrapcommand(commands.table, 'debugdata', debugdatashallow)
def extsetup(ui):
def _runcommandwrapper(orig, lui, repo, cmd, *args, **kwargs):
quarkUnsubmitted
Not Done

Is there a reason to wrap runcommand? I think you can just change fileservice directly?

quark: Is there a reason to wrap runcommand? I think you can just change `fileservice` directly?
if util.safehasattr(repo, 'fileservice') and cmd == 'commit':
quarkUnsubmitted
Not Done

I see. You're checking if the command is commit. That has to be done via runcommand unfortunately.

quark: I see. You're checking if the command is `commit`. That has to be done via runcommand…
durhamUnsubmitted
Not Done

Instead of putting fileserver logging code up here, can we put the command name somewhere that the fileserver can read? Like temporary attribute on the ui object? Then the fileserver can have it's own logic check that. Other parts of the code might want to know the current command as well, so it would help them too.

durham: Instead of putting fileserver logging code up here, can we put the command name somewhere that…
# Currently prefetches happen even during commit, and that means
# that sometimes it's impossible to commit offline. This is a very
# bad user experience, but we don't know when and why it happens.
# This logger should help us with that.
logger = partial(lui.log, 'remotefilelogcommitprefetch',
user=shallowutil.getusername(repo.ui))
repo.fileservice.logger = logger
return orig(lui, repo, cmd, *args)
extensions.wrapfunction(dispatch, 'runcommand', _runcommandwrapper)
def cloneshallow(orig, ui, repo, *args, **opts): def cloneshallow(orig, ui, repo, *args, **opts):
if opts.get('shallow'): if opts.get('shallow'):
repos = [] repos = []
def pull_shallow(orig, self, *args, **kwargs): def pull_shallow(orig, self, *args, **kwargs):
if shallowrepo.requirement not in self.requirements: if shallowrepo.requirement not in self.requirements:
repos.append(self.unfiltered()) repos.append(self.unfiltered())
# set up the client hooks so the post-clone update works # set up the client hooks so the post-clone update works
setupclient(self.ui, self.unfiltered()) setupclient(self.ui, self.unfiltered())

remotefilelog/fileserverclient.py

historystore = unionmetadatastore(*repo.sharedhistorystores) historystore = unionmetadatastore(*repo.sharedhistorystores)
missingids = set() missingids = set()
if fetchdata: if fetchdata:
missingids.update(datastore.getmissing(idstocheck)) missingids.update(datastore.getmissing(idstocheck))
if fetchhistory: if fetchhistory:
missingids.update(historystore.getmissing(idstocheck)) missingids.update(historystore.getmissing(idstocheck))
if util.safehasattr(self, 'logger') and missingids:
# logger is set if we want to log all prefetches (for example,
# prefetches that happen during command that shouldn't require
# network connection like hg commit).
# Since there can be a lot of missing ids, let's log just first 5
# of them
files = ['(%s %s)' % (f[0], hex(f[1]))
for f in sorted(list(missingids))[:5]]
self.logger(files=', '.join(files), total=len(missingids))
# partition missing nodes into nullid and not-nullid so we can # partition missing nodes into nullid and not-nullid so we can
# warn about this filtering potentially shadowing bugs. # warn about this filtering potentially shadowing bugs.
nullids = len([None for unused, id in missingids if id == nullid]) nullids = len([None for unused, id in missingids if id == nullid])
if nullids: if nullids:
missingids = [(f, id) for f, id in missingids if id != nullid] missingids = [(f, id) for f, id in missingids if id != nullid]
repo.ui.develwarn( repo.ui.develwarn(
('remotefilelog not fetching %d null revs' ('remotefilelog not fetching %d null revs'
' - this is likely hiding bugs' % nullids), ' - this is likely hiding bugs' % nullids),

tests/test-remotefilelog-commit-logging.t

  • This file was added.
Currently 'hg commit' sometimes requires network connection, and that means
that people can't commit offline. Let's log these issues to understand why and
how often it happens.
$ PYTHONPATH=$TESTDIR/..:$PYTHONPATH
$ export PYTHONPATH
$ . "$TESTDIR/library.sh"
$ hginit master
$ cd master
$ cat >> .hg/hgrc <<EOF
> [remotefilelog]
> server=True
> EOF
$ echo x > x
$ hg commit -qAm x
$ mkdir dir
$ echo y > dir/y
$ hg commit -qAm y
$ cd ..
Shallow clone from full
$ hgcloneshallow ssh://user@dummy/master shallow --noupdate
streaming all changes
2 files to transfer, 473 bytes of data
transferred 473 bytes in * seconds (*/sec) (glob)
searching for changes
no changes found
$ cd shallow
Setup extension that logs ui.log linkrevfixup output on the stderr
$ cat >> $TESTTMP/uilog.py <<EOF
> from mercurial import extensions
> from mercurial import ui as uimod
> def uisetup(ui):
> extensions.wrapfunction(uimod.ui, 'log', mylog)
> def mylog(orig, self, service, *msg, **opts):
> if service in ['remotefilelogcommitprefetch']:
> kwstr = ", ".join("%s=%s" % (k, v) for k, v in
> sorted(opts.iteritems()))
> self.warn('%s: %s\n' % (service, kwstr))
> return orig(self, service, *msg, **opts)
> EOF
$ cat >> $HGRCPATH <<EOF
> [extensions]
> uilog=$TESTTMP/uilog.py
> EOF
$ hg update
2 files updated, 0 files merged, 0 files removed, 0 files unresolved
2 files fetched over 1 fetches - (2 misses, 0.00% hit ratio) over *s (glob)
Delete the cache - it should trigger prefetch
$ rm -r $TESTTMP/hgcache
$ echo y > x
$ hg ci -m test
remotefilelogcommitprefetch: files=(dir/y 076f5e2225b3ff0400b98c92aa6cdf403ee24cca), (x 1406e74118627694268417491f018a4a883152f0), total=2, user=test
2 files fetched over 1 fetches - (2 misses, 0.00% hit ratio) over *s (glob)
Make sure that next commit doesn't trigger prefetch
$ echo z > x
$ hg ci -m test2