commit is slow — 1 minute and amend is even slower — 6+ minutes (not completed)

[develar]

Version

0.14.32

Operating System

macOS

Distribution Method

dmg (Mac OS - Apple Silicon)

Describe the issue

The trace contains two runs—a one-minute run for the commit action and a six-minute run for the amend (at least, I stopped recording—the action was not completed in six minutes :)).

https://drive.google.com/uc?export=download&id=1sTaG0eLtQ-VsoGC0mh0nLpa3QfYrkjCj

I committed ~4 files with small changes.
Or amend (drag several files to some existing commit).

How to reproduce (Optional)

No response

Expected behavior (Optional)

No response

Relevant log output (Optional)

[Caleb-T-Owens]

Hi @develar,

Would you mind sharing how large your repository is in terms of number of commits and quantity of files?

[develar]

Hi, you can find git-sizer output in this discussion: #8999 (comment)

[Byron]

Thanks so much!

Judging by the attached instruments save file, both operations spend the majority of time in repeated gix status calls (3).
It takes 10s to 12s to get stack details, and IsIntegrated stakes the biggest chunk of time therein.

Each gix status calls takes quite a while, 14s for traversing the directory alone, which seems to be the bottleneck as the stat calls take ~7s across 20 threads.

Would you mind sharing the amount of tracked files with git ls-files | wc -l?
Further, how long does a git status call take?
My experience here is that Git will happily stat the filesystem with as many threads as there are cores and perfect scaling, but if gix does it, the kernel times go up so that reducing the amount of threads is actually better for performance.

