facebook/sapling
1
1
Fork 0
mirror of https://github.com/facebook/sapling.git synced 2025-01-04 03:06:30 +03:00
Code Issues Projects Releases Wiki Activity

hgsql: log rows read and write

Browse Source 
Summary:
This gives us more information about how large the hgsql operation is.

As we're here, move `sqlwriteunlock` to an earlier place so the logging is outside
the sql lock. Also document `unbundle` a bit so it's clear `repo.transaction()` only
takes sql lock in `unbundle` context.

Reviewed By: phillco

Differential Revision: D10056307

fbshipit-source-id: 5d3361b4044e6fcf01e60409ef1ecb34da34ccac
This commit is contained in:
Jun Wu 2018-09-26 16:32:10 -07:00 committed by Facebook Github Bot
parent 4ddedaf7d2
commit 9cf0c87149
5 changed files with 81 additions and 43 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

62
hgext/hgsql.py
View File

@ -271,7 +271,10 @@ def reposetup(ui, repo):
executewithsql(repo, noop, waitforlock=waitforlock)
# Incoming commits are only allowed via push and pull
# Incoming commits are only allowed via push and pull.
# This changes repo.transaction to take a sql write lock. Note:
# repo.transaction outside unbundle is not changed. Question: is it better
# to change repo.transaction for everything?
def unbundle(orig, repo, cg, *args, **kwargs):
if not issqlrepo(repo):
return orig(repo, cg, *args, **kwargs)
@ -427,6 +430,9 @@ class sqlcontext(object):
self._active = True
repo = self.repo
repo._sqlreadrows = 0
repo._sqlwriterows = 0
if not repo.sqlconn:
repo.sqlconnect()
self._connected = True
@ -439,7 +445,7 @@ class sqlcontext(object):
elapsed = time.time() - startwait
repo.ui.log(
"sqllock",
"failed to get sql lock after %s " "seconds\n",
"failed to get sql lock after %s seconds\n",
elapsed,
elapsed=elapsed * 1000,
valuetype="lockwait",
@ -454,14 +460,20 @@ class sqlcontext(object):
elapsed = time.time() - startwait
repo.ui.log(
"sqllock",
"waited for sql lock for %s seconds\n",
"waited for sql lock for %s seconds (read %s rows)\n",
elapsed,
repo._sqlreadrows,
elapsed=elapsed * 1000,
valuetype="lockwait",
success="true",
readrows=repo._sqlreadrows,
repository=repo.root,
)
repo._hgsqlnote("got lock after %.2f seconds" % elapsed)
repo._hgsqlnote(
"got lock after %.2f seconds (read %s rows)"
% (elapsed, repo._sqlreadrows)
)
repo._sqlreadrows = 0
self._startlocktime = time.time()
if self._connected:
@ -472,17 +484,24 @@ class sqlcontext(object):
repo = self.repo
if self._locked:
elapsed = time.time() - self._startlocktime
repo.sqlwriteunlock()
self._stopprofile(elapsed)
repo.ui.log(
"sqllock",
"held sql lock for %s seconds\n",
"held sql lock for %s seconds (read %s rows; write %s rows)\n",
elapsed,
repo._sqlreadrows,
repo._sqlwriterows,
elapsed=elapsed * 1000,
valuetype="lockheld",
repository=repo.root,
readrows=repo._sqlreadrows,
writerows=repo._sqlwriterows,
)
repo._hgsqlnote(
"held lock for %.2f seconds (read %s rows; write %s rows)"
% (elapsed, repo._sqlreadrows, repo._sqlwriterows)
)
self._stopprofile(elapsed)
repo.sqlwriteunlock()
repo._hgsqlnote("held lock for %.2f seconds" % elapsed)
if self._connected:
repo.sqlclose()
@ -600,6 +619,25 @@ def wraprepo(repo):
self.locktimeout = self.sqlconn.converter.escape("%s" % self.locktimeout)
self.sqlcursor = self.sqlconn.cursor()
self._sqlreadrows = 0
self._sqlwriterows = 0
# Patch sqlcursor so it updates the read write counters.
def _fetchallupdatereadcount(orig):
result = orig()
self._sqlreadrows += self.sqlcursor.rowcount
return result
def _executeupdatewritecount(orig, sql, *args, **kwargs):
result = orig(sql, *args, **kwargs)
# naive ways to detect "writes"
if sql.split(" ", 1)[0].upper() in {"DELETE", "UPDATE", "INSERT"}:
self._sqlwriterows += self.sqlcursor.rowcount
return result
wrapfunction(self.sqlcursor, "fetchall", _fetchallupdatereadcount)
wrapfunction(self.sqlcursor, "execute", _executeupdatewritecount)
self.sqlcursor.execute("SET wait_timeout=%s" % waittimeout)
if self.engine == "rocksdb":
@ -1469,7 +1507,7 @@ def wraprepo(repo):
localnode = hex(rl.node(rev))
if localnode != node:
raise CorruptionException(
("expected node %s at rev %d of " "%s but found %s")
("expected node %s at rev %d of %s but found %s")
% (node, rev, path, localnode)
)
@ -2004,7 +2042,7 @@ def sqlrecover(ui, *args, **opts):
"",
"i-know-what-i-am-doing",
None,
_("only run sqltreestrip if you " "know exactly what you're doing"),
_("only run sqltreestrip if you know exactly what you're doing"),
),
],
_("hg sqltreestrip REV"),
@ -2019,7 +2057,7 @@ def sqltreestrip(ui, repo, rev, *args, **opts):
return 1
if not repo.ui.configbool("treemanifest", "server"):
ui.warn(_("this repository is not configured to be a treemanifest " "server\n"))
ui.warn(_("this repository is not configured to be a treemanifest server\n"))
return 1
if not opts.get("i_know_what_i_am_doing"):
@ -2547,7 +2585,7 @@ def _sqlverify(repo, minrev, maxrev, revlogcache):
revlogentry = rl.index[rev]
if revlogentry != sqlentry:
raise CorruptionException(
("'%s:%s' with linkrev %s, disk does " "not match mysql")
("'%s:%s' with linkrev %s, disk does not match mysql")
% (path, hex(node), str(linkrev))
)
finally:

16
tests/test-fb-hgext-pushrebase-cannot-rebasepublic.t
View File

@ -40,8 +40,8 @@ Set up server repository.
$ config_server
$ echo foo > base
$ commit "base"
[hgsql] got lock after * seconds (glob)
[hgsql] held lock for * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
[hgsql] held lock for * seconds (read 5 rows; write 5 rows) (glob)
$ cd ..
Add a new commit to server2 (as if we stripped in server1):
@ -50,11 +50,11 @@ Add a new commit to server2 (as if we stripped in server1):
$ cd server2
$ echo foo > a
$ commit "first"
[hgsql] got lock after * seconds (glob)
[hgsql] held lock for * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
[hgsql] held lock for * seconds (read 7 rows; write 7 rows) (glob)
$ hg book -r . master
[hgsql] got lock after * seconds (glob)
[hgsql] held lock for * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
[hgsql] held lock for * seconds (read 4 rows; write 1 rows) (glob)
$ log
@ first [draft:8585ef078134] master
|
@ -86,9 +86,9 @@ Create a _third_ draft commit, push to the (behind) server1:
remote: checking conflicts with 8585ef078134
remote: pushing 1 changeset:
remote: 87df66bba286 third commit
remote: [hgsql] got lock after * seconds (glob)
remote: [hgsql] got lock after * seconds (read 1 rows) (glob)
remote: rebasing stack from 8585ef078134 onto 8585ef078134
remote: [hgsql] held lock for * seconds (glob)
remote: [hgsql] held lock for * seconds (read 6 rows; write 9 rows) (glob)
updating bookmark master

6
tests/test-hgsql-metrics.t
View File

@ -64,11 +64,11 @@
$ hg push ssh://user@dummy/master
pushing to ssh://user@dummy/master
searching for changes
remote: sqllock: waited for sql lock for * seconds (glob)
remote: sqllock: waited for sql lock for * seconds (read 1 rows) (glob)
remote: (elapsed=*, repository=$TESTTMP/master, success=true, valuetype=lockwait) (glob)
remote: adding changesets
remote: adding manifests
remote: adding file changes
remote: added 1 changesets with 1 changes to 1 files
remote: sqllock: held sql lock for * seconds (glob)
remote: (elapsed=*, repository=$TESTTMP/master, valuetype=lockheld) (glob)
remote: sqllock: held sql lock for * seconds (read 5 rows; write 5 rows) (glob)
remote: (elapsed=*, readrows=5, repository=$TESTTMP/master, valuetype=lockheld, writerows=5) (glob)

16
tests/test-hgsql-sync-interval.t
View File

