Regression: smartlog at HEAD is slower than v0.5.0

[mlcui-corp]

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)

1. 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")) }
2. 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)

1. 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")) }
2. 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)

1. 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)

1. RewriteEvent { timestamp: 1667793048.3937514, event_tx_id: EventTransactionId(59), old_commit_oid: 21477bf7bbe22c4ae875f310cab196fb718b351d, new_commit_oid: f697958be1d6d9121ecd3c41b15a882af22b4a69 }
2. RewriteEvent { timestamp: 1667793048.3937514, event_tx_id: EventTransactionId(59), old_commit_oid: 2717372cb090f4ef99bef68c4d0bf16bf45771d2, new_commit_oid: 58ad601600caf6db760df0e88c1bbe68c6bdda71 }
3. RewriteEvent { timestamp: 1667793048.3937514, event_tx_id: EventTransactionId(59), old_commit_oid: b64ae1b6ba18ac5dff50a098e9074240670d4d71, new_commit_oid: 710dc0ee9177424fbd9a86c272a6a1fa8c83914a }
4. RewriteEvent { timestamp: 1667793048.3937514, event_tx_id: EventTransactionId(59), old_commit_oid: f880f9f898a57867001ef73b5da878587d5b55aa, new_commit_oid: 6894f271131b48e50afa69d5ab91e806f9854535 }
5. 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 }
6. WorkingCopySnapshot { timestamp: 1667793049.48474, event_tx_id: EventTransactionId(59), head_oid: 6894f271131b48e50afa69d5ab91e806f9854535, commit_oid: NonZeroOid(fa63978906ff0ad0d9510b60b74449ff35e88d97), ref_name: None }
7. 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)

1. 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

[arxanas]

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]

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]

@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]

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]

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

[arxanas]

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

[mlcui-corp]

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]

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