If you would install gitoxide you could also run gix status for comparison and control the amount of threads to find the optimal number (i.e. gix -t3 status.

Usually when the UI refreshes, it runs one gix status, then when an operation is made it runs another to assure nothing changed meanwhile (this is very defensive and maybe something that can change), and then the UI will be triggered again and check for worktree changes with git status.

Maybe this explains why committing causes the work it does.

The amend, however, is different as it calls gix status 7 times, and there is a lot of filesystem watcher activity, each of which costs 23s to run. This is older code, which also does the equivalent of git status but with git2 this time.
Maybe the amend triggers a rebase of various commits above, and each commit triggers a UI refresh?

WebKit

In terms of number of files, this is the biggest I have got:

❯ git ls-files | wc -l
  417001

❯ hyperfine 'git status' 'gix status'
Benchmark 1: git status
  Time (mean ± σ):      2.673 s ±  0.374 s    [User: 0.328 s, System: 26.341 s]
  Range (min … max):    1.625 s …  2.942 s    10 runs

  Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet system without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options.

Benchmark 2: gix status
  Time (mean ± σ):      1.526 s ±  0.077 s    [User: 0.549 s, System: 3.472 s]
  Range (min … max):    1.338 s …  1.607 s    10 runs

Summary
  gix status ran
    1.75 ± 0.26 times faster than git status

When running GitButler like this…

 LOG_LEVEL=debug GITBUTLER_PERFORMANCE_LOG=1 /Applications/GitButler\ Nightly.app/Contents/MacOS/gitbutler-tauri

…it's quite easy to see how much time an operation takes and roughly where it's going.

Creating a commit for instance prints this too much right now, but this will be fixed with the next nightly.

It's probably best to not let this comment get much longer, and conclude with saying that my WebKit tests weren't anywhere near as slow as what you are experiencing, with GB remaining usable even in WebKit. And this alone is a huge win that I'd want to high-five the team for :).

However, I also think that we should aim for not be as wasteful as we are right now.

In any case, I am looking forward to hearing from you.

[develar]

git ls-files | wc -l

1188391

how long does a git status call take?

git status
Refresh index: 100% (1188391/1188391), done.
On branch gitbutler/workspace
Changes not staged for commit:
  (use "git add <file>..." to update what will be committed)
  (use "git restore <file>..." to discard changes in working directory)
	modified:   build/src/IdeaUltimateLocalDistribution.kt


It took 17.33 seconds to enumerate untracked files,
but the results were cached, and subsequent runs may be faster.
See 'git help status' for information on how to improve this.

~17 seconds (I checked it before, was also 17 seconds).

Please note — showUntrackedFiles = all. I tried to set it to no, but no difference for Git Butler (I suppose, Git Buttler should explicitly set it).

[core]
    repositoryformatversion = 0
    bare = false
    logallrefupdates = true
    untrackedcache = true
    fsmonitor = true
    longpaths = true
    autocrlf = input
[status]
	showUntrackedFiles = all

showUntrackedFiles = all is used because IntelliJ IDEA passes it anyway, please see
https://patchwork.kernel.org/project/git/patch/f60d2c6e36c3218f9b19d7ce62a090d7d6e0e7f6.1648553134.git.gitgitgadget@gmail.com/#24795244 and git/git@e6a6535

I will check debug log, thanks a lot for working on this.

[develar]

gix status
 18:34:09 status done 1.2M files in 14.57s (81.6K files/s)                                                                                                                      
  M build/src/IdeaUltimateLocalDistribution.kt
gix -t3 status
 18:34:40 status done 1.2M files in 15.36s (77.4K files/s)                                                                                                                      
  M build/src/IdeaUltimateLocalDistribution.kt

gix -t1 status
 18:36:39 status done 1.2M files in 23.68s (50.2K files/s)                                                                                                                      
  M build/src/IdeaUltimateLocalDistribution.kt

gix -t40 status
 18:37:38 status done 1.2M files in 25.82s (46.0K files/s)                                                                                                                      
  M build/src/IdeaUltimateLocalDistribution.kt

Looks like the default 0 (all, no -t) is the good one, and customizing thread count is not needed.

[Byron]

This is very interesting, thank you! ~1.2m files and nearly 3x of WebKit is impressive!
We could probably generate one with an equal number to get similar timings for further optimisation. So many files seem to slow down the filesystem disproportionally as well.

Please note — showUntrackedFiles = all. I tried to set it to no, but no difference for Git Butler (I suppose, Git Buttler should explicitly set it).

I also see that fsmonitor is true, which is ignored in gitoxide. Additionally, GitButler will see all untracked files to perform rename among them correctly (thus mv x/ y/ will work just like git mv x/ y/). It also doesn't use the untracked file cache in the index. All that considered it's very interesting that it still seems to be noticeably faster.

It's definitely good to know that the threads-scaling works as it should here.

WebKit

With the latest nightly I can finally see the performance log properly.

Here is the WebKit timings, which overall feels responsive enough to be usable, far from what you are seeing which is unusable.

• Uncommit 1 (no rebases): 4.29s (mostly old code as well)
• Commit 1 (no rebases): 3,45s
  • create_wd_tree takes 2,5s though and it's something I'd want to avoid calling in V3.
  • hunk-dependency computations follow up, along with another workspace changes check, both taking their time.

Conclusion

It really seems like we'd want to start using our own filesystem monitoring to continuously update status changes and avoid these expensive calls. Additionally, there is a bunch of calls which are currently slow or which shouldn't be there at all.

Overall, there is plenty of potential for improvements, even though all but the low-hanging fruit are out-of-scope while we are redoing the application at its core.

Logs

INFO     undo_commit [ 4.29s | 18.90% / 100.00% ] project_id: 522b1901-1c40-40f1-b2ed-1abd6edeac6d | stack_id: 720d7e8c-cd83-4063-a158-298f453bb41a | commit_oid: "cce801fa68c47016945f278127104c60c790cb33"
DEBUG    ┝━ create_wd_tree [ 2.43s | 56.54% ]
DEBUG    ┕━ undo_commit [ 1.05s | 10.98% / 24.56% ] stack_id: 720d7e8c-cd83-4063-a158-298f453bb41a | commit_to_remove: cce801fa68c47016945f278127104c60c790cb33
DEBUG       ┝━ rebase [ 6.83µs | 0.00% ] base: Some(Sha1(886077e077a496a6e398df52a4b7915d8cd68f76)) | base_substitute: None | steps: [Reference(Git(FullName("refs/heads/main")))] | pick_mode: SkipIfNoop
DEBUG       ┕━ update_workspace_commit [ 583ms | 13.12% / 13.58% ]
DEBUG          ┕━ head [ 19.9ms | 0.46% ]

INFO     create_commit_from_worktree_changes [ 3.45s | 25.30% / 100.00% ] project_id: 522b1901-1c40-40f1-b2ed-1abd6edeac6d | stack_id: 720d7e8c-cd83-4063-a158-298f453bb41a | parent_id: None | worktree_changes: [DiffSpec { previous_path: Some("resources/xcode-build-settings-for-run.png"), path: "resources-renamed/xcode-build-settings-for-run.png", hunk_headers: [] }] | message: "\n\nnew" | stack_branch_name: "main"
DEBUG    ┝━ create_wd_tree [ 2.38s | 68.96% ]
DEBUG    ┝━ 🐛 [debug]: command to produce commit signature | cmd: "gpg" "--status-fd=2" "-bsau" "27C50E7F590947D7273A741E85194C08421980C9" "-"
DEBUG    ┕━ rebase [ 198ms | 5.74% ] base: Some(Sha1(d36057e79fd60698413f3d52d2132e7346e89b9f)) | base_substitute: Some(Sha1(886077e077a496a6e398df52a4b7915d8cd68f76)) | steps: [Pick { commit_id: Sha1(f44f9de06f57345c21df481d0b5f74b922108b2a), new_message: None }] | pick_mode: Unconditionally
DEBUG       ┕━ 🐛 [debug]: command to produce commit signature | cmd: "gpg" "--status-fd=2" "-bsau" "27C50E7F590947D7273A741E85194C08421980C9" "-"
INFO     stack_details [ 5.30ms | 100.00% ] project_id: 522b1901-1c40-40f1-b2ed-1abd6edeac6d | stack_id: 720d7e8c-cd83-4063-a158-298f453bb41a
INFO     commit_details [ 303ms | 100.00% ] project_id: 522b1901-1c40-40f1-b2ed-1abd6edeac6d | commit_id: HexHash(Sha1(d36057e79fd60698413f3d52d2132e7346e89b9f))
DEBUG    🐛 [debug]: Flushed 88 events
INFO     handle [ 2.86ms | 100.00% ] event: GitButlerOplogChange(522b1901-1c40-40f1-b2ed-1abd6edeac6d)
DEBUG    🐛 [debug]: Flushed 2 events
INFO     changes_in_worktree [ 4.48s | 4.76% / 100.00% ] project_id: 522b1901-1c40-40f1-b2ed-1abd6edeac6d
INFO     ┝━ worktree_changes [ 2.47s | 55.11% ]
INFO     ┕━ reconcile_with_worktree_and_locks [ 1.80s | 40.14% ] set_assignment_from_locks: false
INFO     handle [ 3.79s | 5.68% / 100.00% ] event: GitFileChange(522b1901-1c40-40f1-b2ed-1abd6edeac6d, index)
INFO     ┝━ worktree_changes [ 1.77s | 46.74% ]
INFO     ┕━ reconcile_with_worktree_and_locks [ 1.80s | 47.58% ] set_assignment_from_locks: false
DEBUG    🐛 [debug]: Flushed 8 events