sapling/tests/test-hgsql-sync-interval.t

Test hgsql tries to sync before entering the critical section

  $ . "$TESTDIR/hgsql/library.sh"
  $ setconfig hgsql.verbose=1

  $ newrepo state1
  $ hg debugdrawdag << 'EOS'
  > B
  > |
  > A
  > EOS

  $ newrepo state2
  $ hg debugdrawdag << 'EOS'
  > C
  > |
  > B
  > |
  > A
  > EOS

  $ newrepo state3
  $ hg debugdrawdag << 'EOS'
  > D
  > |
  > C
  > |
  > B
  > |
  > A
  > EOS

  $ newrepo state4
  $ hg debugdrawdag << 'EOS'
  > E
  > |
  > D
  > |
  > C
  > |
  > B
  > |
  > A
  > EOS

  $ cd $TESTTMP
  $ initserver repo1 master
  $ initserver repo2 master
  $ initserver repo3 master
  $ initserver repo4 master

Repo1: 2 commits. Sync them to the database.

  $ cd $TESTTMP/repo1
  $ hg pull -r tip $TESTTMP/state1
  [hgsql] got lock after * seconds (glob)
  pulling from $TESTTMP/state1
  adding changesets
  adding manifests
  adding file changes
  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)

Repo2: Emulate client push. Hold the lock for long.

  $ cd $TESTTMP/repo2
  $ hg  --config hooks.pretxnclose.dely='sleep 6' pull -r tip $TESTTMP/state2 &>out &
  $ disown

Repo 3: Emulate client push to sql, after repo2.

  $ sleep 2
  $ cd $TESTTMP/repo3
  $ hg  --config hooks.pretxnclose.dely='sleep 6' pull -r tip $TESTTMP/state3 &>out &
  $ disown

Emulate writing to another repo when the lock was held elsewhere.
Explaination:
- The first "getting 2 commits from database" is because repo4 is empty, and the database has A,B synced from repo1.
- The second "getting 1 commits from database" is because repo2 push completes.
- The third "getting 1 commits from database" is because repo3 push completes.

  $ cd $TESTTMP/repo4
  $ setconfig hgsql.syncinterval=0.1 hgsql.debugminsqllockwaittime=13
  $ hg pull -r tip $TESTTMP/state4
  [hgsql] getting 2 commits from database
  [hgsql] getting 1 commits from database
  [hgsql] getting 1 commits from database
  [hgsql] got lock after * seconds (glob)
  pulling from $TESTTMP/state4
  searching for changes
  adding changesets
  adding manifests
  adding file changes
  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)

