Regression: smartlog at HEAD is slower than v0.5.0 #625

mlcui-corp · 2022-11-07T04:36:50Z

Description of the bug

git-branchless smartlog is quite quick on v0.5.0 under the Chromium repository:

$ time git-branchless smartlog
⋮
◇ 106ec00 45m (main, remote origin/main) Roll src/net/third_party/quiche/src/ 6cea8f629..6a9bf1889 (21 commits)
┣━┓
┃ ◯ d191dad 37m (redacted) [redacted]
┣━┓
┃ ◯ ee48c93 37m (redacted) [redacted]
┃
◯ f697958 32m [redacted]
┃
◯ 58ad601 32m [redacted]
┃
◯ 710dc0e 31m [redacted]
┃
● 6894f27 31m (ᐅ redacted) [redacted]
git-branchless smartlog  0.03s user 0.05s system 99% cpu 0.083 total

but it is much slower at HEAD:

$ time ~/git/git-branchless/target/release/git-branchless smartlog
⋮
◇ 106ec00 45m (main, remote origin/main) Roll src/net/third_party/quiche/src/ 6cea8f629..6a9bf1889 (21 commits)
┣━┓
┃ ◯ d191dad 37m (redacted) [redacted]
┣━┓
┃ ◯ ee48c93 37m (redacted) [redacted]
┃
◯ f697958 32m [redacted]
┃
◯ 58ad601 32m [redacted]
┃
◯ 710dc0e 31m [redacted]
┃
● 6894f27 31m (ᐅ redacted) [redacted]
~/git/git-branchless/target/release/git-branchless  1.53s user 0.06s system 100% cpu 1.590 total

It spends 1.4-1.5 seconds with this loading message: Evaluating revset: union(union(draft(), branches()), @)

A bisect showed c90b52f as the culprit commit.

Expected behavior

git-branchless smartlog is fast (<0.2s runtime).

Actual behavior

git-branchless smartlog is slow (>1s runtime).

Version of `rustc`

No response

Automated bug report

Software version

git-branchless 0.5.0 (v0.3.6-nixos.0-605-gc90b52f)

Operating system

Linux 5.18.16-1rodete4-amd64