@ -53,7 +53,7 @@ Repo1: 2 commits. Sync them to the database.
$ cd $TESTTMP/repo1
$ hg pull -r tip $TESTTMP/state1
[hgsql] got lock after * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
pulling from $TESTTMP/state1
adding changesets
adding manifests
@ -61,7 +61,7 @@ Repo1: 2 commits. Sync them to the database.
added 2 changesets with 2 changes to 2 files
new changesets 426bada5c675:112478962961
(run 'hg update' to get a working copy)
[hgsql] held lock for * seconds (glob)
[hgsql] held lock for * seconds (read 5 rows; write 8 rows) (glob)
Repo2: Emulate client push. Hold the lock for long.
@ -88,7 +88,7 @@ Explaination:
[hgsql] getting 2 commits from database
[hgsql] getting 1 commits from database
[hgsql] getting 1 commits from database
[hgsql] got lock after * seconds (glob)
[hgsql] got lock after * seconds (read * rows) (glob)
pulling from $TESTTMP/state4
searching for changes
adding changesets
@ -97,13 +97,13 @@ Explaination:
added 1 changesets with 1 changes to 1 files
new changesets 9bc730a19041
(run 'hg update' to get a working copy)
[hgsql] held lock for * seconds (glob)
[hgsql] held lock for * seconds (read * rows; write 7 rows) (glob)
Make sure repo2 and repo3 log looks sane.
$ cat $TESTTMP/repo2/out
[hgsql] getting 2 commits from database
[hgsql] got lock after * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
pulling from $TESTTMP/state2
searching for changes
adding changesets
@ -112,11 +112,11 @@ Make sure repo2 and repo3 log looks sane.
added 1 changesets with 1 changes to 1 files
new changesets 26805aba1e60
(run 'hg update' to get a working copy)
[hgsql] held lock for * seconds (glob)
[hgsql] held lock for * seconds (read 6 rows; write 7 rows) (glob)
$ cat $TESTTMP/repo3/out
[hgsql] getting 2 commits from database
[hgsql] got lock after * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
[hgsql] getting 1 commits from database
pulling from $TESTTMP/state3
searching for changes
@ -126,4 +126,4 @@ Make sure repo2 and repo3 log looks sane.
added 1 changesets with 1 changes to 1 files
new changesets f585351a92f8
(run 'hg update' to get a working copy)
[hgsql] held lock for * seconds (glob)
[hgsql] held lock for * seconds (read 6 rows; write 7 rows) (glob)

24
tests/test-hgsql-sync.t
View File

@ -21,8 +21,8 @@
$ cd master
$ hg log
$ hg pull -q ../client
[hgsql] got lock after * seconds (glob)
[hgsql] held lock for * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
[hgsql] held lock for * seconds (read 5 rows; write 5 rows) (glob)
$ cd ..
@ -73,8 +73,8 @@
pushing to ssh://user@dummy/master
searching for changes
no changes found
remote: [hgsql] got lock after * seconds (glob)
remote: [hgsql] held lock for * seconds (glob)
remote: [hgsql] got lock after * seconds (read 1 rows) (glob)
remote: [hgsql] held lock for * seconds (read 4 rows; write 1 rows) (glob)
exporting bookmark mybook
[1]
$ cd ../master2
@ -91,8 +91,8 @@
$ hg commit -qAm z
$ cd ../master
$ hg pull -q ssh://user@dummy/client
[hgsql] got lock after * seconds (glob)
[hgsql] held lock for * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
[hgsql] held lock for * seconds (read 6 rows; write 9 rows) (glob)
$ cd ../master2
$ hg log -l 1
[hgsql] getting 1 commits from database
@ -106,16 +106,16 @@
# Delete a bookmark in one, verify in the other
$ hg book book1
[hgsql] got lock after * seconds (glob)
[hgsql] held lock for * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
[hgsql] held lock for * seconds (read 4 rows; write 1 rows) (glob)
$ cd ../master
$ hg book
[hgsql] getting 0 commits from database
book1 -1:000000000000
mybook 2:f3a7cb746fa9
$ hg book -d book1
[hgsql] got lock after * seconds (glob)
[hgsql] held lock for * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
[hgsql] held lock for * seconds (read 4 rows; write 1 rows) (glob)
$ cd ../master2
$ hg book
[hgsql] getting 0 commits from database
@ -168,9 +168,9 @@
> EOF
$ cd master
$ INSPECTSQL=DELETE,INSERT hg book mybook2
[hgsql] got lock after * seconds (glob)
[hgsql] got lock after * seconds (read 1 rows) (glob)
INSERT INTO revision_references(repo, namespace, name, value) VALUES (masterrepo, 'bookmarks', mybook2, 0000000000000000000000000000000000000000)
INSERT INTO revision_references(repo, namespace, name, value) VALUES(masterrepo, 'tip', 'tip', 3) ON DUPLICATE KEY UPDATE value=3
[hgsql] held lock for * seconds (glob)
[hgsql] held lock for * seconds (read 4 rows; write 1 rows) (glob)
$ cd ..
$ cp backup.hgrc $HGRCPATH