Bug 906468

Alex,

Thanks for the report, and I'm sorry to hear you're having a deadlock issue.

Can you please confirm that the situation you see is as follows?

Thread A:

* Calls fork() which runs atfork handlers, including locking the arenas via the implementation's malloc atfork handler ptmalloc_lock_all() (ensures malloc is in a consistent state across the fork)...
* ... Tries to take the IO lock via _IO_list_lock() 
-> _IO_lock_lock(list_all_lock);

Thread B:

* Likely calls _IO_flush_all() 
-> _IO_flush_all_lockp (do_lock=1) 
-> _IO_lock_lock (list_all_lock); ...
* ... Which then attempts to take all open file locks and flush those files.

Thread C:

* Likely calls _IO_getdelim which takes the file lock and then tries to call realloc which requires the arena lock.

So in summary:
Thread A waits on thread B for the list_all_lock lock.
Thread B waits on thread C for the fp file lock.
Thread C waits on thread A for the arena lock.

Please note that your suggestion solution is not correct and only makes the deadlock window smaller. In general you would have to avoid *all* uses of malloc within critical sections that hold file locks, and that is not possible without serious performance penalties.

One possible fix is to have the malloc pthread_atfork handlers take the IO locks and wait for all IO to stop *before* locking all of the memory arenas. This would make the locking look like this:

Thread A:

* Calls fork() which runs atfork handlers:
- _IO_lock_lock (list_all_lock).
- Lock malloc arenas.

Thread B:

* Calls _IO_flush_all():
- _IO_lock_lock (list_all_lock).
- Lock all open files one by one for flushing.

Thread C:

* Calls _IO_getdelim():
- Takes file lock.
- Locks malloc arena to allocate memory.

In this case A and B acquire _IO_lock_lock before locking the arenas, and that ensures that other threads are able to make forward progress or blocked, but not deadlocked.

This is a more difficult fix since it requires refactoring the malloc pthread_atfork handlers into more generic code which does two things:
* Puts a stop to all IO.
* Puts a stop to all allocations.
... and artificially run this handler last.

Changing the code in this way could potentially delay the fork() indefinitely as the forking thread must wait for the IO lock. However the alternative is a deadlock. If the application ensures no IO is in progress it's no more latency than normal.

Comments?

Cheers,
Carlos.

Note that the workaround is to ensure that all of your threads have *stopped* doing IO before issuing the fork. We understand that this might not be possible in all cases. However, I thought I should mention it since you might have control over the application.

Carlos,
Your summary of the problem is accurate, except that the thread is stuck on malloc (iogetdelim.c:68), not realloc (iogetdelim.c:108).  I am attaching below the stack backtrace of the thread that is performing _IO_getdelim (I am sorry I missed it in the orginal problem description).


Thread 71 (Thread 0x7f0fac24f700 (LWP 14026)):

#0  __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:97
#1  0x00007f0ff139cae8 in _L_lock_9164 () at malloc.c:3503
#2  0x00007f0ff139a482 in *__GI___libc_malloc (bytes=139701797257248) at malloc.c:3657
#3  0x00007f0ff1387f59 in _IO_getdelim (lineptr=0x7f0fac24e260, n=0x7f0fac24e268, delimiter=10, fp=0x7f0edc05be90) at iogetdelim.c:68
#4  0x00007f0ff538a909 in getline (__stream=<optimized out>, __n=<optimized out>, __lineptr=<optimized out>) at /usr/include/bits/stdio.h:114
#5  load_1 (ms=0x7f0edc000950, action=<optimized out>, fn=<optimized out>, errs=<optimized out>, marray=<optimized out>, marraycount=<optimized out>) at apprentice.c:690
#6  0x00007f0ff538c7fa in apprentice_load (ms=0x7f0edc000950, magicp=<optimized out>, nmagicp=<optimized out>, fn=0x7f0edc05c980 "/opt/.../magic", action=0) at apprentice.c:825
#7  0x00007f0ff538d729 in apprentice_1 (mlist=<optimized out>, action=<optimized out>, fn=<optimized out>, ms=<optimized out>) at apprentice.c:288
#8  file_apprentice (ms=<optimized out>, fn=<optimized out>, action=<optimized out>) at apprentice.c:385
#9  0x00007f0ff53896d8 in magic_load (ms=0x7f0edc000020, magicfile=<optimized out>) at magic.c:311
#10 0x00007f0fe88da09a in ...
#11 0x00007f0fe88da555 in ...
#12 0x00007f0ff9f0f28f in ...
#13 0x00007f0ffd75dcf7 in ...
#14 0x00007f0ffcf7b1f1 in ...
#15 0x00007f0ffcf7bff8 in ...
#16 0x00007f0ffcf51638 in ...
#17 0x00007f0ffcf55bb5 in ...
#18 0x00007f0ffcf5af9e in ...
#19 0x0000000000408c4d in ...
#20 0x00007f0ff4ee0184 in g_thread_create_proxy (data=0x7f0fd40086d0) at gthread.c:635
#21 0x00007f0ff319d7f1 in start_thread (arg=0x7f0fac24f700) at pthread_create.c:301
#22 0x00007f0ff140670d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115



