Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Improve performance of magit-insert-recent-commits #5075

Open
wants to merge 2 commits into
base: main
Choose a base branch
from
Open

Improve performance of magit-insert-recent-commits #5075

wants to merge 2 commits into from

Conversation

vermiculus
Copy link
Contributor

Related to my investigation in #2982.

See commits for details.

@vermiculus
Avoid unnecessary commit graph calculations
1fef45e 
From my debugging, `range' here is usually something like
"HEAD~10..HEAD" (up to the value of `magit-log-section-commit-count'),
which of course means 'find me everything reachable from HEAD that
isn't reachable from HEAD~10'. We also pass "-n10" as a further
limiter. This appears to be duplicative, so prefer "-n10" alone.

"HEAD~10..HEAD" not only requires Git to parse HEAD~10, but also
requires reachability logic at each step when walking the graph.
Performance of this reachability logic is improved with tools like
`git-commit-graph', but it is not what I'd consider 'solved'.

On a branch with ~3400000 commits (~3700000 commits in --all), this is
a significant improvement (tested with `magit-refresh-verbose'):

current implementation:

    magit-insert-recent-commits    0.884695 !!
    magit-insert-recent-commits    0.508423 !!
    magit-insert-recent-commits    0.357324 !!
    magit-insert-recent-commits    0.360272 !!
    magit-insert-recent-commits    0.356748 !!

new implementation:

    magit-insert-recent-commits    0.125902 !!
    magit-insert-recent-commits    0.125966 !!
    magit-insert-recent-commits    0.125386 !!
    magit-insert-recent-commits    0.125143 !!
    magit-insert-recent-commits    0.125195 !!

This change has also been tested on a repository with <10 commits and
had no issues that I could see.
@vermiculus
Avoid unnecessary rev-parse
1fe6aae 
Now that we're not using `range' in the `magit--insert-log' call, we
don't need to have a value for `range' until its needed as the default
value of the section.

This saves a process-start and nominal compute for the string
manipulation in `format'/`concat'.
@vermiculus vermiculus changed the title Sa/insert recent commits perf Improve performance of `magit-insert-recent-commits' Jan 6, 2024
@vermiculus vermiculus changed the title Improve performance of `magit-insert-recent-commits' Improve performance of magit-insert-recent-commits Jan 6, 2024
@vermiculus vermiculus mentioned this pull request Jan 6, 2024
Open
@tarsius
Copy link
Member

tarsius commented Jan 7, 2024

We've added the range in 55a61d1.
To improve performance! 😱

@vermiculus
Copy link
Contributor Author

Fascinating! Your explanation in that commit message makes good sense. Should this optimization be made conditional on whether --graph is in the argument list?

@tarsius
Copy link
Member

tarsius commented Jan 13, 2024

Should this optimization be made conditional on whether --graph is in the argument list?

Maybe, though such a solution might depend on the user knowing that this is a bottleneck and that disabling that argument is needed.

I'll experiment with this eventually, but currently I trying to get some other things done. I don't have access to a humongous monorepo, so maybe you could run some benchmarks. (Using time git log [all the variants] outside of Emacs, should be good enough for our needs).

@vermiculus
Copy link
Contributor Author

vermiculus commented Jan 13, 2024 •
edited

To be specific, 'all the variants' here means at least the following, right?

time git --no-pager log --oneline -n10 --graph HEAD
time git --no-pager log --oneline -n10 --graph HEAD~10..HEAD
time git --no-pager log --oneline -n100 --graph HEAD~100..HEAD
time git --no-pager log --oneline -n10 HEAD
time git --no-pager log --oneline -n10 HEAD~10..HEAD
time git --no-pager log --oneline -n100 HEAD~100..HEAD
time git --no-pager log --oneline --graph HEAD
time git --no-pager log --oneline --graph HEAD~10..HEAD
time git --no-pager log --oneline --graph HEAD~100..HEAD
time git --no-pager log --oneline HEAD
time git --no-pager log --oneline HEAD~10..HEAD
time git --no-pager log --oneline HEAD~100..HEAD
time git --no-pager log --oneline -n10 --graph
time git --no-pager log --oneline -n100 --graph
time git --no-pager log --oneline -n10
time git --no-pager log --oneline -n100
time git --no-pager log --oneline --graph
time git --no-pager log --oneline

