Clone is slow when repo contains a lot of files

[glibsm]

Problem

I've noticed that PlainClone was taking a long time in my use case.

In order to try and reproduce the problem I created a repo containing 17k files
with randomly generated data in them: https://github.com/glibsm/alphabet.

Below is the code used and the resulting performance numbers.

Any help is appreciated. Haven't dug into the go-git library code just yet, figured
I'd share the info I have first.

Sample code

package main

import (
        "flag"
        "fmt"
        "log"
        "os"
        "runtime/pprof"

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

var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")

func main() {
        flag.Parse()
        if *cpuprofile != "" {
                f, err := os.Create(*cpuprofile)
                if err != nil {
                        log.Fatal(err)
                }
                pprof.StartCPUProfile(f)
                defer pprof.StopCPUProfile()
        }

        cloneOpts := &git.CloneOptions{
                URL:      "https://github.com/glibsm/alphabet", // repo with 17k files
                Progress: os.Stdout,
        }
        repo, err := git.PlainClone("./repo", false, cloneOpts)
        if err != nil {
                log.Panic(err)
        }

        head, err := repo.Head()
        if err != nil {
                log.Panic(err)
        }
        fmt.Println(head)
}

Running the sample code

Counting objects: 36579, done.
Compressing objects: 100% (1423/1423), done.
Total 36579 (delta 4), reused 36574 (delta 3), pack-reused 0
978d628f9d82456dffef0bb0579b8a617750c8db refs/heads/master
./plain --cpuprofile plain.cpu  22.18s user 14.97s system 140% cpu **26.404 total**

Command line clone for speed comparison

$ time git clone https://github.com/glibsm/alphabet
Cloning into 'alphabet'...
remote: Counting objects: 36579, done.
remote: Compressing objects: 100% (1423/1423), done.
remote: Total 36579 (delta 4), reused 36574 (delta 3), pack-reused 0
Receiving objects: 100% (36579/36579), 1.56 MiB | 5.98 MiB/s, done.
Resolving deltas: 100% (4/4), done.
Checking out files: 100% (17579/17579), done.

real    0m3.569s
user    0m0.508s
sys     **0m2.826s**

As we can see, the same repo clone times are 2.8 vs 26 seconds, which is quite a big gap.

CPU Profile

Top20 flat

(pprof) top20
Showing nodes accounting for 31.26s, 96.81% of 32.29s total
Dropped 218 nodes (cum <= 0.16s)
Showing top 20 nodes out of 180
      flat  flat%   sum%        cum   cum%
    20.34s 62.99% 62.99%     20.34s 62.99%  syscall.Syscall
     5.24s 16.23% 79.22%      5.24s 16.23%  runtime.kevent
     1.67s  5.17% 84.39%      1.67s  5.17%  runtime.mach_semaphore_wait
     0.84s  2.60% 86.99%      0.84s  2.60%  runtime.memmove
     0.75s  2.32% 89.32%      1.91s  5.92%  runtime.scanobject
     0.53s  1.64% 90.96%      0.53s  1.64%  runtime.mach_semaphore_timedwait
     0.44s  1.36% 92.32%      0.50s  1.55%  runtime.heapBitsForObject
     0.44s  1.36% 93.68%      0.44s  1.36%  runtime.mach_semaphore_signal
     0.41s  1.27% 94.95%      0.41s  1.27%  runtime.usleep
     0.29s   0.9% 95.85%      0.50s  1.55%  runtime.greyobject
     0.11s  0.34% 96.19%      1.05s  3.25%  os.(*file).close
     0.09s  0.28% 96.47%      2.64s  8.18%  runtime.gcDrain
     0.02s 0.062% 96.53%      0.19s  0.59%  runtime.mallocgc
     0.02s 0.062% 96.59%      6.58s 20.38%  gopkg.in/src-d/go-git%2ev4.(*Worktree).resetIndex
     0.02s 0.062% 96.66%      0.32s  0.99%  gopkg.in/src-d/go-git.v4/plumbing/format/index.(*Index).Remove
     0.01s 0.031% 96.69%      7.11s 22.02%  os.openFileNolog
     0.01s 0.031% 96.72%      0.67s  2.07%  runtime.gcMarkDone
     0.01s 0.031% 96.75%      3.53s 10.93%  runtime.systemstack
     0.01s 0.031% 96.78%      8.85s 27.41%  gopkg.in/src-d/go-git%2ev4.(*Worktree).checkoutChangeRegularFile
     0.01s 0.031% 96.81%      0.24s  0.74%  gopkg.in/src-d/go-git.v4/plumbing/format/packfile.(*teeReader).ReadByte

Top 20 cumulative

(pprof) top20 -cum
Showing nodes accounting for 20.37s, 63.08% of 32.29s total
Dropped 218 nodes (cum <= 0.16s)
Showing top 20 nodes out of 180
      flat  flat%   sum%        cum   cum%
         0     0%     0%     22.55s 69.84%  main.main
         0     0%     0%     22.55s 69.84%  runtime.main
         0     0%     0%     22.55s 69.84%  gopkg.in/src-d/go-git%2ev4.(*Repository).clone
         0     0%     0%     22.55s 69.84%  gopkg.in/src-d/go-git%2ev4.PlainClone
         0     0%     0%     22.55s 69.84%  gopkg.in/src-d/go-git%2ev4.PlainCloneContext
         0     0%     0%     21.68s 67.14%  gopkg.in/src-d/go-git%2ev4.(*Worktree).Reset
    20.34s 62.99% 62.99%     20.34s 62.99%  syscall.Syscall
         0     0% 62.99%     15.10s 46.76%  gopkg.in/src-d/go-git%2ev4.(*Worktree).resetWorktree
     0.01s 0.031% 63.02%     13.64s 42.24%  gopkg.in/src-d/go-git.v4/storage/filesystem.(*ObjectStorage).EncodedObject
         0     0% 63.02%     12.48s 38.65%  gopkg.in/src-d/go-git%2ev4.(*Worktree).checkoutChange
         0     0% 63.02%     12.06s 37.35%  gopkg.in/src-d/go-git.v4/plumbing/object.(*Tree).FindEntry
         0     0% 63.02%     12.06s 37.35%  gopkg.in/src-d/go-git.v4/plumbing/object.(*Tree).dir
         0     0% 63.02%      9.59s 29.70%  gopkg.in/src-d/go-git.v4/storage/filesystem.(*ObjectStorage).getFromPackfile
     0.01s 0.031% 63.05%      8.85s 27.41%  gopkg.in/src-d/go-git%2ev4.(*Worktree).checkoutChangeRegularFile
     0.01s 0.031% 63.08%      7.34s 22.73%  gopkg.in/src-d/go-git.v4/storage/filesystem.(*ObjectStorage).decodeObjectAt
         0     0% 63.08%      7.23s 22.39%  internal/poll.(*FD).Seek
         0     0% 63.08%      7.23s 22.39%  os.(*File).Seek
         0     0% 63.08%      7.23s 22.39%  os.(*File).seek
         0     0% 63.08%      7.23s 22.39%  gopkg.in/src-d/go-billy.v4/helper/chroot.(*file).Seek

Go-git sha

The version used in the sample code

- name: gopkg.in/src-d/go-git.v4
  version: e9247ce9c5ce12126f646ca3ddf0066e4829bd14

e9247ce

[barnettZQG]

I have the same problem. Since using the current package, the code gets significantly slower than the git command.

[guillermo-menjivar]

+1

[guillermo-menjivar]

I am getting the same performance issue

[box-lock]$ time go run go_shell_to_git.go                                                                                                             
2018/04/20 02:47:52 Cloning git repo.
2018/04/20 02:47:55 Command finished with error: <nil>

real    0m3.408s
user    0m2.109s
sys     0m1.736s

[box-lock]$ time ./gogit_version -config=repos.toml                                                                                                
Loaded repos to clone
Completed cloning

real    0m19.653s
user    0m18.711s
sys     0m4.549s

[mcuadros]

go-git performance it's slower in many cases in one order of magnitude, and don't expect any improvement there, unless a miracle happens.

You can't compare git project, an effort of thousands of developers and hundreds of companies, with go-git, being done a few dozens of developers with the support of a few companies. git is written in C, with crazy optimization around the full code.

Basically, if you really need performance and none of the crazy extensivity of go-git, simply use the git command, it's unbeatable.

With this I am not saying that we don't care about the performance, actually, we do performance improvements almost in every release, but I am saying that never we will at the same level.

[guillermo-menjivar]

Thanks for the info @mcuadros ! - Is the same conclusion that a colleague and I landed. And we also realized that is not crazy the performance that we need so we are sticking with go-git. Totally understand and will hope to get really familiar with this project to contribute - thanks again.

[lrstanley]

FWIW if you use go-git to clone and get the base representation of a repo, and don't need history or similar (i.e. maybe to just read a file, do a file walk, etc), may be worth looking at shallow clones (depth: 1), no-recurse-submodules, no-tags, single-branch, etc. This helped speed up clones (from 80s+, to ~6s for 17k+ files and 4k+ commits, and for small repos, less than 2s) for my use-case.

I did some brief pprof poking, and nothing stood out much other than decompression (which isn't necessarily an issue with this library) and GC, since the last few commits. May poke at it again in the future.

[barnettZQG]

@lrstanley depth set to 0 is invalid , it will clone all commit. but set it is 1 well.

[lrstanley]

Sorry, that is correct, I meant depth of 1.

[glibsm]

@mcuadros, thank you for the answer. My goal with this issue was not to compare
go-git 1:1 with the git project, but rather to dig in and try to find some
optimizations.

I've written some more sample code (which I will paste below) to try and uncover
where the performance problem may be. The code runs the clone four different
times, mixing and matching between on-disk and in-memory storer and working tree
filesystem (4 cases total).

I'm not sure if this is throwaway work, or has already been done, but what it
seems to show is that the problem lies in how the filesystem storer interacts
with it's underlying filesystem (even if it's memory based). The memory storer
seems to be a lot more efficient (nearly as efficient as git on-disk, in fact).

Numbers first

Storage Type	Mem Filesystem	Disk Filesystem
Memory	3.2s	6.3s
Disk	19.1s	22.6s

2018/05/09 16:53:18 [1] mem_mem with storer *memory.Storage
2018/05/09 16:53:21 >>> mem_mem took 3.229101841s
2018/05/09 16:53:21 [2] fs_mem with storer *filesystem.Storage
2018/05/09 16:53:41 >>> fs_mem took 19.169234266s
2018/05/09 16:53:41 [3] mem_fs with storer *memory.Storage
2018/05/09 16:53:47 >>> mem_fs took 6.313596936s
2018/05/09 16:53:47 [4] fs_fs with storer *filesystem.Storage
2018/05/09 16:54:10 >>> fs_fs took 22.590898471s

If my code and conclusion are correct, filesystem.Storage is to be dug into further. By association, any PlainClone would show similar performance characteristics.

Code

package main

import (
	"io/ioutil"
	"log"
	"os"
	"path/filepath"
	"runtime/pprof"
	"time"

	billy "gopkg.in/src-d/go-billy.v4"
	"gopkg.in/src-d/go-billy.v4/memfs"
	"gopkg.in/src-d/go-billy.v4/osfs"
	git "gopkg.in/src-d/go-git.v4"
	"gopkg.in/src-d/go-git.v4/storage"
	"gopkg.in/src-d/go-git.v4/storage/filesystem"
	"gopkg.in/src-d/go-git.v4/storage/memory"
)

var (
	cloneOpts = &git.CloneOptions{
		URL:   "https://github.com/glibsm/alphabet", // repo with 17k files
		Depth: 1,                                    // smallest set of history
		Tags:  git.NoTags,                           // tags don't matter
	}
	count = 0
)

func main() {
	// spin up a temp directory into which some clones can be made
	tmp, err := ioutil.TempDir("", "fs_mem")
	if err != nil {
		log.Fatal("Failed to create a temp directory")
	}
	cleanup := func() {
		log.Println("Cleaning up the temporary directory")
		os.RemoveAll(tmp)
	}
	checkError := func(e error) {
		if e != nil {
			cleanup()
			log.Fatal("ERROR: ", err)
		}
	}

	// 1: memory storage and memory filesystem for wc
	run("mem_mem", memory.NewStorage(), memfs.New())

	// 2: on disk storage, and memory filesystem for wc
	f2, err := filesystem.NewStorage(osfs.New(filepath.Join(tmp, "fs_mem")))
	checkError(err)
	run("fs_mem", f2, memfs.New())

	// 3: in-memory storage and on-disk filesystem
	run("mem_fs", memory.NewStorage(), osfs.New(filepath.Join(tmp, "mem_fs")))

	// 4: on disk everything
	f4 := osfs.New(filepath.Join(tmp, "fs_fs"))

	f4dot, err := f4.Chroot(".git")
	checkError(err)

	s4, err := filesystem.NewStorage(f4dot)
	checkError(err)
	run("fs_fs", s4, f4)
}

func run(name string, s storage.Storer, fs billy.Filesystem) {
	count++

	// auto-profile the cpu time
	f, err := os.Create(name + "_cpu.pprof")
	if err != nil {
		log.Fatalf("ERROR: failed to create the cpu profile: %v", err)
	}
	pprof.StartCPUProfile(f)
	defer pprof.StopCPUProfile()

	start := time.Now()

	log.Printf("[%d] %s with storer %T\n", count, name, s)
	_, err = git.Clone(s, fs, cloneOpts)
	if err != nil {
		log.Fatalf("ERROR: %s failed to clone: %v", name, err)
	}

	took := time.Since(start)
	log.Printf(">>> %s took %v\n", name, took)
}

Version sha

  revision = "b30763cb64afa91c016b23e905af0a378eb1b76d"
  version = "v4.3.1"

[glibsm]

The profile of the FindEntry filesystem storer that has a significant cost.

ROUTINE ===========gopkg.in/src-d/go-git.v4/plumbing/object.(*Tree).FindEntry 
         0     10.52s (flat, cum) 41.50% of Total
         .          .    109:   return NewFile(e.Name, e.Mode, blob), nil
         .          .    110:}
         .          .    111:
         .          .    112:// FindEntry search a TreeEntry in this tree or any subtree.
         .          .    113:func (t *Tree) FindEntry(path string) (*TreeEntry, error) {
         .       10ms    114:   pathParts := strings.Split(path, "/")
         .          .    115:
         .          .    116:   var tree *Tree
         .          .    117:   var err error
         .          .    118:   for tree = t; len(pathParts) > 1; pathParts = pathParts[1:] {
         .     10.51s    119:           if tree, err = tree.dir(pathParts[0]); err != nil {
         .          .    120:                   return nil, err
         .          .    121:           }
         .          .    122:   }
         .          .    123:
         .          .    124:   return tree.entry(pathParts[0])

It appears to tree.dir with the same argument over and over, despite me cloning with only depth: 1

[mcuadros]

@jfontan PTAL

[jfontan]

I've added a tree cache in FindEntry that alleviates a bit the problem. Memory consumption is almost the same.

With alphabet repo:

test	before	after
mem_mem	4.8s	3.1s
fs_mem	12.5s	5.2s
mem_fs	4.0s	3.0s
fs_fs	12.6s	4.9s
memory	139084k	138924k

With go-git repo:

test	before	after
mem_mem	1.4s	1.9s
fs_mem	0.7s	0.7s
mem_fs	1.4s	0.4s
fs_fs	0.7s	0.5s
memory	138864k	139460k