Skip to content

git_remote_fetch is slow #4736

New issue
New issue
Closed
Closed
git_remote_fetch is slow#4736

Description

@tomasskare
tomasskare
opened on Jul 23, 2018

Hi,

We use libgit2 to handle a large git repo (about 5GB bare). Some time after upgrading to libgit2 0.25.1, we noticed that git_remote_fetch on large repos was a lot slower than in version 0.21.2 that we used prior to that. Also testing the latest master branch, it is also slow. The remote end is using the standard git-daemon (version 1.8) from CentOS 7. The remote and local repos are in sync when the fetch is run, so it is not expected to need to send anything.

Using git bisect, we tracked this down to a single commit 6708618. Reverting this commit in 0.25.1 made it fast again. See below for more details.

Since we have to fix this rather quickly for a customer, do you see any problems in reverting this commit? Not knowing the libgit2 code that well, I can't tell if it includes important changes, but it looks like it's an attempt to optimize things.

Reproduction steps

  1. Git repo on remote site, running git-daemon.
  2. git2 --git-dir=becs.git fetch git://10.50.0.1/becs.git

Expected behavior

Fast as the wind!

Actual behavior

[master from github.com libgit2-fa401a32d23eb832c6494db9770e6522b11f36d7]
[root@vostro libgit2_measure]# time git2 --git-dir=becs.git fetch git://10.50.0.1/becs.git
Fetching git://10.50.0.1/becs.git for repo 0x17caa00
remote: Counting objects: 87, done.
remote: Compressing objects: 100% (40/40), done.
remote: Total 84 (delta 53), reused 72 (delta 44)
Received 84/84 objects in 8823 bytes (used 3 local objects)

real 0m35.880s
user 0m34.043s
sys 0m0.565s

[0.21.2 libgit2-9c0463530d8e96d08e7c87e5a5d07949ea71b77c]
[root@vostro libgit2_measure]# time git2 fetch git://10.50.0.1/becs.git becs.git
Fetching git://10.50.0.1/becs.git for repo 0x237d510
remote: Counting objects: 93, done.
remote: Compressing objects: 100% (46/46), done.
remote: Total 90 (delta 56), reused 72 (delta 44)
Received 90/90 objects in 0 bytes (used 3 local objects)

real 0m1.913s
user 0m0.010s
sys 0m0.002s

[0.25.1 libgit2-2fcb8705e584ca61f6c4657525c9d2713f6a39d2]
[root@vostro libgit2_measure]# time git2 fetch git://10.50.0.1/becs.git becs.git
Fetching git://10.50.0.1/becs.git for repo 0x253c880
remote: Counting objects: 99, done.
remote: Compressing objects: 100% (52/52), done.
remote: Total 96 (delta 61), reused 72 (delta 44)
Received 96/96 objects in 10212 bytes (used 3 local objects)

real 0m27.201s
user 0m25.440s
sys 0m0.492s

Version of libgit2 (release number or SHA1)

Operating system(s) tested

CentOS 7