You're right saying that moving (iogetdelim.c:68) outside of section holding the lock on fp file lock delays the problem, since we can still hit realloc (iogetdelim.c:108) while holding the fp lock.

Reversing the order of the locks as you suggested makes sense, since this would cover more cases.

Regarding your suggestion for the workaround where all the threads stop IO before forking, in our case this is simply not feasable.  We can have up to 1000 threads in our app, and synchronizing all IO and forking would kill the performance.

(In reply to comment #5)
> Carlos,
> Your summary of the problem is accurate, except that the thread is stuck on
> malloc (iogetdelim.c:68), not realloc (iogetdelim.c:108).  I am attaching
> below the stack backtrace of the thread that is performing _IO_getdelim (I
> am sorry I missed it in the orginal problem description).
 
Thanks for the quick followup.

I'm glad you agree with the summary.

Note that there were two paths in _IO_getdelmin, one with malloc, the other with realloc, both attempt to lock the memory arena lock which was already locked by the malloc pthread_atfork handler.
 
> You're right saying that moving (iogetdelim.c:68) outside of section holding
> the lock on fp file lock delays the problem, since we can still hit realloc
> (iogetdelim.c:108) while holding the fp lock.

Correct.

> Regarding your suggestion for the workaround where all the threads stop IO
> before forking, in our case this is simply not feasable.  We can have up to
> 1000 threads in our app, and synchronizing all IO and forking would kill the
> performance.

The other alternative is to do unbuffered IO and recompile lua to stop calling fflush(NULL) before popen().

I should have clarified that this is stream-related IO using FILE pointers not normal IO using file descriptors.

Please note that you already incur a synchronization penalty by forking. The forking thread takes the libio list_all_lock and that will block *all* other threads from doing any libio operations which may make the stream IO state inconsistent across the fork. Generally this is limited to operations like "flush all streams" (walks master file list), "open FILE" (adds to master file list) etc.

Cheers,
Carlos.

I've had a couple of upstream conversations regarding this deadlock and it's going to be too invasive and risky for RHEL 6.5, so I'm moving this to RHEL 7.0 where we'll have a chance to do the appropriate validation and verification.

If the priority of this issue changes for you, please update this issue.

I think i ran into the same or a similar problem with a program of mine, that was working until and including Fedora-22. Now, on Fedora-23 it gets stuck after some fractions of a second. It is a service, that accepts TCP connections in threads, then depending on the request it may fork and run another program.
On Redhat 5 and 6 it is working since years and now is being broken by some change. On my Fedora 23 the glibc and pthread is from the package glibc-2.22-6.fc23.i686 . The machine is a Pentium single processor, even there it happens, so i think there something really bad has been introduced. When stuck, the program has around 40 threads. I see two threads with this fraction of a stack dump:
# gstack 26558
Thread 1 (Thread 0xa8be6b40 (LWP 26558)):
#0  0xb7795bc8 in __kernel_vsyscall ()
#1  0xb73d2392 in __lll_lock_wait_private () from /lib/libc.so.6
#2  0xb733d723 in ptmalloc_lock_all () from /lib/libc.so.6
#3  0xb7384eef in fork () from /lib/libc.so.6
# gstack 25500
Thread 1 (Thread 0xb67e3b40 (LWP 25500)):
#0  0xb7795bc8 in __kernel_vsyscall ()
#1  0xb73d2392 in __lll_lock_wait_private () from /lib/libc.so.6
#2  0xb733d6f3 in ptmalloc_lock_all () from /lib/libc.so.6
#3  0xb7384eef in fork () from /lib/libc.so.6
and ALL threads of the process are either in __lll_lock_wait or in __lll_lock_wait_private. I don't see any thread left holding the lock and doing something else.
This cannot be sane. Frankly i don't know if this is exactly the same thing like reported in this bug. However, one more time (i don't count it anymore how often) over the years i update RPMs and something in my programs (in this case emu used in the openvenus monitoring) breaks and i have no idea how long i have to wait until it is fixed again. Worse, here i have no instant idea how to workaround.

(In reply to Albert Flügel from comment #13)
> I think i ran into the same or a similar problem with a program of mine,
> that was working until and including Fedora-22. Now, on Fedora-23 it gets
> stuck after some fractions of a second. It is a service, that accepts TCP
> connections in threads, then depending on the request it may fork and run
> another program.
> On Redhat 5 and 6 it is working since years and now is being broken by some
> change. On my Fedora 23 the glibc and pthread is from the package
> glibc-2.22-6.fc23.i686 . The machine is a Pentium single processor, even
> there it happens, so i think there something really bad has been introduced.
> When stuck, the program has around 40 threads. I see two threads with this

This deadlock and others exist in rhel5, rhel6, and likely rhel7. To some extent we can fix this in rhel6, and rhel7. However, rhel5 is out of scope given the production phase 3 for the release.

We will look into these changes for rhel-7.3 to see what we can do.

Rough test case posted upstream.

Patch posted upstream for review:

https://sourceware.org/ml/libc-alpha/2016-02/msg00267.html

Upstream commit:

commit 29d794863cd6e03115d3670707cc873a9965ba92
Author: Florian Weimer <fweimer>
Date:   Thu Apr 14 09:17:02 2016 +0200

    malloc: Run fork handler as late as possible [BZ #19431]

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2017:1916