git_stash_save really slow on large repositories

[mikesart]

Calling git_stash_save with libigt2 v0.24.1 on the linux repository takes 8 seconds to stash a single untracked file on my machine. Using the git command takes less than 2 seconds. I am running on the current version of Debian Stretch: "4.6.0-1-amd64 #1 SMP Debian 4.6.4-1 (2016-07-18) x86_64 GNU/Linux"

I've attached a simple cpp sample, and put it in a gist as well.

stashtest.zip
https://gist.github.com/mikesart/a99585317a8f57f0f57b9e5bd17d37c0

It appears the time is going into git_diff_tree_to_workdir and git_diff_index_to_workdir. I will update this bug report with the results on Windows tomorrow.

To reproduce:

mikesart@mikesart-cos:~/dev/linux/linux-src (master)$ git remote -v
origin git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git (fetch)
origin git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git (push)

mikesart@mikesart-cos:~/dev/linux/linux-src (master)$ git rev-parse HEAD
4935e04ef431c7980ba6e8145ad4c697abccf6b9

mikesart@mikesart-cos:~/dev/linux/linux-src (master)$ echo "blah" > blah.txt

mikesart@mikesart-cos:~/dev/linux/linux-src (master)$ git status --short
?? blah.txt

mikesart@mikesart-cos:~/dev/linux/linux-src (master)$ time git stash -u
Saved working directory and index state WIP on master: 4935e04 Merge branch 'for-linus-4.8-rc4' of git://git.kernel.org/pub/scm/linux/kernel/git/rw/uml
HEAD is now at 4935e04 Merge branch 'for-linus-4.8-rc4' of git://git.kernel.org/pub/scm/linux/kernel/git/rw/uml

real 0m1.864s
user 0m1.336s
sys 0m0.796s

mikesart@mikesart-cos:~/dev/linux/linux-src (master)$ stashtest .
Opening repository '.'
Calling git_repository_open_ext...
0.47ms
Calling git_signature_default...
0.09ms
Calling git_stash_save...
7935.53ms

[mikesart]

On Windows in the libgit2 v0.24.1 branch, git_stash_save takes 13 seconds where git stash -u takes 4. In our repository, which is larger than libgit2, git_stash_save takes 25 seconds, git stash -u takes 4.

[ethomson]

I'd be curious to know where the time is spent. I'm certain that you're right - it's going into the diffs, but I wonder which. I suspect that it's git_diff_tree_to_workdir, since that will have to, well, diff the workdir, which is quite obnoxious. (git_diff_index_to_workdir is nice enough to use the stat cache in the index.)

There's almost certainly an optimization that can be made to look at the index while diffing the tree to the workdir, but if git_stash_save is actually correct now, then I suspect swapping out git_diff_tree_to_workdir with git_diff_tree_to_workdir_with_index will produce the wrong behavior.

I don't know offhand if there's an easy way to make a git_diff_tree_to_workdir_with_index variant that will merge the trees differently in a way that would emulate git_diff_tree_to_workdir - that would likely be the simplest way to proceed... I'll try to give this a bit more thought this weekend.

[mikesart]

I added a very simple clock() timer in both functions around the DIFF_FROM_ITERATORS macro.

First run ( after clearing caches: sudo sh -c 'echo 3 >/proc/sys/vm/drop_caches' ):

Calling git_stash_save...
  git_diff_index_to_workdir: 0.26 seconds.
  git_diff_tree_to_workdir: 8.05 seconds.
  git_diff_index_to_workdir: 3.70 seconds.

Subsequent runs:

Calling git_stash_save...
  git_diff_index_to_workdir: 0.21 seconds.
  git_diff_tree_to_workdir: 3.66 seconds.
  git_diff_index_to_workdir: 3.51 seconds.

Thanks Edward!

[whavinga]

I noticed the same, and used vTune to analyze it (on Windows). Similar to the example attached in this issue, I used "GIT_STASH_KEEP_INDEX | GIT_STASH_INCLUDE_UNTRACKED" on a big repository (50k small files) with 1 newly added untracked file, and it is particularly the INCLUDE_UNTRACKED flag that causes a lot of overhead. Here are some numbers (only including the top-level items by time spent), they match the above results - on Windows CR/LF conversions can make the effect even more pronounced:

Function Stack Effective Time by Utilization

• git_stash_save 15.347s
  • commit_worktree 7.526s
    • build_workdir_tree 7.494s
      • git_diff_index_to_workdir 7.480s
        • git_diff__from_iterators 7.480s
          • maybe_modified 7.357s
            • git_diff__oid_for_entry 7.357s
  • commit_untracked 7.240s
    • build_untracked_tree 7.240s
      • git_diff_tree_to_workdir 7.240s
        • git_diff__from_iterators 7.240s
          • maybe_modified 6.956s
            • git_diff__oid_for_entry 6.948s

I think to have figured out the cause:

One of the earlier steps in git_stash_save is to create a commit from the index (commit_index). Then, if INCLUDE_UNTRACKED is enabled, it calls commit_untracked, which calls build_untracked_tree, which as one of the first steps clears the index (this will be relevant later). It then calls git_diff_tree_to_workdir, which is relatively expensive, as the tree knows commit id's but has no ctime/fsize data, whereas the workdir has ctime/fsize data but no oid's. So: we get git_diff__oid_for_entry on the entire workdir. I don't see an obvious way to avoid this. Subsequently, stash_update_index_from_diff updates the index, but only for entries in the diff (i.e. in my case 1 entry out of 50k).

Clearing the index seems correct because we have just created a commit of its earlier contents, and are now trying to create a "new" index to create the second commit that only contains untracked workingdir changes (i.e. exactly how stashing is supposed to work).

Back in stash_save, next up is commit_worktree, which calls build_workdir_tree, which calls git_diff_index_to_workdir, which is normally pretty fast because it uses the ctimes/fsizes in the index, as ethomson remarked above. However, since the earlier step cleared the index, there is no cached info for nearly all entries (except 1, in my example). So we get a full oid calculation on the working dir again.

In short, it is doing at least twice the work it feels like it should be doing.

Perhaps a secondary index could be used to create the commit for the untracked changes? I'm not sure what would be a good solution.

[ianhattendorf]

Has anyone taken a look at this recently? This appears to still be an issue. For example, stashing a single file in the UnrealEngine repo takes 80+ seconds using libgit2 but 2 seconds using the CLI.

Profiling through Xcode, it appears the time is still being spent in the same places as mentioned previously (39s in git_diff_tree_to_workdir -> git_diff__from_iterators -> git_diff__oid_for_entry and 34s in git_diff_index_to_workdir -> git_diff__from_iterators -> git_diff__oid_for_entry).

I'm profiling with the following code:

void test_stash_save__unreal_engine(void)
{
    git_repository *ue_repo;
    git_signature *ue_signature;
    git_oid ue_stash_tip_oid;
    cl_git_pass(git_repository_init(&ue_repo, "/tmp/epicgames-unrealengine", 0));
    cl_git_pass(git_signature_now(&ue_signature, "example", "example@example.com"));

    cl_git_mkfile("/tmp/epicgames-unrealengine/what.cpp", "hello\n");

    cl_git_pass(git_stash_save(&ue_stash_tip_oid, ue_repo, ue_signature, NULL, GIT_STASH_INCLUDE_UNTRACKED));

    git_signature_free(ue_signature);
    git_repository_free(ue_repo);
}

Unfortunately I'm not super familiar with the inner workings of libgit2, however I'll continue poking around and see what I can find.

[safield]

Is this being looked into.

Using Gitahead, which use libgit2, stashing on my large repo takes around 2-3min, and can use exorbitant amount of system resources.

[pks-t]

I've just had a look and found that we're in fact invalidating the complete cache when computing worktree changes. Please have a look at #5113 and whether that improves performance for you. At least for me, I've got a 15x perf improvement in linux.git, I guess on Windows that'll be a lot more effective

[ianhattendorf]

Excellent news @pks-t. Testing on macOS went from ~90 to ~6 seconds, while Windows went from ~100 to ~5 seconds (using https://github.com/soxueren/EpicGames-UnrealEngine as a test repo). Looking forward to this getting merged in! Thanks for looking into this.

[pks-t]

Thanks a lot for confirming!

[pks-t]

Fixed via #5113. Thanks to all for the report and helpful data!