I'll have that shortly. Based on how long I've been in -n100 --graph is taking, it may be a while.

It struck me (while watching the christmas tree that is --graph output) that HEAD~10..HEAD is not necessarily ten commits. There's probably not a safe way to be more restrictive about that range.

@vermiculus
Copy link
Contributor Author

vermiculus commented Jan 13, 2024 •
edited

Turns out it wasn't -n100 --graph that was taking a while; it was --graph HEAD facepalm Churned through >40GB of memory before the terminal died.

Results are in.

Old, one-off numbers:

git --no-pager log --oneline -n10 --graph HEAD           0.08s user 0.11s system 26% cpu 0.702 total
git --no-pager log --oneline -n10 --graph HEAD~10..HEAD  0.06s user 0.04s system 88% cpu 0.106 total
git --no-pager log --oneline -n20 --graph HEAD~20..HEAD  0.15s user 0.07s system 71% cpu 0.303 total
git --no-pager log --oneline -n10 HEAD                   0.04s user 0.01s system 76% cpu 0.070 total
git --no-pager log --oneline -n10 HEAD~10..HEAD          0.23s user 0.06s system 93% cpu 0.307 total
git --no-pager log --oneline -n20 HEAD~20..HEAD          0.23s user 0.07s system 96% cpu 0.307 total
git --no-pager log --oneline --graph HEAD~10..HEAD       0.19s user 0.07s system 92% cpu 0.273 total
git --no-pager log --oneline --graph HEAD~20..HEAD       0.18s user 0.07s system 96% cpu 0.261 total
git --no-pager log --oneline HEAD~10..HEAD               0.24s user 0.07s system 94% cpu 0.327 total
git --no-pager log --oneline HEAD~20..HEAD               0.23s user 0.08s system 96% cpu 0.323 total
git --no-pager log --oneline -n10 --graph                0.06s user 0.04s system 90% cpu 0.108 total
git --no-pager log --oneline -n20 --graph                0.14s user 0.07s system 95% cpu 0.220 total
git --no-pager log --oneline -n10                        0.04s user 0.01s system 77% cpu 0.069 total
git --no-pager log --oneline -n20                        0.04s user 0.02s system 82% cpu 0.071 total

Cached (ran the script twice in quick succession; this is the second run):

git --no-pager log --oneline -n10 --graph HEAD           0.07s user 0.05s system 82% cpu 0.139 total
git --no-pager log --oneline -n10 --graph HEAD~10..HEAD  0.06s user 0.04s system 87% cpu 0.112 total
git --no-pager log --oneline -n20 --graph HEAD~20..HEAD  0.15s user 0.07s system 92% cpu 0.233 total
git --no-pager log --oneline -n10 HEAD                   0.04s user 0.02s system 81% cpu 0.072 total
git --no-pager log --oneline -n10 HEAD~10..HEAD          0.23s user 0.07s system 95% cpu 0.308 total
git --no-pager log --oneline -n20 HEAD~20..HEAD          0.23s user 0.07s system 97% cpu 0.304 total
git --no-pager log --oneline --graph HEAD~10..HEAD       0.18s user 0.06s system 94% cpu 0.257 total
git --no-pager log --oneline --graph HEAD~20..HEAD       0.18s user 0.07s system 95% cpu 0.258 total
git --no-pager log --oneline HEAD~10..HEAD               0.23s user 0.07s system 97% cpu 0.307 total
git --no-pager log --oneline HEAD~20..HEAD               0.23s user 0.06s system 93% cpu 0.304 total
git --no-pager log --oneline -n10 --graph                0.06s user 0.04s system 88% cpu 0.107 total
git --no-pager log --oneline -n20 --graph                0.14s user 0.07s system 96% cpu 0.219 total
git --no-pager log --oneline -n10                        0.04s user 0.02s system 87% cpu 0.070 total
git --no-pager log --oneline -n20                        0.04s user 0.02s system 92% cpu 0.071 total

Averaged numbers (10 iterations)

