plumbing: format/packfile, performance optimizations for reading large commit histories

[filipnavara]

We have recently evaluated using Gitea as our Git hosting solution. It turned out to have quite a few performance bottlenecks stemming from the fact that it invokes the git command line tool for all operations. In one of the tracking issues go-git was suggested as one way of speeding it up. Over the weekend I prototyped computing the directory listing with last commit for each file on top of go-git (https://gist.github.com/filipnavara/8e6fdf980130d6ca120bfda4c25481e9). The speed improvement seemed promising enough that yesterday I proceeded further and reimplemented part of Gitea to use go-git (https://github.com/filipnavara/gitea/tree/perf-read). Overall I am seeing about 10x improvement on page load times for directory listings on our repository.

As part of the experiment I hit couple of bottlenecks in the go-git itself and I think it would make sense to resolve them. The proposed solutions may not necessarily be the best for general use, but I would like to spark a discussion about it at least.

1. Profiling the I/O showed a lot of Seek(0, io.SeekCurrent) calls that were unnecessary since the offset was either not used and thrown away or already known in the code path. This accounted for up to 5% of the history traversal.
   Proposed solution: I added SeekObjectHeader to packfile/scanner that combines seeking in the file and then reading the object header at that position into one call. This should not adversly affect any workloads. Related to that I found that Seek(<non-zero integer>, io.SeekCurrent) was implemented incorrectly. It is never used in the code base, but should probably be fixed nevertheless.

2. Iterating over commits using the repository.log, object.NewCommitIterCTime or other iterators always loads the commit objects from disk for loose objects. Since we examined the commit parents inside the iterator we were essentially loading all the commits from disk twice. It is possible to rewrite our algorithms/loops to avoid that, but it seemed that the use case could be better serviced within the library.
   Proposed solution: Add small cache for the loaded loose objects. It is more efficient to keep couple of them in the memory instead of reading them from disk. This could probably be tweaked to cache only small objects where the I/O and syscalls are going to be most expensive compared to memory cost.

3. Iterating deep in the history eventually started hitting the packfiles. The profiler and Process Monitor showed that there was significant time spent in OpenFile calls. Most of these OpenFile calls failed because the objects were stored in the packfiles and not as loose objects.
   Proposed solution: If the packfile indexes are already loaded then prefer them to loose object lookup. For our use case it improves the hit rate to almost 100% and avoids the unnecessary I/O calls. The indexes are already loaded in memory and should be cheap to check compared to hitting syscalls and disk. It may not be too efficient if many packfiles are present, but then the probability of objects being in the packfile is higher anyway. This simple optimization improved our algorithm performance by nearly 30%.

4. The I/O patterns for reading small objects from packfiles was quite erratic. It resulted in almost 3x as much disk reads performed than necessary (checked by timeit tool) and it often loaded 4k buffered blocks only to seek back in the file and read an overlapping block again (seen in Process Monitor on Windows). It turned out to be caused by the way FSObject is implemented. There's potential for significant improvement.
   Proposed solution: For small objects use MemoryObject instead and read the content right away since it's already buffered in memory. I chose an arbitrary threshold of 16 Kb, which may not be ideal. Something like (4Kb - header size) would be a conservative value that would work for our use case too.

5. Pack file index reading is done in 4Kb chunks, but it is mostly sequential reads that could easily use bigger buffer. This is not addressed within the PR.

[filipnavara]

Apparently the "Improve performace for reading many small objects from packfile by letting the I/O buffers be used better." change (nr. 4 in the list) is triggering some unwanted behavior with cache. I am looking into it.

[ajnavarro]

shall we move this magic number to a configurable param?

[filipnavara]

Probably a good idea.

(I only started learning Golang last Thursday, so if you have any pointers about proper/preferred code style I'd appreciate it.)

[mcuadros]

Just add a const with a explanation of the variable

[jfontan]

Can't we reuse deltaBaseCache? Maybe we have to change its name to objectCache.

[filipnavara]

It could definitely be reused. I wasn't sure whether that would be a preferred option. On one hand the loose object cache doesn't have to be big and serves slightly different purpose. On the other hand I assume it would be uncommon to hit both loose objects and packfile objects at the same time, so reusing the cache shouldn't hurt much.

[jfontan]

Then use deltaBaseCache. I don't expect to have a penalty using the same cache for both and makes it simpler.

[mcuadros]

An awesome job is done here. Have you done any benchmarks? Can you show us? Thanks

[filipnavara]

@mcuadros I don't have any scientific benchmarks (being a .NET guy I miss a tool like BenchmarkDotNet). For my specific use case (roughly the GIST link in the original description) on our repository with ~12 year of history, 3Gb of data and ~30000 commits it sped up my directory listing algorithm from 4s to 1.6s. It roughly corresponds to the reduced I/O calls shown by timeit and go tool ppref. Further improvements are possible, but this moved go-git for this specific use case into a usable territory in comparison to git command line. Now the profiler shows that the I/O is roughly 29% of the run time compared to 78% before the changes.

I am toying with some ideas how to make the commit graph traversal even faster and avoid a lot of parsing of information that is thrown away. Notably I have written a parser for the Git 2.18+ commit-graph files. It is very much work in progress and nothing quite ready to share yet.

[jfontan]

I've tested borges that is a tool that downloads and packs repositories in siva files. To do this it has to go through all the commits to repack the repos. Most of the times are lower and system time (Stime) is consistently smaller. Only the last repo takes more time than before. Not sure why.

#### Comparing /root/borges/borges-4.7.0 - /root/borges/borges-4.7.0-pr-963 ####
## Repo cangallo ##
Memory: 25528 -> 26780 (4.904418677530555), true
Wtime: 849.703176ms -> 889.788468ms (4.717564101466887), true
Stime: 140ms -> 170ms (21.428571428571427), false
Utime: 1.05s -> 920ms (-12.380952380952381), true
FileSize: 116541 -> 120423 (3.3310165521147064), true
## Repo octoprint-tft ##
Memory: 60824 -> 65160 (7.1287649611995265), true
Wtime: 8.727670689s -> 8.487030095s (-2.757214411209323), true
Stime: 710ms -> 550ms (-22.535211267605636), true
Utime: 9.61s -> 9.55s (-0.6243496357960457), true
FileSize: 2950179 -> 2956207 (0.20432658492925346), true
## Repo upsilon ##
Memory: 630096 -> 628164 (-0.30661994362763767), true
Wtime: 2m18.403927785s -> 2m11.427576858s (-5.040572936511767), true
Stime: 12.39s -> 10.1s (-18.48264729620662), true
Utime: 2m32.23s -> 2m25.9s (-4.158181698745319), true
FileSize: 100912676 -> 101071233 (0.1571229763047806), true
## Repo numpy ##
Memory: 1168112 -> 1232408 (5.504266714150698), true
Wtime: 7m5.497781807s -> 7m37.625167174s (7.550541210946323), true
Stime: 54.85s -> 46.12s (-15.916134913400182), true
Utime: 9m13.03s -> 10m35.02s (14.825597164710775), false
FileSize: 96717584 -> 110103219 (13.83991870599249), false

[filipnavara]

The slow down could be caused by something I didn't think of. There are two things that could result in worse performance in some scenarios:

1. When there is a lot of pack files and someone tries to look up loose object by hash. In that case the in-memory query with object hash across all loaded pack file indexes could be more expensive than making a syscall and hitting an OS disk cache.
2. If the loose objects are inadvertently spilling too much of the object cache and slow-down later delta lookups.

I assumed that either of those scenarios are unlikely to be hit. For 1) my thinking is that the more packfiles there are the larger is the chance that the object is stored in them. And in the unlikely case that it's not then the hash table lookup should still be cheap. For 2) I assumed that at certain point in time one will either be hitting mostly loose objects or mostly objects in pack files. Not many algorithms or traversals are randomly accessing the objects in such a fashion that accesses to loose objects and pack file objects would interleave too much.

If the Borges scenario could be reproduced on my machine I can try to pinpoint the specific optimization (commit in this PR) that causes the slow down and work on it.

[filipnavara]

I am not quite sure that I followed the right steps to reproduce your scenario. I created repos.txt file with one line: https://github.com/numpy/numpy.git. Then I built borges cli straight from GIT and executed ./borges pack --log-level=debug repos.txt. I did that three times without the patch and three times with the patch (against master, not 4.7). I took the time between "remote repository cloned" and "repository processed". The times I see are 2m56s with my patch, 2m59s with master. The difference is kinda in the margin of an error. However, the number are so much smaller than yours that I feel that I am actually testing a wrong thing. This is on a MacBook Pro 2017 model under macOS 10.14 with pretty speedy SSD.

[jfontan]

I'm testing in a slow machine (Intel(R) Atom(TM) CPU C2550 @ 2.40GHz) with a network attached disk. That's why the numbers are that different. The difference in my machine with that repo is not that big. Around 7%. I was just curious why it could be as looking at the code it seems it should be faster.

The repos are testing are local to the machine where I'm doing the test and only have one packfile.

[ajnavarro]

I did some really simple tests using this PR to compare against the master branch. I used this script on kubernetes repository:

package main

import (
    "fmt"
    "io"

    "gopkg.in/src-d/go-git.v4"
    . "gopkg.in/src-d/go-git.v4/_examples"
)

func main() {
    r, err := git.PlainOpen(".git")
    CheckIfError(err)

    iter, err := r.CommitObjects()
    CheckIfError(err)
    for {
        c, err := iter.Next()
        if err == io.EOF {
            break
        }

        CheckIfError(err)
        fmt.Println(c.Hash.String())
    }

    iter.Close()
}

Instead of taking ~20secs it is taking ~1m30s.

Maybe this can be related with no usage of the delta cache on someplace.

[filipnavara]

Just got back home after couple of weeks on vacation. As soon as I dig through my piled up work I will try to reproduce your benchmark and investigate it.

[smola]

When not interested in dangling commits, this will speed things up: #1024

[filipnavara]

@ajnavarro I run a profiler on it and tracked it to one of my changes. The logic for pre-loading of small objects was incorrectly applied also on deltas, which resulted in more file seeking and reading than intended, ie. exact opposite of what the optimisation tried to achieve.

I can't quite reproduce the numbers you have, but the fix reduced it from ~1m40s to ~30s on my machine (with profiling enabled).

[ajnavarro]

Hi @filipnavara ,

Now, executing the script I provided above, I'm having the following results:

09:36 $ time /tmp/count-commits-2 | wc -l
80313

real	0m20.012s
user	0m19.432s
sys	0m1.480s

Thanks a lot to take care of this!

[smola]

@jfontan @ajnavarro What about borges? Does it run faster now with latest changes?

[jfontan]

@smola Now borges is a little bit faster:

#### Comparing /root/borges/borges-4.8.0 - /root/borges/borges-4.8.0-pr-963 ####
## Repo cangallo ##
Memory: 24044 -> 24848 (3.343869572450507), true
Wtime: 783.30907ms -> 715.507071ms (-8.655842450541266), true
Stime: 130ms -> 150ms (15.384615384615385), false
Utime: 1.06s -> 990ms (-6.60377358490566), true
FileSize: 116333 -> 120157 (3.2871154358608474), true
## Repo octoprint-tft ##
Memory: 58632 -> 52472 (-10.506208213944603), true
Wtime: 8.633554855s -> 8.539363412s (-1.0909925816415051), true
Stime: 820ms -> 570ms (-30.48780487804878), true
Utime: 9.55s -> 9.28s (-2.8272251308900525), true
FileSize: 2950139 -> 2955791 (0.19158419315157693), true
## Repo upsilon ##
Memory: 628556 -> 613224 (-2.439241690477857), true
Wtime: 2m17.845137743s -> 2m11.257079352s (-4.779318660686348), true
Stime: 11.86s -> 11.02s (-7.082630691399664), true
Utime: 2m32.1s -> 2m25.09s (-4.608809993425378), true
FileSize: 100906120 -> 101068735 (0.16115474462797696), true
## Repo numpy ##
Memory: 1131220 -> 1180632 (4.3680274394017085), true
Wtime: 7m5.332720436s -> 6m56.547470917s (-2.0655005121624352), true
Stime: 55.89s -> 51.97s (-7.01377706208624), true
Utime: 9m11.83s -> 9m39.34s (4.985230958809779), true
FileSize: 96709754 -> 110124947 (13.871602858177056), false