Re: Periodic hang during git index-pack

From: Sitsofe Wheeler <sitsofe@gmail.com>
Date: Dec 20, 2018, 10:03 UTC
Message-ID: <CALjAwxg2E_48kQYt1GHkcXvVmaFyPY3PGG9rHZNMp+++UqKfow@mail.gmail.com>
In-Reply-To: <20181219232200.GB21283@sigill.intra.peff.net>

On Wed, 19 Dec 2018 at 23:22, Jeff King <peff@peff.net> wrote:

Show 25 quoted lines

>
> On Wed, Dec 19, 2018 at 10:59:30PM +0000, Sitsofe Wheeler wrote:
>
> > While using trying to use git to clone a remote repository git
> > index-pack occasionally goes on to hang:
> > [...]
> > Looking at where it is stuck, git is doing read of a pipe:
> >
> > #0  0x00007fd1b845034e in __libc_read (fd=fd@entry=0,
> > buf=buf@entry=0x55ab81e19d40 <input_buffer>, nbytes=nbytes@entry=4096)
> >     at ../sysdeps/unix/sysv/linux/read.c:27
> > #1  0x000055ab81b51b23 in read (__nbytes=4096, __buf=0x55ab81e19d40
> > <input_buffer>, __fd=0)
> >     at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
>
> Index-pack is reading the pack on stdin, so it's expecting more bytes.
> Those bytes should be coming from the git-clone process, which is
> relaying the bytes from the other side.
>
> Check the backtrace of git-clone to see why it isn't feeding more data
> (but note that it will generally have two threads -- one processing the
> data from the remote, and one wait()ing for index-pack to finish).
>
> My guess, though, is that you'll find that git-clone is simply waiting
> on another pipe: the one from ssh.

Ok here are backtraces from another run (with SSH multiplexing disabled):

(gdb) thread apply all bt

Thread 2 (Thread 0x7faafbf1c700 (LWP 36586)):
#0  0x00007faafc805384 in __libc_read (fd=fd@entry=5,
    buf=buf@entry=0x7faafbf0ddec, nbytes=nbytes@entry=5)
    at ../sysdeps/unix/sysv/linux/read.c:27
#1  0x000055c8ca2f5b23 in read (__nbytes=5, __buf=0x7faafbf0ddec, __fd=5)
    at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
#2  xread (fd=fd@entry=5, buf=buf@entry=0x7faafbf0ddec, len=len@entry=5)
    at wrapper.c:260
#3  0x000055c8ca2f5cdb in read_in_full (fd=5, buf=buf@entry=0x7faafbf0bdf0,
    count=5, count@entry=8193) at wrapper.c:318
#4  0x000055c8ca27222b in get_packet_data (fd=fd@entry=5,
    src_buf=src_buf@entry=0x0, src_size=src_size@entry=0x0,
    dst=dst@entry=0x7faafbf0bdf0, size=size@entry=8193,
    options=options@entry=0) at pkt-line.c:289
#5  0x000055c8ca272ed8 in packet_read_with_status (fd=fd@entry=5,
    src_buffer=src_buffer@entry=0x0, src_len=src_len@entry=0x0,
    buffer=buffer@entry=0x7faafbf0bdf0
"\001\344\305\066JJj\341q@\243\225ժ\350\026M\fkM9:-ƀ\253\206\336\001\275\070\325\372\250\204\232aM\221\213(\320B%\a\275\233\261g\321A\245\n
\247\374\326\b'\v\252\277rA\211\312l\212j\352\177\260\317j\aT\252&t2\256\254\360\002\217V\024\061k\201ڲ;;\017`\361\020:*b\n5\222\036i\272\067}\360,\323\345Y\314ir\311\034b\232F\267\364\016]",
size=size@entry=65520,
    pktlen=pktlen@entry=0x7faafbf0bd94, options=0) at pkt-line.c:344
#6  0x000055c8ca273078 in packet_read (fd=fd@entry=5,
    src_buffer=src_buffer@entry=0x0, src_len=src_len@entry=0x0,
    buffer=buffer@entry=0x7faafbf0bdf0
"\001\344\305\066JJj\341q@\243\225ժ\350\026M\fkM9:-ƀ\253\206\336\001\275\070\325\372\250\204\232aM\221\213(\320B%\a\275\233\261g\321A\245\n
\247\374\326\b'\v\252\277rA\211\312l\212j\352\177\260\317j\aT\252&t2\256\254\360\002\217V\024\061k\201ڲ;;\017`\361\020:*b\n5\222\036i\272\067}\360,\323\345Y\314ir\311\034b\232F\267\364\016]",
size=size@entry=65520,
    options=options@entry=0) at pkt-line.c:364
#7  0x000055c8ca2cbf73 in recv_sideband (
    me=me@entry=0x55c8ca3466ed "fetch-pack", in_stream=5, out=out@entry=6)
    at sideband.c:143
#8  0x000055c8ca22d6cb in sideband_demux (in=<optimised out>, out=6,
    data=<optimised out>) at fetch-pack.c:776
#9  0x000055c8ca2a8458 in run_thread (data=0x7ffda489ef90)
    at run-command.c:1032
#10 0x00007faafc7fb6db in start_thread (arg=0x7faafbf1c700)
    at pthread_create.c:463
#11 0x00007faafc31c88f in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7faafce3bb80 (LWP 36584)):
#0  0x00007faafc805384 in __libc_read (fd=fd@entry=7,
    buf=buf@entry=0x7ffda489ef10, nbytes=nbytes@entry=46)
    at ../sysdeps/unix/sysv/linux/read.c:27
#1  0x000055c8ca2f5b23 in read (__nbytes=46, __buf=0x7ffda489ef10, __fd=7)
    at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
#2  xread (fd=fd@entry=7, buf=buf@entry=0x7ffda489ef10, len=len@entry=46)
    at wrapper.c:260
#3  0x000055c8ca2f5cdb in read_in_full (fd=7, buf=buf@entry=0x7ffda489ef10,
    count=count@entry=46) at wrapper.c:318
#4  0x000055c8ca26a54f in index_pack_lockfile (ip_out=<optimised out>)
    at pack-write.c:297
#5  0x000055c8ca22e18c in get_pack (args=args@entry=0x7ffda489f2e0,
    xd=xd@entry=0x55c8cb4966f8,
    pack_lockfile=pack_lockfile@entry=0x55c8cb496660) at fetch-pack.c:881
#6  0x000055c8ca22fbfb in do_fetch_pack (pack_lockfile=<optimised out>,
    si=0x7ffda489f1f0, nr_sought=<optimised out>, sought=<optimised out>,
    orig_ref=<optimised out>, fd=<optimised out>, args=0x7ffda489f2e0)
    at fetch-pack.c:1019
#7  fetch_pack (args=args@entry=0x7ffda489f2e0, fd=<optimised out>,
    conn=<optimised out>, ref=<optimised out>,
    dest=dest@entry=0x55c8cb498820
"remotehost:diffusion/LIBEDIT/libedit",
sought=sought@entry=0x55c8cb498580,
    nr_sought=<optimised out>, shallow=<optimised out>,
    pack_lockfile=<optimised out>, version=<optimised out>)
    at fetch-pack.c:1649
#8  0x000055c8ca2dddf8 in fetch_refs_via_pack (transport=0x55c8cb496620,
    nr_heads=2, to_fetch=0x55c8cb498580) at transport.c:365
#9  0x000055c8ca2df246 in transport_fetch_refs (
    transport=transport@entry=0x55c8cb496620, refs=refs@entry=0x55c8cb4959e0)
    at transport.c:1295
#10 0x000055c8ca1529ab in cmd_clone (argc=<optimised out>,
    argv=<optimised out>, prefix=<optimised out>) at builtin/clone.c:1212
#11 0x000055c8ca1374e1 in run_builtin (argv=<optimised out>,
    argc=<optimised out>, p=<optimised out>) at git.c:421
#12 handle_builtin (argc=<optimised out>, argv=<optimised out>) at git.c:647
#13 0x000055c8ca138515 in run_argv (argv=0x7ffda489fa00, argcp=0x7ffda489fa0c)
    at git.c:701
#14 cmd_main (argc=<optimised out>, argv=<optimised out>) at git.c:798
#15 0x000055c8ca13718f in main (argc=4, argv=0x7ffda489fc78)
    at common-main.c:45

(gdb) thread apply all bt

Thread 1 (Thread 0x7ff8a03dab80 (LWP 36587)):
#0  0x00007ff89fda434e in __libc_read (fd=fd@entry=0,
    buf=buf@entry=0x5604bea43d40 <input_buffer>, nbytes=nbytes@entry=4096)
    at ../sysdeps/unix/sysv/linux/read.c:27
#1  0x00005604be77bb23 in read (__nbytes=4096,
    __buf=0x5604bea43d40 <input_buffer>, __fd=0)
    at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
#2  xread (fd=0, buf=0x5604bea43d40 <input_buffer>, len=4096) at wrapper.c:260
#3  0x00005604be5fb069 in fill (min=min@entry=1) at builtin/index-pack.c:255
#4  0x00005604be5fb23a in unpack_entry_data (offset=528312,
    size=size@entry=19448, type=<optimised out>, oid=oid@entry=0x5604c0605ea0)
    at builtin/index-pack.c:445
#5  0x00005604be5fbbc7 in unpack_raw_entry (oid=0x5604c0605ea0,
    ref_oid=0x7ffc74cd73f0, ofs_offset=0x5604c0603580, obj=0x5604c0605ea0)
    at builtin/index-pack.c:526
#6  parse_pack_objects (hash=0x7ffc74cd74a0 "\001")
    at builtin/index-pack.c:1113
#7  cmd_index_pack (argc=<optimised out>, argv=<optimised out>,
    prefix=<optimised out>) at builtin/index-pack.c:1775
#8  0x00005604be5bd4e1 in run_builtin (argv=<optimised out>,
    argc=<optimised out>, p=<optimised out>) at git.c:421
#9  handle_builtin (argc=<optimised out>, argv=<optimised out>) at git.c:647
#10 0x00005604be5be515 in run_argv (argv=0x7ffc74cd7640, argcp=0x7ffc74cd764c)
    at git.c:701
#11 cmd_main (argc=<optimised out>, argv=<optimised out>) at git.c:798
#12 0x00005604be5bd18f in main (argc=7, argv=0x7ffc74cd78b8)
    at common-main.c:45

As before, any hints on how to debug this gratefully accepted!

-- 
Sitsofe | http://sucs.org/~sits/