Slow cloning with hg-git: an attempt at profiling
Hi,
cloning a big git repository via hg-git has always been not really fast. For example, on my machine cloning https://github.com/bitcoin/bitcoin takes ~30 minutes.
I really hope this could be made faster; to start this effort, I thought that doing some profiling work could help. The bitcoin repository is too big, so I choose another project (https://github.com/kdave/btrfs-progs: 6500 commits, 148 tags, 16 MB of contents in its head revision, a .git folder of 19 MB).
First of all, the baselines:
command | time | %baseline |
---|---|---|
git clone https://github.com/kdave/btrfs-progs |
3.2 s | 100% |
hg clone git+https://github.com/kdave/btrfs-progs |
52.9 s | 1653% (16 times slower!) |
cprofile on hg clone git+https://github.com/kdave/btrfs-progs
|
84.3 s | speed not meaningful due to the measuring overhead |
A cloning that takes ~3 seconds with git takes ~53 seconds with mercurial/hg-git: 16 times as much!
These tests were made in this environment:
- fedora 37 (kernel 6.2)
- git v2.40.1
- python v3.11.3
- hg v6.2.3
- hg-git v1.0.2
- dulwich v0.21.3
Hardware:
- Xeon E3-1265L V2 @ 2.50GHz (not really a bottleneck here)
- 16 GB RAM
- SATA3 SSD (not really a bottleneck here)
profiling using cProfile
I have used cProfile to profile the cloning. The profiling overhead is significant (we go from from 53s to 84s), hopefully this will decrease when we can use perf on python3.12.
time python -m cProfile -o ~/btrfs-progs-clone.cprof /usr/bin/hg clone git+https://github.com/kdave/btrfs-progs
destination directory: btrfs-progs
importing 6699 git commits
new changesets 3fe272fcfd57:8a107059ab38 (6699 drafts)
updating to bookmark master
791 files updated, 0 files merged, 0 files removed, 0 files unresolved
real 1m24,293s
user 1m18,146s
sys 0m2,480s
The result of the profiling is here: btrfs-progs-clone.cprof. It can be visualized, for example, with SnakeViz (pip install snakeviz
):
snakeviz btrfs-progs-clone.cprof
As said, in this thest the total time for the cloning was ~84 seconds. This is a zoom on the first meaningful function that accounts for ~100% of that time. A breakdown of the deeper functions is in the image, while the list of the previous call stack elements is on the right, for completeness:
profiling using strace
I've also tried using strace to profile the cloning. The overhead is still higher, however.
time strace --summary -o ~/btrfs-progs-strace.log /usr/bin/hg clone git+https://github.com/kdave/btrfs-progs
destination directory: btrfs-progs
importing 6699 git commits
new changesets 3fe272fcfd57:8a107059ab38 (6699 drafts)
updating to bookmark master
791 files updated, 0 files merged, 0 files removed, 0 files unresolved
real 3m52,715s
user 2m5,755s
sys 1m36,003s
I believe the very high sys time is strace's overhead. In the plain hg-git clone the system time was just 4% of the total time (less than 3 seconds). This aligns nicely with the absolute times that strace produces in its summary:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ------------------
26,91 0,889219 1 548434 3 lseek
24,04 0,794304 2 350410 read
12,80 0,422899 4 101525 17551 openat
12,53 0,414054 2 150241 2878 newfstatat
6,02 0,198903 6027 33 3 wait4
5,62 0,185728 2 83999 close
4,96 0,163822 1 87659 83051 ioctl
4,12 0,136191 3 41115 write
1,02 0,033586 5 6502 utimensat
I'd say that not too much time is spent in the system calls. Maybe there is a tad too much disk activity but nothing stands out.