'guix substitutes' sometimes hangs on glibc 2.27

> When downloading a number of substitutes, ‘guix substitute’ sometimes

> hangs for me since the switch to glibc 2.27. Anyone else experiencing

> this? It’s relatively frequent for me.

> #0 0x00007fbb34bf794d in __GI___pthread_timedjoin_ex (threadid=140441961314048, thread_return=thread_return@entry=0x0, abstime=abstime@entry=0x0, block=block@entry=true)

> at pthread_join_common.c:89

> #1 0x00007fbb34bf773c in __pthread_join (threadid=<optimized out>, thread_return=thread_return@entry=0x0) at pthread_join.c:24

> #2 0x00007fbb350d7548 in stop_finalization_thread () at finalizers.c:265

> #3 0x00007fbb350d7759 in scm_i_finalizer_pre_fork () at finalizers.c:290

> #4 0x00007fbb3514f256 in scm_fork () at posix.c:1222

> (let loop ((files files)

> (n 0))

> (match files

> ((file . tail)

> (call-with-input-file file

> (lambda (port)

> (call-with-decompressed-port 'gzip port

> (lambda (port)

> (let loop ()

> (unless (eof-object? (get-bytevector-n port 777))

> (loop)))))))

> ;; (pk 'loop n file)

> (display ".")

> (loop tail (+ n 1)))))

> (+Cc: Andy as the ultimate authority for all these things. :-))

>

> ludo@gnu.org (Ludovic Courtès) skribis:

>

>> (let loop ((files files)

>> (n 0))

>> (match files

>> ((file . tail)

>> (call-with-input-file file

>> (lambda (port)

>> (call-with-decompressed-port 'gzip port

>> (lambda (port)

>> (let loop ()

>> (unless (eof-object? (get-bytevector-n port 777))

>> (loop)))))))

>> ;; (pk 'loop n file)

>> (display ".")

>> (loop tail (+ n 1)))))

>

> One problem I’ve noticed is that the child process that

> ‘call-with-decompressed-port’ spawns would be stuck trying to get the

> allocation lock:

>

> (gdb) bt

> #0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135

> #1 0x00007f9fd8d5cb25 in __GI___pthread_mutex_lock (mutex=0x7f9fd91b3240 <GC_allocate_ml>) at ../nptl/pthread_mutex_lock.c:78

> #2 0x00007f9fd8f8ef8f in GC_call_with_alloc_lock (fn=fn@entry=0x7f9fd92b0420 <do_copy_weak_entry>, client_data=client_data@entry=0x7ffe4b9a0d80) at misc.c:1929

> #3 0x00007f9fd92b1270 in copy_weak_entry (dst=0x7ffe4b9a0d70, src=0x759ed0) at weak-set.c:124

> #4 weak_set_remove_x (closure=0x8850c0, pred=0x7f9fd92b0440 <eq_predicate>, hash=3944337866184184181, set=0x70cf00) at weak-set.c:615

> #5 scm_c_weak_set_remove_x (set=set@entry=#<weak-set 756df0>, raw_hash=<optimized out>, pred=pred@entry=0x7f9fd92b0440 <eq_predicate>, closure=closure@entry=0x8850c0) at weak-set.c:791

> #6 0x00007f9fd92b13b0 in scm_weak_set_remove_x (set=#<weak-set 756df0>, obj=obj@entry=#<port 2 8850c0>) at weak-set.c:812

> #7 0x00007f9fd926f72f in close_port (port=#<port 2 8850c0>, explicit=<optimized out>) at ports.c:884

> #8 0x00007f9fd92ad307 in vm_regular_engine (thread=0x7f9fd91b3240 <GC_allocate_ml>, vp=0x7adf30, registers=0x0, resume=-657049556) at vm-engine.c:786

> #9 0x00007f9fd92afb37 in scm_call_n (proc=<error reading variable: ERROR: Cannot access memory at address 0xd959b030>0x7f9fd959b030, argv=argv@entry=0x7ffe4b9a1018, nargs=nargs@entry=1) at vm.c:1257

> #10 0x00007f9fd9233017 in scm_primitive_eval (exp=<optimized out>, exp@entry=<error reading variable: ERROR: Cannot access memory at address 0xd5677cf8>0x855280) at eval.c:662

> #11 0x00007f9fd9233073 in scm_eval (exp=<error reading variable: ERROR: Cannot access memory at address 0xd5677cf8>0x855280, module_or_state=module_or_state@entry=<error reading variable: ERROR: Cannot access memory at address 0xd95580d8>0x83d140) at eval.c:696

> #12 0x00007f9fd927e8d0 in scm_shell (argc=2, argv=0x7ffe4b9a1668) at script.c:454

> #13 0x00007f9fd9249a9d in invoke_main_func (body_data=0x7ffe4b9a1510) at init.c:340

> #14 0x00007f9fd922c28a in c_body (d=0x7ffe4b9a1450) at continuations.c:422

> #15 0x00007f9fd92ad307 in vm_regular_engine (thread=0x7f9fd91b3240 <GC_allocate_ml>, vp=0x7adf30, registers=0x0, resume=-657049556) at vm-engine.c:786

> #16 0x00007f9fd92afb37 in scm_call_n (proc=proc@entry=#<smob catch-closure 795120>, argv=argv@entry=0x0, nargs=nargs@entry=0) at vm.c:1257

> #17 0x00007f9fd9231e69 in scm_call_0 (proc=proc@entry=#<smob catch-closure 795120>) at eval.c:481

> #18 0x00007f9fd929e7b2 in catch (tag=tag@entry=#t, thunk=#<smob catch-closure 795120>, handler=<error reading variable: ERROR: Cannot access memory at address 0x400000000>0x7950c0, pre_unwind_handler=<error reading variable: ERROR: Cannot access memory at address 0x400000000>0x7950a0) at throw.c:137

> #19 0x00007f9fd929ea95 in scm_catch_with_pre_unwind_handler (key=key@entry=#t, thunk=<optimized out>, handler=<optimized out>, pre_unwind_handler=<optimized out>) at throw.c:254

> #20 0x00007f9fd929ec5f in scm_c_catch (tag=tag@entry=#t, body=body@entry=0x7f9fd922c280 <c_body>, body_data=body_data@entry=0x7ffe4b9a1450, handler=handler@entry=0x7f9fd922c510 <c_handler>, handler_data=handler_data@entry=0x7ffe4b9a1450, pre_unwind_handler=pre_unwind_handler@entry=0x7f9fd922c370 <pre_unwind_handler>, pre_unwind_handler_data=0x7a9bc0) at throw.c:377

> #21 0x00007f9fd922c870 in scm_i_with_continuation_barrier (body=body@entry=0x7f9fd922c280 <c_body>, body_data=body_data@entry=0x7ffe4b9a1450, handler=handler@entry=0x7f9fd922c510 <c_handler>, handler_data=handler_data@entry=0x7ffe4b9a1450, pre_unwind_handler=pre_unwind_handler@entry=0x7f9fd922c370 <pre_unwind_handler>, pre_unwind_handler_data=0x7a9bc0) at continuations.c:360

> #22 0x00007f9fd922c905 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>) at continuations.c:456

> #23 0x00007f9fd929d3ec in with_guile (base=base@entry=0x7ffe4b9a14b8, data=data@entry=0x7ffe4b9a14e0) at threads.c:661

> #24 0x00007f9fd8f8efb8 in GC_call_with_stack_base (fn=fn@entry=0x7f9fd929d3a0 <with_guile>, arg=arg@entry=0x7ffe4b9a14e0) at misc.c:1949

> #25 0x00007f9fd929d708 in scm_i_with_guile (dynamic_state=<optimized out>, data=data@entry=0x7ffe4b9a14e0, func=func@entry=0x7f9fd9249a80 <invoke_main_func>) at threads.c:704

> #26 scm_with_guile (func=func@entry=0x7f9fd9249a80 <invoke_main_func>, data=data@entry=0x7ffe4b9a1510) at threads.c:710

> #27 0x00007f9fd9249c32 in scm_boot_guile (argc=argc@entry=2, argv=argv@entry=0x7ffe4b9a1668, main_func=main_func@entry=0x400cb0 <inner_main>, closure=closure@entry=0x0) at init.c:323

> #28 0x0000000000400b70 in main (argc=2, argv=0x7ffe4b9a1668) at guile.c:101

> (gdb) info threads

> Id Target Id Frame

> * 1 Thread 0x7f9fd972eb80 (LWP 15573) "guile" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135

>

> So it seems quite clear that the thing has the alloc lock taken. I

> suppose this can happen if one of the libgc threads runs right when we

> call fork and takes the alloc lock, right?

> If that is correct, the fix would be to call fork within

> ‘GC_call_with_alloc_lock’.

>

> How does that sound?

> As a workaround on the Guix side, we might achieve the same effect by

> calling ‘gc-disable’ right before ‘primitive-fork’.

>> One problem I’ve noticed is that the child process that

>> ‘call-with-decompressed-port’ spawns would be stuck trying to get the

>> allocation lock:

>>

>> So it seems quite clear that the thing has the alloc lock taken. I

>> suppose this can happen if one of the libgc threads runs right when we

>> call fork and takes the alloc lock, right?

>

> Does libgc spawn threads that run concurrently with user threads? If

> so, that would be news to me. My understanding was that incremental

> marking occurs within GC allocation calls, and marking threads are only

> spawned after all user threads have been stopped, but I could be wrong.

> The first idea that comes to my mind is that perhaps the finalization

> thread is holding the GC allocation lock when 'fork' is called.

> Another possibility: both the finalization thread and the signal

> delivery thread call 'scm_without_guile', which calls 'GC_do_blocking',

> which also temporarily grabs the GC allocation lock before calling the

> specified function. See 'GC_do_blocking_inner' in pthread_support.c in

> libgc. You spawn the signal delivery thread by calling 'sigaction' and

> you make work for it to do every second when the SIGALRM is delivered.

>> If that is correct, the fix would be to call fork within

>> ‘GC_call_with_alloc_lock’.

>>

>> How does that sound?

>

> Sure, sounds good to me.

> Does libgc spawn threads that run concurrently with user threads? If

> so, that would be news to me. My understanding was that incremental

> marking occurs within GC allocation calls, and marking threads are only

> spawned after all user threads have been stopped, but I could be wrong.

> The first idea that comes to my mind is that perhaps the finalization

> thread is holding the GC allocation lock when 'fork' is called. The

> finalization thread grabs the GC allocation lock every time it calls

> 'GC_invoke_finalizers'. All ports backed by POSIX file descriptors

> (including pipes) register finalizers and therefore spawn the

> finalization thread and make work for it to do.

> Another possibility: both the finalization thread and the signal

> delivery thread call 'scm_without_guile', which calls 'GC_do_blocking',

> which also temporarily grabs the GC allocation lock before calling the

> specified function. See 'GC_do_blocking_inner' in pthread_support.c in

> libgc. You spawn the signal delivery thread by calling 'sigaction' and

> you make work for it to do every second when the SIGALRM is delivered.

>> If that is correct, the fix would be to call fork within

>> ‘GC_call_with_alloc_lock’.

>>

>> How does that sound?

>

> Sure, sounds good to me.

> On Thu 05 Jul 2018 05:33, Mark H Weaver <mhw@netris.org> writes:

>

>>> One problem I’ve noticed is that the child process that

>>> ‘call-with-decompressed-port’ spawns would be stuck trying to get the

>>> allocation lock:

>>>

>>> So it seems quite clear that the thing has the alloc lock taken. I

>>> suppose this can happen if one of the libgc threads runs right when we

>>> call fork and takes the alloc lock, right?

>>

>> Does libgc spawn threads that run concurrently with user threads? If

>> so, that would be news to me. My understanding was that incremental

>> marking occurs within GC allocation calls, and marking threads are only

>> spawned after all user threads have been stopped, but I could be wrong.

>

> I think Mark is correct.

>> The first idea that comes to my mind is that perhaps the finalization

>> thread is holding the GC allocation lock when 'fork' is called.

>

> So of course we agree you're only supposed to "fork" when there are no

> other threads running, I think.

>

> As far as the finalizer thread goes, "primitive-fork" calls

> "scm_i_finalizer_pre_fork" which should join the finalizer thread,

> before the fork. There could be a bug obviously but the intention is

> for Guile to shut down its internal threads.

> Here's the body of primitive-fork fwiw:

>

> {

> int pid;

> scm_i_finalizer_pre_fork ();

> if (scm_ilength (scm_all_threads ()) != 1)

>> Another possibility: both the finalization thread and the signal

>> delivery thread call 'scm_without_guile', which calls 'GC_do_blocking',

>> which also temporarily grabs the GC allocation lock before calling the

>> specified function. See 'GC_do_blocking_inner' in pthread_support.c in

>> libgc. You spawn the signal delivery thread by calling 'sigaction' and

>> you make work for it to do every second when the SIGALRM is delivered.

>

> The signal thread is a possibility though in that case you'd get a

> warning; the signal-handling thread appears in scm_all_threads. Do you

> see a warning? If you do, that is a problem :)

>>> If that is correct, the fix would be to call fork within

>>> ‘GC_call_with_alloc_lock’.

>>>

>>> How does that sound?

>>

>> Sure, sounds good to me.

>

> I don't think this is necessary. I think the problem is that other

> threads are running. If we solve that, then we solve this issue; if we

> don't solve that, we don't know what else those threads are doing, so we

> don't know what mutexes and other state they might have.

> On Thu 05 Jul 2018 05:33, Mark H Weaver <mhw@netris.org> writes:

>> Another possibility: both the finalization thread and the signal

>> delivery thread call 'scm_without_guile', which calls 'GC_do_blocking',

>> which also temporarily grabs the GC allocation lock before calling the

>> specified function. See 'GC_do_blocking_inner' in pthread_support.c in

>> libgc. You spawn the signal delivery thread by calling 'sigaction' and

>> you make work for it to do every second when the SIGALRM is delivered.

>

> The signal thread is a possibility though in that case you'd get a

> warning; the signal-handling thread appears in scm_all_threads. Do you

> see a warning? If you do, that is a problem :)

> However, it's also the case that libgc uses 'pthread_atfork' (where

> available) to arrange to grab the GC allocation as well as the "mark

> locks" in the case where parallel marking is enabled. See

> fork_prepare_proc, fork_parent_proc, and fork_child_proc in

> pthread_support.c.

>> Here's the body of primitive-fork fwiw:

>>

>> {

>> int pid;

>> scm_i_finalizer_pre_fork ();

>> if (scm_ilength (scm_all_threads ()) != 1)

>

> I think there's a race here. I think it's possible for the finalizer

> thread to be respawned after 'scm_i_finalizer_pre_fork' in two different

> ways:

>

> (1) 'scm_all_threads' performs allocation, which could trigger GC.

>

> (2) another thread could perform heap allocation and trigger GC after

> 'scm_i_finalizer_pre_fork' joins the thread. it might then shut

> down before 'scm_all_thread' is called.

>

> However, these are highly unlikely scenarios, and most likely not the

> problem we're seeing here.

>

> Still, I think the 'scm_i_finalizer_pre_fork' should be moved after the

> 'if', to avoid this race.

> Hello,

>

> Andy Wingo <wingo@igalia.com> skribis:

>

>> The signal thread is a possibility though in that case you'd get a

>> warning; the signal-handling thread appears in scm_all_threads. Do you

>> see a warning? If you do, that is a problem :)

>

> I don’t see a warning.

>

> But as a Guile user, I shouldn’t see a warning just because there’s a

> signal thread anyway; it’s not a thread I spawned myself.

> The weird thing is that the signal thread always exists, and it’s

> surprising IMO that it shows up in ‘scm_all_threads’ because it’s not a

> “user thread”. The other surprise is that the warning isn’t triggered:

>

> $ guile

> GNU Guile 2.2.4

> Copyright (C) 1995-2017 Free Software Foundation, Inc.

>

> Guile comes with ABSOLUTELY NO WARRANTY; for details type `,show w'.

> This program is free software, and you are welcome to redistribute it

> under certain conditions; type `,show c' for details.

>

> Enter `,help' for help.

> scheme@(guile-user)> (all-threads)

> $1 = (#<thread 140488743438080 (1b06c40)> #<thread 140488815434624 (1b06e00)>)

> scheme@(guile-user)> (when (zero? (primitive-fork)) (primitive-_exit 0))

> ;; no warning

> On Thu 05 Jul 2018 14:27, ludo@gnu.org (Ludovic Courtès) writes:

>

>> Hello,

>>

>> Andy Wingo <wingo@igalia.com> skribis:

>>

>>> The signal thread is a possibility though in that case you'd get a

>>> warning; the signal-handling thread appears in scm_all_threads. Do you

>>> see a warning? If you do, that is a problem :)

>>

>> I don’t see a warning.

>>

>> But as a Guile user, I shouldn’t see a warning just because there’s a

>> signal thread anyway; it’s not a thread I spawned myself.

>

> I understand but it's how it works. If we want to change this, probably

> we need a similar interface as we have with finalization.

>> scheme@(guile-user)> (all-threads)

>> $1 = (#<thread 140488743438080 (1b06c40)> #<thread 140488815434624 (1b06e00)>)

>> scheme@(guile-user)> (when (zero? (primitive-fork)) (primitive-_exit 0))

>> ;; no warning

>

> Are you certain that this is the signal-handling thread and not the

> finalizer thread? I suspect it is the finalizer thread, and that it

> gets properly shut down before the fork.

> Regarding seeing the warning: do you do make some other binding for the

> default warning port in Guix?