Activity

  1. ethomson commented on Jul 23, 2018

    @ethomson
    ethomson
    on Jul 23, 2018
    Member

    Ouch, that’s quite a regression. @carlosmn?

  2. carlosmn commented on Jul 23, 2018

    @carlosmn
    carlosmn
    on Jul 23, 2018
    Member

    Which part of the fetch is slow then? The negotiation? That would make sense with the regression in the revwalk speed,. If that is indeed the case, it was fixed in #4606.

  3. tomasskare commented on Jul 23, 2018

    @tomasskare
    tomasskare
    on Jul 23, 2018
    Author

    But the fix for #4606 was included in the test we did for the master version (fa401a3).

    Is there a good way for us to tell what part is slow, since we can reproduce it? Unfortunately, we can't give you the git repo because it's a customer database.

  4. neithernut commented on Jul 23, 2018

    @neithernut
    neithernut
    on Jul 23, 2018
    Contributor

    Is using perf an option?

  5. carlosmn commented on Jul 23, 2018

    @carlosmn
    carlosmn
    on Jul 23, 2018
    Member

    You haven't said which step is slow. There are several distinct steps; the revwalk could be the cause for one being slow, the move to the SHAttered-safe hashing functions could be another. If you're running debug builds, I would expect hashing to be much slower.

    Knowing which bit is actually slow would help in figuring out where the issue might be. It could also just be that we're now doing the same revwalks as git when things are sorted and that we should not actually ask for any sorting in the negotiation phase, but your debug output doesn't include timing for the different steps.

  6. tomasskare commented on Jul 24, 2018

    @tomasskare
    tomasskare
    on Jul 24, 2018
    Author

    We've done some more runs with perf, I hope it will give you some ideas. We have a patch for reverting 6708618 on fa401a3 (master a few commits back). The revert patch used is: 0001-revert-670861-based-on-fa401a.new.patch.txt. The compiled program is the examples/network/git2 program.

    Perf report from unpatched fa401a3:
    libgit2_fetch_perf_report-fa401a-release.txt

    Perf report with the revert patch:
    libgit2_fetch_perf_report-fa401a-plus-reversion_670861-release.txt

    I was incorrect in that both sides were in sync when running this. The remote side has one new commit in each of the tests.

    Without the revert, it takes 27s, and with the revert on the same machine it takes 1.8s.

    libgit2 was compiled as a Release build type in both cases.

    If you know of any other things we can test, we're happy to do it.

  7. neithernut commented on Jul 25, 2018

    @neithernut
    neithernut
    on Jul 25, 2018
    Contributor

    Ok, from the perf it is obvious that much time is spent in libz-functions. More interestingly, the list of symbols in the report is significantly longer for the report without the revert.

    However, other than that the reports you posted are rather useless since it contains no information about where those functions get called (so many times, or at all). It would be helpful if you could generate a report containing this information, e.g. have a look at the --call-graph options for perf record and perf report.

  8. dlundqvist commented on Jul 26, 2018

    @dlundqvist
    dlundqvist
    on Jul 26, 2018

    Hi,

    I'm a colleague with Tomas, and assisting him with this issue since he is on vacation.

    Here are reports gathered using --call-graph:
    libgit2_fetch_perf_graphical_report-fa401a-release-20180726-v2.txt
    libgit2_fetch_perf_graphical_report-fa401a-plus-reversion_670861-release-20180726-v3.txt

    Let us know if there is more we can do to assist.

  9. neithernut commented on Jul 26, 2018

    @neithernut
    neithernut
    on Jul 26, 2018
    Contributor

    Much better!

    From having a quick look, it appears that the regression is rooted inside the invocation of git_smart__negotiate_fetch (in git_fetch_negotiate): the second report (with the revert) assigns 0.76% of the total runtime to the invocation while the first one assigns 96.64%. The second report doesn't even report any callees of git_smart__negotiate_fetch.

    I did not yet check how the offending commit would cause this. I'll do in a few hours --after work.

  10. neithernut commented on Jul 26, 2018

    @neithernut
    neithernut
    on Jul 26, 2018
    Contributor

    The callchain looks like this:

    • git_smart__negotiate_fetch()
    • git_revwalk_next()
    • prepare_walk()
    • limit_list()
    • add_parents_to_list()
    • git_commit_list_parse()

    The latter four appear in the diff of 6708618: add_parents_to_list() and limit_list() appear to be introduced by the commit; git_commit_list_parse() seems to only appear as a caller (if I didn't miss something).

    Sadly, the diff is rather long as it was a rewrite. As mentioned, multiple new functions were introduced. However, I still have one idea left: both limit_list() and add_parents_to_list() contain loops which call the respective child in the chain above. Maybe we could narrow it down further by counting the respective invocations and/or loop iterations. Perf is not suited for that, so you have to use a debugger (e.g. add a breakpoint and let it increment some variable). And please post the raw counts. @dlundqvist, @tomasskare.

    And also count the invocations of git_revwalk_next() for both cases (with and without the revert), so we get a baseline.

  11. maxbrunsfeld commented on Jul 26, 2018

    @maxbrunsfeld
    maxbrunsfeld
    on Jul 26, 2018

    Possibly related: #4740

  12. neithernut commented on Jul 27, 2018

    @neithernut
    neithernut
    on Jul 27, 2018
    Contributor

    @maxbrunsfeld: Yep, probably. Could you confirm by reverting 6708618 and running some tests?

  13. neithernut commented on Jul 27, 2018

    @neithernut
    neithernut
    on Jul 27, 2018
    Contributor

    Also possibly related: #4428

  14. dlundqvist commented on Jul 30, 2018

    @dlundqvist
    dlundqvist
    on Jul 30, 2018

    From a colleague that ran tests:

    revwalk_counter.fa401a.txt

    Fetching git://10.50.0.1/becs.git for repo 0x14a4a00
remote: Counting objects: 345, done.
remote: Compressing objects: 100% (156/156), done.
remote: Total 335 (delta 215), reused 290 (delta 179)
Received 335/335 objects in 32704 bytes (used 10 local objects)
===revwalk counters report===
git_revwalk_next():function enter       : 20
prepare_walk():function enter           : 1
prepare_walk():for1 enter               : 1
prepare_walk():for1 exit                : 1
limit_list():function enter             : 1
limit_list():while enter                : 4132354
limit_list():while exit                 : 4132354
add_parents_to_list():function enter    : 4132354
add_parents_to_list():for1 enter        : 0
add_parents_to_list():for1 exit         : 0
add_parents_to_list():for2 enter        : 4132353
add_parents_to_list():for2 exit         : 4132353
===
===commit_list counters report===
git_commit_list_parse():function enter  : 4132354
===

real    0m26.700s
user    0m24.892s
sys     0m0.450s

    revwalk_counter.fa401a_revert-6708618.txt

    Fetching git://10.50.0.1/becs.git for repo 0x137ba00
remote: Counting objects: 342, done.
remote: Compressing objects: 100% (153/153), done.
remote: Total 332 (delta 213), reused 290 (delta 179)
Received 332/332 objects in 32414 bytes (used 10 local objects)
---revwalk counters report---
git_revwalk_next():function enter       : 2
prepare_walk():function enter           : 1
prepare_walk():for1 enter               : 1
prepare_walk():for1 exit                : 1
limit_list():function enter             : 0
limit_list():while enter                : 0
limit_list():while exit                 : 0
add_parents_to_list():function enter    : 0
add_parents_to_list():for1 enter        : 0
add_parents_to_list():for1 exit         : 0
add_parents_to_list():for2 enter        : 0
add_parents_to_list():for2 exit         : 0
---
---commit_list counters report---
git_commit_list_parse():function enter  : 1
---

real    0m1.805s
user    0m0.013s
sys     0m0.008s

    Again, let us know if you need more info and/or tests done.

  15. neithernut commented on Jul 30, 2018

    @neithernut
    neithernut
    on Jul 30, 2018
    Contributor

    Thanks. That's somewhat consistent with what I saw during an investigation of #4428. The issues seem to be indeed related. Sadly, I don't see a road to success yet (see #4428 for details).

  16. carlosmn commented on Sep 17, 2018

    @carlosmn
    carlosmn
    on Sep 17, 2018
    Member

    Chances are that this is fixed by #4809 as well since we're spending so much time in the revision walk.

  17. ethomson commented on Dec 1, 2019

    @ethomson
    ethomson
    on Dec 1, 2019
    Member

    Cleaning this up - it should have been fixed by the revwalk improvements in #4809.

  18. ethomson
    closed this as completedon Dec 1, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions