Skip to content

Speed up Send/Receive operations significantly - #258

Merged
rmunn merged 8 commits into
masterfrom
feature/cache-hg-log-results-master
Aug 20, 2021
Merged

Speed up Send/Receive operations significantly#258
rmunn merged 8 commits into
masterfrom
feature/cache-hg-log-results-master

Conversation

@rmunn

@rmunn rmunn commented Aug 20, 2021

Copy link
Copy Markdown
Contributor

The Send/Receive code does a lot of hg log -rREV --template "{node}" calls in order to learn the long hash of a revision number. This happens very often during a Send/Receive process: the Chorus logs are full of hg log -r0 operations. Thing is, every single call to hg log incurs a cost as a Python process has to be spun up every time this happens. And in any given repository, a specific revision number wil always refer to the same revision with the same long hash, so each long hash only has to be calculated once for any given revision number. So we'll cache the output of log -rREV operations and return the cached output if the same operation runs a second time. (Other operations like hg parents aren't safe to cache, as their result will change during a Send/Receive operation as new commits are added to the repo. Only log -rREV calls are 100% safe to cache).

This is PR #257 applied to master (#257 is applied to the lfmerge branch) as suggested in #257 (review)


This change is Reviewable

@rmunn
rmunn force-pushed the feature/cache-hg-log-results-master branch from 3cd1ff2 to bc748eb Compare August 20, 2021 09:04
The Send/Receive code does a lot of `hg log -rREV --template "{node}"`
calls in order to learn the long hash of a revision number. This happens
very often during a Send/Receive process: the Chorus logs are full of
`hg log -r0` operations. Thing is, every single call to `hg log` incurs
a cost as a Python process has to be spun up every time this happens.
And in any given repository, a specific revision number wil always refer
to the same revision with the same long hash, so each long hash only has
to be calculated *once* for any given revision number. So we'll cache
the output of `log -rREV` operations and return the cached output if the
same operation runs a second time. (Other operations like `hg parents`
aren't safe to cache, as their result will change during a Send/Receive
operation as new commits are added to the repo. Only `log -rREV` calls
are 100% safe to cache).
@rmunn
rmunn force-pushed the feature/cache-hg-log-results-master branch from bc748eb to 5160d4e Compare August 20, 2021 09:09
Comment thread src/LibChorus/VcsDrivers/Mercurial/HgRepository.cs Outdated
Make ExecuteErrorsOk an instance method since there's no reason it needs
to be static (no code that uses the Chorus library can be calling it
since it's private, so this won't affect any other code). This also
allows simplifying its type signature.
@rmunn
rmunn force-pushed the feature/cache-hg-log-results-master branch from 6454df5 to ef08bf8 Compare August 20, 2021 09:26
rmunn added 3 commits August 20, 2021 16:27
Elsewhere the `command` parameter is used without checking for nullity,
so LGTM.com considers my null check to add a new possible problem. Since
this is an internal method and we're pretty much never going to pass a
null command string in here, we can remove that null check and be okay.
@rmunn

rmunn commented Aug 20, 2021

Copy link
Copy Markdown
Contributor Author

I wasn't seeing any occurrences of the "Using cached result" message in the Chorus logs while TeamCity ran the unit tests, and I just found out from looking at the logs (and then the source) that HgRepository.Execute() adds a sneaky little space character at the end of the command, so command.EndsWith("foo") wasn't returning true because the command actually ended with "foo ". Sigh. THIS version should actually fire the speedup code.

On the plus side, this means I can compare the time it took TeamCity to run the unit tests before and after commit 05fa900 and I'll have a poor man's benchmark. I still want to run a proper benchmark, but that'll help me get initial speedup numbers.

@rmunn

rmunn commented Aug 20, 2021

Copy link
Copy Markdown
Contributor Author

Preliminary results: the TeamCity build including unit tests took 1374 seconds before commit 05fa900 went in (meaning it wasn't actually running the optimizations) and the build after commit 05fa900 went in took 858 seconds. That's 62.5% of the previous value, which means that 1/3 of the build's time was being spent running hg log over and over.

Unfortunately, now four unit tests are failing because they relied on HgRepository.Identifier changing from "000000" to a non-zero value when commits are added, and my code was caching the zero result from the first time the property was accessed. I'll have to look into those tests and figure out whether it's safe to change their logic so that they expect the identifier value to be cached, or whether I should do something else.

First thought: add some logic to the caching to examine the output and, if (and only if) the output is an all-zeroes value, do not cache that value as it's going to change in the near future. That should, I think, take care of all four of the failing unit tests. But I'm running out of time to test that today.

An all-zero result from hg is highly likely to be the repo identifier of
an empty repository, which is going to change in the near future. So
we'll skip caching anything that starts with twelve zeroes in a row.
This will occasionally have a false positive, but that false positive
won't have any negative impact (a minor slowdown).
@rmunn

rmunn commented Aug 20, 2021

Copy link
Copy Markdown
Contributor Author

Bingo. That worked. One more commit and I'll feel ready to merge this. I wrote the check to use only a dozen zeroes, but I think I should compare against the full all-0 SHA value, which is encoded somewhere in the code, so I can use a reference instead of a magic string. Once that commit is merged and tests passing, I'll merge this.

This avoids using magic strings.
@rmunn
rmunn force-pushed the feature/cache-hg-log-results-master branch from 7eb3485 to 76fb646 Compare August 20, 2021 11:25
Negative revision numbers mean "counting backwards from tip", i.e.
running `hg log -r-1 --template "{node}" gets the long hash of the tip
revision. We therefore should not cache negative revision numbers as
those are subject to change.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants