Re: upload-pack is slow with lots of refs

[Ævar Arnfjörð Bjarmason <avarab@gmail.com>]

On Wed, Oct 3, 2012 at 11:20 PM, Jeff King <peff@peff.net> wrote:

Thanks for all that info, it's really useful.

>>  * A co-worker who was working on this today tried it on 1.7.12 and
>>    claimed that it had the same performance characteristics.
>
> That's surprising to me. Can you try to verify those numbers?

I think he was wrong, I tested this on git.git by first creating a lot
of tags:

     parallel --eta "git tag -a -m"{}" test-again-{}" ::: $(git rev-list HEAD)

Then doing:

    git pack-refs --all
    git repack -A -d

And compiled with -g -O3 I get around 1.55 runs/s of git-upload-pack
on 1.7.8 and 2.59/s on the master branch.

>>  * I tried to profile it under gcc -pg && echo -n | ./git-upload-pack
>>    <repo> but it doesn't produce a profile like that, presumably
>>    because the process exits unsuccessfully.
>
> If it's a recent version of Linux, you'll get much nicer results with
> perf. Here's what my 400K-ref case looks like:
>
>   $ time echo 0000 | perf record git-upload-pack . >/dev/null
>   real    0m0.808s
>   user    0m0.660s
>   sys     0m0.136s
>
>   $ perf report | grep -v ^# | head
>   11.40%  git-upload-pack  libc-2.13.so        [.] vfprintf
>    9.70%  git-upload-pack  git-upload-pack     [.] find_pack_entry_one
>    7.64%  git-upload-pack  git-upload-pack     [.] check_refname_format
>    6.81%  git-upload-pack  libc-2.13.so        [.] __memcmp_sse4_1
>    5.79%  git-upload-pack  libc-2.13.so        [.] getenv
>    4.20%  git-upload-pack  libc-2.13.so        [.] __strlen_sse42
>    3.72%  git-upload-pack  git-upload-pack     [.] ref_entry_cmp_sslice
>    3.15%  git-upload-pack  git-upload-pack     [.] read_packed_refs
>    2.65%  git-upload-pack  git-upload-pack     [.] sha1_to_hex
>    2.44%  git-upload-pack  libc-2.13.so        [.] _IO_default_xsputn

FWIW here are my results on the above pathological git.git

    $ uname -r; perf --version; echo 0000 | perf record
./git-upload-pack .>/dev/null; perf report | grep -v ^# | head
    3.2.0-2-amd64
    perf version 3.2.17
    [ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 0.026 MB perf.data (~1131 samples) ]
        29.08%  git-upload-pack  libz.so.1.2.7       [.] inflate
        17.99%  git-upload-pack  libz.so.1.2.7       [.] 0xaec1
         6.21%  git-upload-pack  libc-2.13.so        [.] 0x117503
         5.69%  git-upload-pack  libcrypto.so.1.0.0  [.] 0x82c3d
         4.87%  git-upload-pack  git-upload-pack     [.] find_pack_entry_one
         3.18%  git-upload-pack  ld-2.13.so          [.] 0x886e
         2.96%  git-upload-pack  libc-2.13.so        [.] vfprintf
         2.83%  git-upload-pack  git-upload-pack     [.] search_for_subdir
         1.56%  git-upload-pack  [kernel.kallsyms]   [k] do_raw_spin_lock
         1.36%  git-upload-pack  libc-2.13.so        [.] vsnprintf

I wonder why your report doesn't note any time in libz. This is on
Debian testing, maybe your OS uses different strip settings so it
doesn't show up?

    $ ldd -r ./git-upload-pack
            linux-vdso.so.1 =>  (0x00007fff621ff000)
            libz.so.1 => /lib/x86_64-linux-gnu/libz.so.1 (0x00007f768feee000)
            libcrypto.so.1.0.0 =>
/usr/lib/x86_64-linux-gnu/libcrypto.so.1.0.0 (0x00007f768fb0a000)
            libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0
(0x00007f768f8ed000)
            libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f768f566000)
            libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f768f362000)
            /lib64/ld-linux-x86-64.so.2 (0x00007f7690117000