(rodete is Google's Rolling Debian Testing release.)

Command-line

~/git/git-branchless/target/release/git-branchless bug-report

Environment variables

SHELL=/bin/zsh
EDITOR=nvim

Git version

> git version 
git version 2.38.1.431.g37b22c650d-goog

Hooks

Show 6 hooks

Hook `post-commit`

#!/bin/sh
## START BRANCHLESS CONFIG

git branchless hook-post-commit "$@"
## END BRANCHLESS CONFIG

Hook `post-merge`

#!/bin/sh
## START BRANCHLESS CONFIG

git branchless hook-post-merge "$@"
## END BRANCHLESS CONFIG

Hook `post-rewrite`

#!/bin/sh
## START BRANCHLESS CONFIG

git branchless hook-post-rewrite "$@"
## END BRANCHLESS CONFIG

Hook `post-checkout`

#!/bin/sh
## START BRANCHLESS CONFIG

git branchless hook-post-checkout "$@"
## END BRANCHLESS CONFIG

Hook `pre-auto-gc`

#!/bin/sh
## START BRANCHLESS CONFIG

git branchless hook-pre-auto-gc "$@"
## END BRANCHLESS CONFIG

Hook `reference-transaction`

#!/bin/sh
## START BRANCHLESS CONFIG

# Avoid canceling the reference transaction in the case that `branchless` fails
# for whatever reason.
git branchless hook-reference-transaction "$@" || (
echo 'branchless: Failed to process reference transaction!'
echo 'branchless: Some events (e.g. branch updates) may have been lost.'
echo 'branchless: This is a bug. Please report it.'
)
## END BRANCHLESS CONFIG

Events

Show 5 events

Event ID: 370, transaction ID: 63 (message: checkout)

WorkingCopySnapshot { timestamp: 1667793444.537032, event_tx_id: EventTransactionId(63), head_oid: ee48c934d22c5905048203dfb0053e3dd74ebce8, commit_oid: NonZeroOid(e103bfe874692da2aa80d04219714bcdfdbfa36b), ref_name: Some(ReferenceName("refs/heads/redacted-ref-0")) }
RefUpdateEvent { timestamp: 1667793445.520311, event_tx_id: EventTransactionId(63), ref_name: ReferenceName("HEAD"), old_oid: ee48c934d22c5905048203dfb0053e3dd74ebce8, new_oid: 6894f271131b48e50afa69d5ab91e806f9854535, message: None }

:
O 47b81ab 25d xxxxxx xxxx xxxx xxxx xxxxxxxxxxxxxx
|\
| x 21477bf 25d (rewritten as f697958b) xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
| |
| x 2717372 25d (rewritten as 58ad6016) xxx xxxxxxxx xxxxxxxxx xxxx
| |
| x b64ae1b 25d (rewritten as 710dc0ee) xxxx xxxxxxxxxxxxxxxxxxxxxxx
| |
| x f880f9f 25d (rewritten as 6894f271) xxx
|\
| x a298fca 25d (rewritten as d191dad3) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
: x a1f7919 1h (rewritten as ee48c934) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
: |
: x 41c4a55 1h (manually hidden) xxxxxx xxxx
: |
: x a4d1cc4 1h (manually hidden) xxxxxx xxxxxxx xxxxx
:
O 106ec00 40m (main) xxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxx xxx xxxxxxxx
|\
| o d191dad 32m (redacted-ref-1) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
| o ee48c93 32m (redacted-ref-0) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
|
o f697958 27m xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
|
o 58ad601 27m xxx xxxxxxxx xxxxxxxxx xxxx
|
o 710dc0e 26m xxxx xxxxxxxxxxxxxxxxxxxxxxx
|
@ 6894f27 26m (redacted-ref-2) xxx

Event ID: 368, transaction ID: 61 (message: checkout)

WorkingCopySnapshot { timestamp: 1667793424.9770467, event_tx_id: EventTransactionId(61), head_oid: d191dad369fb881ce73a859febb6704d3bb95305, commit_oid: NonZeroOid(423f1cd04163d42049a110d68014700c3493fba1), ref_name: Some(ReferenceName("refs/heads/redacted-ref-1")) }
RefUpdateEvent { timestamp: 1667793425.944182, event_tx_id: EventTransactionId(61), ref_name: ReferenceName("HEAD"), old_oid: d191dad369fb881ce73a859febb6704d3bb95305, new_oid: ee48c934d22c5905048203dfb0053e3dd74ebce8, message: None }

:
O 47b81ab 25d xxxxxx xxxx xxxx xxxx xxxxxxxxxxxxxx
|\
| x 21477bf 25d (rewritten as f697958b) xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
| |
| x 2717372 25d (rewritten as 58ad6016) xxx xxxxxxxx xxxxxxxxx xxxx
| |
| x b64ae1b 25d (rewritten as 710dc0ee) xxxx xxxxxxxxxxxxxxxxxxxxxxx
| |
| x f880f9f 25d (rewritten as 6894f271) xxx
|\
| x a298fca 25d (rewritten as d191dad3) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
: x a1f7919 1h (rewritten as ee48c934) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
: |
: x 41c4a55 1h (manually hidden) xxxxxx xxxx
: |
: x a4d1cc4 1h (manually hidden) xxxxxx xxxxxxx xxxxx
:
O 106ec00 40m (main) xxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxx xxx xxxxxxxx
|\
| o d191dad 32m (redacted-ref-1) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
| o ee48c93 32m (redacted-ref-0) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
|
o f697958 27m xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
|
o 58ad601 27m xxx xxxxxxxx xxxxxxxxx xxxx
|
o 710dc0e 26m xxxx xxxxxxxxxxxxxxxxxxxxxxx
|
@ 6894f27 26m (redacted-ref-2) xxx

Event ID: 367, transaction ID: 60 (message: hook-post-checkout)

RefUpdateEvent { timestamp: 1667793075.8793802, event_tx_id: EventTransactionId(60), ref_name: ReferenceName("HEAD"), old_oid: 106ec001bf94906f443f15904867343528c50354, new_oid: d191dad369fb881ce73a859febb6704d3bb95305, message: None }

:
O 47b81ab 25d xxxxxx xxxx xxxx xxxx xxxxxxxxxxxxxx
|\
| x 21477bf 25d (rewritten as f697958b) xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
| |
| x 2717372 25d (rewritten as 58ad6016) xxx xxxxxxxx xxxxxxxxx xxxx
| |
| x b64ae1b 25d (rewritten as 710dc0ee) xxxx xxxxxxxxxxxxxxxxxxxxxxx
| |
| x f880f9f 25d (rewritten as 6894f271) xxx
|\
| x a298fca 25d (rewritten as d191dad3) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
: x a1f7919 1h (rewritten as ee48c934) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
: |
: x 41c4a55 1h (manually hidden) xxxxxx xxxx
: |
: x a4d1cc4 1h (manually hidden) xxxxxx xxxxxxx xxxxx
:
O 106ec00 40m (main) xxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxx xxx xxxxxxxx
|\
| o d191dad 32m (redacted-ref-1) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
| o ee48c93 32m (redacted-ref-0) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
|
o f697958 27m xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
|
o 58ad601 27m xxx xxxxxxxx xxxxxxxxx xxxx
|
o 710dc0e 26m xxxx xxxxxxxxxxxxxxxxxxxxxxx
|
@ 6894f27 26m (redacted-ref-2) xxx

Event ID: 360, transaction ID: 59 (message: hook-post-rewrite)

RewriteEvent { timestamp: 1667793048.3937514, event_tx_id: EventTransactionId(59), old_commit_oid: 21477bf7bbe22c4ae875f310cab196fb718b351d, new_commit_oid: f697958be1d6d9121ecd3c41b15a882af22b4a69 }
RewriteEvent { timestamp: 1667793048.3937514, event_tx_id: EventTransactionId(59), old_commit_oid: 2717372cb090f4ef99bef68c4d0bf16bf45771d2, new_commit_oid: 58ad601600caf6db760df0e88c1bbe68c6bdda71 }
RewriteEvent { timestamp: 1667793048.3937514, event_tx_id: EventTransactionId(59), old_commit_oid: b64ae1b6ba18ac5dff50a098e9074240670d4d71, new_commit_oid: 710dc0ee9177424fbd9a86c272a6a1fa8c83914a }
RewriteEvent { timestamp: 1667793048.3937514, event_tx_id: EventTransactionId(59), old_commit_oid: f880f9f898a57867001ef73b5da878587d5b55aa, new_commit_oid: 6894f271131b48e50afa69d5ab91e806f9854535 }
RefUpdateEvent { timestamp: 1667793048.4998088, event_tx_id: EventTransactionId(59), ref_name: ReferenceName("refs/heads/redacted-ref-2"), old_oid: f880f9f898a57867001ef73b5da878587d5b55aa, new_oid: 6894f271131b48e50afa69d5ab91e806f9854535, message: None }
WorkingCopySnapshot { timestamp: 1667793049.48474, event_tx_id: EventTransactionId(59), head_oid: 6894f271131b48e50afa69d5ab91e806f9854535, commit_oid: NonZeroOid(fa63978906ff0ad0d9510b60b74449ff35e88d97), ref_name: None }
RefUpdateEvent { timestamp: 1667793050.7584877, event_tx_id: EventTransactionId(59), ref_name: ReferenceName("HEAD"), old_oid: 6894f271131b48e50afa69d5ab91e806f9854535, new_oid: 106ec001bf94906f443f15904867343528c50354, message: None }

:
O 47b81ab 25d xxxxxx xxxx xxxx xxxx xxxxxxxxxxxxxx
|\
| x 21477bf 25d (rewritten as f697958b) xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
| |
| x 2717372 25d (rewritten as 58ad6016) xxx xxxxxxxx xxxxxxxxx xxxx
| |
| x b64ae1b 25d (rewritten as 710dc0ee) xxxx xxxxxxxxxxxxxxxxxxxxxxx
| |
| x f880f9f 25d (rewritten as 6894f271) xxx
|\
| x a298fca 25d (rewritten as d191dad3) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
: x a1f7919 1h (rewritten as ee48c934) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
: |
: x 41c4a55 1h (manually hidden) xxxxxx xxxx
: |
: x a4d1cc4 1h (manually hidden) xxxxxx xxxxxxx xxxxx
:
O 106ec00 40m (main) xxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxx xxx xxxxxxxx
|\
| o d191dad 32m (redacted-ref-1) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
| o ee48c93 32m (redacted-ref-0) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
|
o f697958 27m xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
|
o 58ad601 27m xxx xxxxxxxx xxxxxxxxx xxxx
|
o 710dc0e 26m xxxx xxxxxxxxxxxxxxxxxxxxxxx
|
@ 6894f27 26m (redacted-ref-2) xxx

Event ID: 359, transaction ID: 55 (message: post-commit)

CommitEvent { timestamp: 1667793046.0, event_tx_id: EventTransactionId(55), commit_oid: NonZeroOid(6894f271131b48e50afa69d5ab91e806f9854535) }

:
O 47b81ab 25d xxxxxx xxxx xxxx xxxx xxxxxxxxxxxxxx
|\
| x 21477bf 25d xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
| |
| x 2717372 25d xxx xxxxxxxx xxxxxxxxx xxxx
| |
| x b64ae1b 25d xxxx xxxxxxxxxxxxxxxxxxxxxxx
| |
| x f880f9f 25d xxx
|\
| x a298fca 25d (rewritten as d191dad3) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
: x a1f7919 1h (rewritten as ee48c934) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
: |
: x 41c4a55 1h (manually hidden) xxxxxx xxxx
: |
: x a4d1cc4 1h (manually hidden) xxxxxx xxxxxxx xxxxx
:
O 106ec00 40m (main) xxxx xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx xxxxxxxxxxxxxxxxxxxx xxx xxxxxxxx
|\
| o d191dad 32m (redacted-ref-1) xx xxx xxxxxxx xxxxxx xxxxxxxx xxxxxxxxxx xx xxxxxxxxxxxxxxxxxxxxxxxxxx
|\
| o ee48c93 32m (redacted-ref-0) xxx xxxxxx xxxxxx xxx xxxxxxxxxxxxx
|
o f697958 27m xxxxxxxxxxxxxxxxxx xxxxxxx xx xxxxxxxxxx
|
o 58ad601 27m xxx xxxxxxxx xxxxxxxxx xxxx
|
o 710dc0e 26m xxxx xxxxxxxxxxxxxxxxxxxxxxx
|
@ 6894f27 26m (redacted-ref-2) xxx

Version of `git-branchless`

No response

Version of `git`

No response

The text was updated successfully, but these errors were encountered:

arxanas · 2022-11-07T20:30:54Z

Hi @mlcui-google, thanks for reporting and bisecting! I was able to reproduce the slow-down on my machine. It looks like the regression is in the time it takes to calculate Dag::get_visible_commits. I'm not really sure why that is — the underlying commit set representation should be pretty compact and simple to calculate. I'll try adjusting this function to be Dag::get_visible_heads and fixing the call-sites and see if that helps.

claytonrcarter · 2022-11-08T01:35:49Z

FWIW I haven't noticed the normal smartlog being much slower (though I'm working on much smaller repos), but I also just encountered a significant performance issue with git branchless switch that seems to stem from that same commit.

This command: cargo run -- -C [redacted] switch main takes around to 2s to run on 2c1a5b9 but more like 20s to run on c90b52f.

It spends around 15s in this state:

⠤ Examining local history (9.9s)
  ⠲ Walking commits (9.8s)

This seems to be related to the issue I just ran into over on #619. In that case, some crude debugging seems to indicate that the smartlog is processing commits that seem well out of scope. In that case, it seems like it was walking commits from 10 months ago that are only reachable by remote ref and have no business in my smartlog. 😄 Note that displaying a smartlog with git smartlog works just fine; it's only an issue when using git switch. (git next/prev seem to work OK, too.)

arxanas · 2022-11-08T02:42:18Z

@claytonrcarter you should also try with cargo run --release for these cases, as I've noticed that there are sometimes important optimizations that get applied and make the runtime significantly faster.

mlcui-corp · 2022-11-08T02:50:46Z

Interestingly, a similar performance regression occurs when executing the query mentioned in #624 (comment) (this is in my Chromium checkout):

$ time git query --branches "heads(branches() & ancestors(cl2^))"                                               
main
origin/main
cl1
git query --branches "heads(branches() & ancestors(cl2^))"  0.07s user 0.03s system 99% cpu 0.100 total

$ time ~/git/git-branchless/target/release/git-branchless query --branches "heads(branches() & ancestors(cl2^))" 
main
cl1
~/git/git-branchless/target/release/git-branchless query --branches   1.24s user 0.02s system 100% cpu 1.255 total

The latter takes much longer with this loading message: Evaluating revset: heads(intersection(branches(), ancestors(parents.nth(test, 1)))). Reverting c90b52f fixes the performance of the query.

claytonrcarter · 2022-11-08T03:30:32Z

try with cargo run --release

Ah, thank you. #rtfm

After the initial build, cargo run --release -- -C [redacted] switch main takes around 800ms on 2c1a5b9 and approx 2.5s on c90b52f

As reported in #625, commit c90b52f introduced a performance regression. It's not clear to me why queries like `ancestors(X)` are slow in this case. In my experimentation, the result was often a single-span commit set, which should be fairly quick to compute and process for other operations (such as `intersection`). Nonetheless, avoiding that query seems to improve the speed of evaluating various revsets.

arxanas · 2022-11-09T00:55:30Z

@mlcui-google can you try #631 and see if it resolves the performance issue?

mlcui-corp · 2022-11-09T02:27:10Z

Yes - in fact, it's even faster than v0.5.0! Using hyperfine to measure:

	`smartlog`	`query --branches "heads(branches() & ancestors(test^))"`
v0.5.0	82.9 ms ± 2.1 ms (main) 82.4 ms ± 2.4 ms (origin/main)	78.1 ms ± 0.7 ms (main) 77.8 ms ± 1.1 ms (origin/main)
HEAD	1.313 s ± 0.023 s (main)	1.204 s ± 0.013 s (main)
#631	53.3 ms ± 2.0 ms (main)	47.8 ms ± 0.5 ms (main)

arxanas · 2022-11-09T03:02:51Z

@mlcui-google Nice! Thanks again for reporting 🙂.

As reported in #625, commit c90b52f introduced a performance regression. It's not clear to me why queries like `ancestors(X)` are slow in this case. In my experimentation, the result was often a single-span commit set, which should be fairly quick to compute and process for other operations (such as `intersection`). Nonetheless, avoiding that query seems to improve the speed of evaluating various revsets.

mlcui-corp added the bug Something isn't working label Nov 7, 2022

arxanas mentioned this issue Nov 9, 2022

Fix performance regression #631

Merged

arxanas closed this as completed in #631 Nov 9, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Regression: smartlog at HEAD is slower than v0.5.0 #625

Regression: smartlog at HEAD is slower than v0.5.0 #625

mlcui-corp commented Nov 7, 2022 •

edited

Loading

Hook `post-commit`

Hook `post-merge`

Hook `post-rewrite`

Hook `post-checkout`

Hook `pre-auto-gc`

Hook `reference-transaction`

Event ID: 370, transaction ID: 63 (message: checkout)

Event ID: 368, transaction ID: 61 (message: checkout)

Event ID: 367, transaction ID: 60 (message: hook-post-checkout)

Event ID: 360, transaction ID: 59 (message: hook-post-rewrite)

Event ID: 359, transaction ID: 55 (message: post-commit)

arxanas commented Nov 7, 2022

claytonrcarter commented Nov 8, 2022

arxanas commented Nov 8, 2022

mlcui-corp commented Nov 8, 2022

claytonrcarter commented Nov 8, 2022

arxanas commented Nov 9, 2022

mlcui-corp commented Nov 9, 2022

arxanas commented Nov 9, 2022

Regression: smartlog at HEAD is slower than v0.5.0 #625

Regression: smartlog at HEAD is slower than v0.5.0 #625

Comments

mlcui-corp commented Nov 7, 2022 • edited Loading

Description of the bug

Expected behavior

Actual behavior

Version of rustc

Automated bug report

Software version

Operating system

Command-line

Environment variables

Git version

Hooks

Hook post-commit

Hook post-merge

Hook post-rewrite

Hook post-checkout

Hook pre-auto-gc

Hook reference-transaction

Events

Event ID: 370, transaction ID: 63 (message: checkout)

Event ID: 368, transaction ID: 61 (message: checkout)

Event ID: 367, transaction ID: 60 (message: hook-post-checkout)

Event ID: 360, transaction ID: 59 (message: hook-post-rewrite)

Event ID: 359, transaction ID: 55 (message: post-commit)

Version of git-branchless

Version of git

arxanas commented Nov 7, 2022

claytonrcarter commented Nov 8, 2022

arxanas commented Nov 8, 2022

mlcui-corp commented Nov 8, 2022

claytonrcarter commented Nov 8, 2022

arxanas commented Nov 9, 2022

mlcui-corp commented Nov 9, 2022

arxanas commented Nov 9, 2022

mlcui-corp commented Nov 7, 2022 •

edited

Loading

Version of `rustc`

Hook `post-commit`

Hook `post-merge`

Hook `post-rewrite`

Hook `post-checkout`

Hook `pre-auto-gc`

Hook `reference-transaction`

Version of `git-branchless`

Version of `git`