#!/usr/bin/zsh
function time_it {
    for i in {1..10}
    do
        git --no-pager log --oneline $@
    done
}

for args in "HEAD~10..HEAD" "--graph HEAD~10..HEAD" "-n10" "-n10 HEAD" "-n10 HEAD~10..HEAD" "-n10 --graph" "-n10 --graph HEAD" "-n10 --graph HEAD~10..HEAD" "HEAD~20..HEAD" "--graph HEAD~20..HEAD" "-n20" "-n20 HEAD" "-n20 HEAD~20..HEAD" "-n20 --graph" "-n20 --graph HEAD" "-n20 --graph HEAD~20..HEAD"
do
    echo +$args
    time (time_it ${=args})
done

Processed output below. Divide timings by 10 to get the per-run timings.

( time_it HEAD~10..HEAD              )  2.31s user 0.70s system 95% cpu 3.137 total
( time_it --graph HEAD~10..HEAD      )  1.79s user 0.67s system 95% cpu 2.579 total
( time_it -n10                       )  0.42s user 0.18s system 85% cpu 0.701 total
( time_it -n10 HEAD                  )  0.42s user 0.17s system 84% cpu 0.701 total
( time_it -n10 HEAD~10..HEAD         )  2.26s user 0.66s system 96% cpu 3.014 total
( time_it -n10 --graph               )  0.58s user 0.33s system 85% cpu 1.057 total
( time_it -n10 --graph HEAD          )  0.58s user 0.35s system 87% cpu 1.068 total
( time_it -n10 --graph HEAD~10..HEAD )  0.55s user 0.29s system 84% cpu 0.999 total
( time_it HEAD~20..HEAD              )  2.29s user 0.64s system 95% cpu 3.079 total
( time_it --graph HEAD~20..HEAD      )  1.94s user 0.66s system 92% cpu 2.824 total
( time_it -n20                       )  0.42s user 0.15s system 81% cpu 0.700 total
( time_it -n20 HEAD                  )  0.42s user 0.20s system 89% cpu 0.695 total
( time_it -n20 HEAD~20..HEAD         )  2.26s user 0.61s system 95% cpu 3.008 total
( time_it -n20 --graph               )  1.41s user 0.57s system 91% cpu 2.148 total
( time_it -n20 --graph HEAD          )  1.42s user 0.61s system 93% cpu 2.180 total
( time_it -n20 --graph HEAD~20..HEAD )  1.41s user 0.56s system 91% cpu 2.152 total

Sorted by user:

( time_it -n20                       )  0.42s user 0.15s system 81% cpu 0.700 total
( time_it -n10 HEAD                  )  0.42s user 0.17s system 84% cpu 0.701 total
( time_it -n10                       )  0.42s user 0.18s system 85% cpu 0.701 total
( time_it -n20 HEAD                  )  0.42s user 0.20s system 89% cpu 0.695 total
( time_it -n10 --graph HEAD~10..HEAD )  0.55s user 0.29s system 84% cpu 0.999 total
( time_it -n10 --graph               )  0.58s user 0.33s system 85% cpu 1.057 total
( time_it -n10 --graph HEAD          )  0.58s user 0.35s system 87% cpu 1.068 total
( time_it -n20 --graph HEAD~20..HEAD )  1.41s user 0.56s system 91% cpu 2.152 total
( time_it -n20 --graph               )  1.41s user 0.57s system 91% cpu 2.148 total
( time_it -n20 --graph HEAD          )  1.42s user 0.61s system 93% cpu 2.180 total
( time_it --graph HEAD~10..HEAD      )  1.79s user 0.67s system 95% cpu 2.579 total
( time_it --graph HEAD~20..HEAD      )  1.94s user 0.66s system 92% cpu 2.824 total
( time_it -n20 HEAD~20..HEAD         )  2.26s user 0.61s system 95% cpu 3.008 total
( time_it -n10 HEAD~10..HEAD         )  2.26s user 0.66s system 96% cpu 3.014 total
( time_it HEAD~20..HEAD              )  2.29s user 0.64s system 95% cpu 3.079 total
( time_it HEAD~10..HEAD              )  2.31s user 0.70s system 95% cpu 3.137 total

100 iterations.

script (note >/dev/null, otherwise it was overwhelming my terminal's scrollback):

#!/usr/bin/zsh
function time_it {
    for i in {1..$1}
    do
        git --no-pager log --oneline ${@:2} >/dev/null
    done
}

# time git commit-graph write --changed-paths
for args in "HEAD~10..HEAD" "--graph HEAD~10..HEAD" "-n10" "-n10 HEAD" "-n10 HEAD~10..HEAD" "-n10 --graph" "-n10 --graph HEAD" "-n10 --graph HEAD~10..HEAD" "HEAD~20..HEAD" "--graph HEAD~20..HEAD" "-n20" "-n20 HEAD" "-n20 HEAD~20..HEAD" "-n20 --graph" "-n20 --graph HEAD" "-n20 --graph HEAD~20..HEAD"
do
    echo -n $args
    time (time_it 100 ${=args})
done

Output:

( time_it 100 ${=args}; )  23.15s user 9.82s system 90% cpu 36.439 total   HEAD~10..HEAD
( time_it 100 ${=args}; )  17.27s user 9.95s system 93% cpu 29.090 total   --graph HEAD~10..HEAD
( time_it 100 ${=args}; )  04.30s user 3.58s system 68% cpu 11.566 total   -n10
( time_it 100 ${=args}; )  04.32s user 3.59s system 67% cpu 11.799 total   -n10 HEAD
( time_it 100 ${=args}; )  22.73s user 9.49s system 93% cpu 34.591 total   -n10 HEAD~10..HEAD
( time_it 100 ${=args}; )  05.79s user 6.89s system 87% cpu 14.419 total   -n10 --graph
( time_it 100 ${=args}; )  05.78s user 5.60s system 79% cpu 14.364 total   -n10 --graph HEAD
( time_it 100 ${=args}; )  05.59s user 6.07s system 82% cpu 14.215 total   -n10 --graph HEAD~10..HEAD
( time_it 100 ${=args}; )  22.97s user 9.38s system 92% cpu 34.972 total   HEAD~20..HEAD
( time_it 100 ${=args}; )  17.76s user 9.35s system 91% cpu 29.738 total   --graph HEAD~20..HEAD
( time_it 100 ${=args}; )  04.26s user 4.69s system 83% cpu 10.679 total   -n20
( time_it 100 ${=args}; )  04.32s user 4.17s system 76% cpu 11.054 total   -n20 HEAD
( time_it 100 ${=args}; )  23.17s user 8.65s system 90% cpu 35.218 total   -n20 HEAD~20..HEAD
( time_it 100 ${=args}; )  14.11s user 8.96s system 90% cpu 25.515 total   -n20 --graph
( time_it 100 ${=args}; )  14.08s user 9.27s system 91% cpu 25.488 total   -n20 --graph HEAD
( time_it 100 ${=args}; )  14.06s user 8.69s system 90% cpu 25.172 total   -n20 --graph HEAD~20..HEAD

Sorted:

( time_it 100 ${=args}; )  04.26s user 4.69s system 83% cpu 10.679 total   -n20
( time_it 100 ${=args}; )  04.30s user 3.58s system 68% cpu 11.566 total   -n10
( time_it 100 ${=args}; )  04.32s user 3.59s system 67% cpu 11.799 total   -n10 HEAD
( time_it 100 ${=args}; )  04.32s user 4.17s system 76% cpu 11.054 total   -n20 HEAD
( time_it 100 ${=args}; )  05.59s user 6.07s system 82% cpu 14.215 total   -n10 --graph HEAD~10..HEAD
( time_it 100 ${=args}; )  05.78s user 5.60s system 79% cpu 14.364 total   -n10 --graph HEAD
( time_it 100 ${=args}; )  05.79s user 6.89s system 87% cpu 14.419 total   -n10 --graph
( time_it 100 ${=args}; )  14.06s user 8.69s system 90% cpu 25.172 total   -n20 --graph HEAD~20..HEAD
( time_it 100 ${=args}; )  14.08s user 9.27s system 91% cpu 25.488 total   -n20 --graph HEAD
( time_it 100 ${=args}; )  14.11s user 8.96s system 90% cpu 25.515 total   -n20 --graph
( time_it 100 ${=args}; )  17.27s user 9.95s system 93% cpu 29.090 total   --graph HEAD~10..HEAD
( time_it 100 ${=args}; )  17.76s user 9.35s system 91% cpu 29.738 total   --graph HEAD~20..HEAD
( time_it 100 ${=args}; )  22.73s user 9.49s system 93% cpu 34.591 total   -n10 HEAD~10..HEAD
( time_it 100 ${=args}; )  22.97s user 9.38s system 92% cpu 34.972 total   HEAD~20..HEAD
( time_it 100 ${=args}; )  23.15s user 9.82s system 90% cpu 36.439 total   HEAD~10..HEAD
( time_it 100 ${=args}; )  23.17s user 8.65s system 90% cpu 35.218 total   -n20 HEAD~20..HEAD

The fact that --graph HEAD~10..HEAD somehow runs faster than just HEAD~10..HEAD is very surprising.

@tarsius
Copy link
Member

tarsius commented Jan 17, 2024

Please include the results for 100 and 1000 commits. You can skip the HEAD variants because those are the same as the respective variants without any rev or range.

@vermiculus
Copy link
Contributor Author

vermiculus commented Jan 17, 2024 •
edited

Still including the HEAD variants because, well, I've seen weirder things happen with this migration project. Things that are conceptually identical can go down different codepaths. Providing HEAD for example requires Git to effectively rev-parse it rather than having the hard-coded HEAD already understood. The consistent differences between different calling patterns below seem a fitting testament to how weird it can get.

( time_it 100 ${=args}; )    4.31s user  1.45s system 79% cpu    7.208 total   -n100 HEAD
( time_it 100 ${=args}; )    4.34s user  2.09s system 88% cpu    7.275 total   -n100
( time_it 100 ${=args}; )   17.44s user  6.70s system 96% cpu   24.935 total   -n100 --graph HEAD~100..HEAD
( time_it 100 ${=args}; )   18.57s user  6.86s system 96% cpu   26.253 total   -n100 --graph
( time_it 100 ${=args}; )   18.62s user  6.81s system 96% cpu   26.348 total   -n100 --graph HEAD
( time_it 100 ${=args}; )   37.11s user  7.31s system 97% cpu   45.681 total   --graph HEAD~100..HEAD
( time_it 100 ${=args}; )   47.94s user  7.17s system 98% cpu   56.200 total   -n100 HEAD~100..HEAD
( time_it 100 ${=args}; )   49.80s user  7.94s system 87% cpu 1:06.31  total   HEAD~100..HEAD

( time_it 100 ${=args}; )    5.40s user  3.00s system 89% cpu    9.417 total   -n1000 HEAD
( time_it 100 ${=args}; )    5.45s user  2.96s system 87% cpu    9.621 total   -n1000
( time_it 100 ${=args}; )  160.00s user  9.21s system 98% cpu 2:51.38  total   -n1000 --graph
( time_it 100 ${=args}; )  164.80s user  9.39s system 98% cpu 2:56.66  total   -n1000 --graph HEAD
( time_it 100 ${=args}; )  165.93s user  9.47s system 98% cpu 2:57.38  total   -n1000 --graph HEAD~1000..HEAD
( time_it 100 ${=args}; )  165.97s user 10.20s system 98% cpu 2:58.11  total   --graph HEAD~1000..HEAD
( time_it 100 ${=args}; )  209.30s user  9.25s system 98% cpu 3:41.03  total   -n1000 HEAD~1000..HEAD
( time_it 100 ${=args}; )  215.95s user 10.38s system 98% cpu 3:49.65  total   HEAD~1000..HEAD

@vermiculus
Copy link
Contributor Author

vermiculus commented Feb 3, 2024 •
edited

Any other metrics I can add here? The numbers above seem to support the idea that removing the range improves performance. It's been a number of years since 55a61d1; perhaps Git's rev-walking logic has changed in that time?

@tarsius
Copy link
Member

tarsius commented Feb 21, 2024

Sorry for not following up. I'm rather busy getting Forge into a releasable state, so that I can finally release "everything".

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

None yet
2 participants
@vermiculus @tarsius