Make sure repo2 and repo3 log looks sane.

  $ cat $TESTTMP/repo2/out
  [hgsql] getting 2 commits from database
  [hgsql] got lock after * seconds (glob)
  pulling from $TESTTMP/state2
  searching for changes
  adding changesets
  adding manifests
  adding file changes
  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)

  $ cat $TESTTMP/repo3/out
  [hgsql] getting 2 commits from database
  [hgsql] got lock after * seconds (glob)
  [hgsql] getting 1 commits from database
  pulling from $TESTTMP/state3
  searching for changes
  adding changesets
  adding manifests
  adding file changes
  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: sync repos before acquiring the SQL write lock Summary: When entering the critical section (creating a transaction), hgsql might wait for SQL lock for a long time (minutes). And it currently does nothing during that wait time. If the lock was acquired after a long time, the work of catching up with what the database already has might be too much. That is a waste within the precious hgsql lock held critical section. Instead of waiting for the lock for N seconds and doing nothing, wait for k (k < N) seconds and also try to sync with SQL periodically. This makes the repo closer to what the database has and can reduce work needed to pull from the database in the critical section. This adds CPU pressure to the MySQL tier. I added a config option to control it. Worse case, we can change `hgsql.syncinterval` to make the sync less frequent. As we're here, try document the configs. Reviewed By: phillco Differential Revision: D10002578 fbshipit-source-id: bd72d8225c919aa2bc62743de1e1d3f27cba606a 2018-09-26 02:04:12 +03:00			`Test hgsql tries to sync before entering the critical section`

			`$ . "$TESTDIR/hgsql/library.sh"`
			`$ setconfig hgsql.verbose=1`

			`$ newrepo state1`
			`$ hg debugdrawdag << 'EOS'`
			`> B`
			`> \|`
			`> A`
			`> EOS`

			`$ newrepo state2`
			`$ hg debugdrawdag << 'EOS'`
			`> C`
			`> \|`
			`> B`
			`> \|`
			`> A`
			`> EOS`

			`$ newrepo state3`
			`$ hg debugdrawdag << 'EOS'`
			`> D`
			`> \|`
			`> C`
			`> \|`
			`> B`
			`> \|`
			`> A`
			`> EOS`

			`$ newrepo state4`
			`$ hg debugdrawdag << 'EOS'`
			`> E`
			`> \|`
			`> D`
			`> \|`
			`> C`
			`> \|`
			`> B`
			`> \|`
			`> A`
			`> EOS`

			`$ cd $TESTTMP`
			`$ initserver repo1 master`
			`$ initserver repo2 master`
			`$ initserver repo3 master`
			`$ initserver repo4 master`

			`Repo1: 2 commits. Sync them to the database.`

			`$ cd $TESTTMP/repo1`
			`$ hg pull -r tip $TESTTMP/state1`
			`[hgsql] got lock after * seconds (glob)`
			`pulling from $TESTTMP/state1`
			`adding changesets`
			`adding manifests`
			`adding file changes`
			`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)`

			`Repo2: Emulate client push. Hold the lock for long.`

			`$ cd $TESTTMP/repo2`
			`$ hg --config hooks.pretxnclose.dely='sleep 6' pull -r tip $TESTTMP/state2 &>out &`
			`$ disown`

			`Repo 3: Emulate client push to sql, after repo2.`

			`$ sleep 2`
			`$ cd $TESTTMP/repo3`
			`$ hg --config hooks.pretxnclose.dely='sleep 6' pull -r tip $TESTTMP/state3 &>out &`
			`$ disown`

			`Emulate writing to another repo when the lock was held elsewhere.`
			`Explaination:`
			`- The first "getting 2 commits from database" is because repo4 is empty, and the database has A,B synced from repo1.`
			`- The second "getting 1 commits from database" is because repo2 push completes.`
			`- The third "getting 1 commits from database" is because repo3 push completes.`

			`$ cd $TESTTMP/repo4`
			`$ setconfig hgsql.syncinterval=0.1 hgsql.debugminsqllockwaittime=13`
			`$ hg pull -r tip $TESTTMP/state4`
			`[hgsql] getting 2 commits from database`
			`[hgsql] getting 1 commits from database`
			`[hgsql] getting 1 commits from database`
			`[hgsql] got lock after * seconds (glob)`
			`pulling from $TESTTMP/state4`
			`searching for changes`
			`adding changesets`
			`adding manifests`
			`adding file changes`
			`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)`

			`Make sure repo2 and repo3 log looks sane.`

			`$ cat $TESTTMP/repo2/out`
			`[hgsql] getting 2 commits from database`
			`[hgsql] got lock after * seconds (glob)`
			`pulling from $TESTTMP/state2`
			`searching for changes`
			`adding changesets`
			`adding manifests`
			`adding file changes`
			`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)`

			`$ cat $TESTTMP/repo3/out`
			`[hgsql] getting 2 commits from database`
			`[hgsql] got lock after * seconds (glob)`
			`[hgsql] getting 1 commits from database`
			`pulling from $TESTTMP/state3`
			`searching for changes`
			`adding changesets`
			`adding manifests`
			`adding file changes`
			`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)`