Fedora Account System
Red Hat Associate
Red Hat Customer
Description of problem: Trying to build erlang on rawhide will hang during erlc invocation, preventing the build from completing, but only on s390x. For example: https://koji.fedoraproject.org/koji/taskinfo?taskID=38804985 Ran for nearly a day before cancelled. See also: https://pagure.io/releng/issue/8711 and https://lists.fedoraproject.org/archives/list/devel@lists.fedoraproject.org/thread/KEVZTKSHMJJR6EVTRS4ZNC27SPX4Q4DU/ I am going to attempt to track this down here.
I've tried to use mock on RHEL8 to build for rawhide, and I cannot reproduce the problem there. However I can reproduce the problem with mock on F29.
Here's kernel stack traces for all threads on a stuck erlc: 44611 [<0>] do_select+0x4d0/0x710 [<0>] core_sys_select+0x202/0x518 [<0>] kern_select+0x11c/0x160 [<0>] __s390x_sys_select+0x26/0x38 [<0>] system_call+0x290/0x2b0 44612 [<0>] pipe_read+0x232/0x318 [<0>] new_sync_read+0x1ac/0x1e8 [<0>] vfs_read+0x84/0x140 [<0>] ksys_read+0x62/0xe8 [<0>] system_call+0x290/0x2b0 44613 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44615 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44616 [<0>] do_epoll_wait+0xb0/0xc8 [<0>] __s390x_sys_epoll_wait+0x2e/0x40 [<0>] system_call+0x290/0x2b0 44617 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44618 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44619 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44620 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44621 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44622 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44623 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44624 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44625 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44626 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44627 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44628 [<0>] futex_wait+0x158/0x250 [<0>] do_futex+0x76/0xcd0 [<0>] __s390x_sys_futex+0xe0/0x168 [<0>] system_call+0x290/0x2b0 44629 [<0>] do_sys_poll+0x4a0/0x560 [<0>] __s390x_sys_ppoll+0x8c/0xc8 [<0>] system_call+0x290/0x2b0 44630 [<0>] do_epoll_wait+0xb0/0xc8 [<0>] __s390x_sys_epoll_wait+0x2e/0x40 [<0>] system_call+0x290/0x2b0 If I use strace to attach to the main process with -f and thus attach to all children, the process immediately becomes unstuck. For the above example, I attached strace one at a time to each thread individually until I found which thread caused the entire process to unwedge itself, and it was this one: # strace -p 44616 strace: Process 44616 attached timerfd_settime(11, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}, NULL) = 0 munmap(0x3ff4f380000, 524288) = 0 futex(0x3ff513402d0, FUTEX_WAKE_PRIVATE, 1) = 1 fcntl(2, F_GETFL) = 0x401 (flags O_WRONLY|O_APPEND) fcntl(2, F_SETFL, O_WRONLY|O_APPEND) = 0 write(10, "!", 1) = 1 fcntl(1, F_GETFL) = 0x401 (flags O_WRONLY|O_APPEND) fcntl(1, F_SETFL, O_WRONLY|O_APPEND) = 0 fcntl(0, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE) fcntl(0, F_SETFL, O_RDONLY|O_LARGEFILE) = 0 exit_group(0) = ? +++ exited with 0 +++ So it appears that interrupting the epoll_wait call is sufficient for the task to complete.
I can reproduce without mock, just trying to build otp from git at OTP-22.1.5 on f29.
Initial kernel testing: On RHEL8 host: RHEL8 kernel 4.18.0-147.el8.s390x does not reproduce the problem On F29 host: F29 kernel 5.3.6-100.fc29.s390x reproduces the problem Upstream 5.3.6 reproduces the problem Upstream 4.18 does not reproduce the problem I am going to check the latest 5.4-rc6 next and assuming it fails the same as 5.3.6, I'll start bisecting from 4.18 to 5.3.6.
5.4-rc6 reproduces the problem
I've bisected this down to here: $ git log --summary --oneline HEAD~1..refs/bisect/bad abc610e01c66 (refs/bisect/bad) fs/epoll: avoid barrier after an epoll_wait(2) timeout c5a282e9635e (refs/bisect/skip-c5a282e9635e9c7382821565083db5d260085e3e) fs/epoll: reduce the scope of wq lock in epoll_wait() 21877e1a5b52 (HEAD, refs/bisect/good-21877e1a5b520132f54515f8835c963056418b4c) fs/epoll: robustify ep->mtx held checks c5a282e9635e does not boot. So either c5a282e9635e or abc610e01c66 seems to be a regression.
John, first, great job, and second, what hw did you use for debugging / bisecting the kernel?
(In reply to Dan Horák from comment #7) > John, first, great job, and second, what hw did you use for debugging / > bisecting the kernel? I've used several different lab machines, the one I am currently using is: IBM 2964 - N63 But I've been using whatever the lab scheduler gives me. At one point I was also using: IBM 2827 - H20 and it behaved the same.
Another quick note, I tested 5.4-rc7 yesterday and it still reproduces the problem.
OK, so it's both zEC12 and z13. I wasn't able to reproduce the crash earlier, but I'm going to let IBM know about this problem now.
(In reply to Dan Horák from comment #10) > OK, so it's both zEC12 and z13. I wasn't able to reproduce the crash > earlier, but I'm going to let IBM know about this problem now. Let me double check that the 2827-H20 behaved the same. I'm not 100% positive and would hate to waste time relying on bad information.
(In reply to John Eckersberg from comment #11) > (In reply to Dan Horák from comment #10) > > OK, so it's both zEC12 and z13. I wasn't able to reproduce the crash > > earlier, but I'm going to let IBM know about this problem now. > > Let me double check that the 2827-H20 behaved the same. I'm not 100% > positive and would hate to waste time relying on bad information. Confirmed, on a newly provisioned IBM 2827 - H20 system: 21877e1a5b52 works correctly abc610e01c66 hangs
------- Comment From h.carstens.com 2019-11-13 03:37 EDT------- Could you report this upstream to Davidlohr Bueso, please? This doesn't look like an architecture specific bug at all. Thank you for taking the time to bisect this!
Sure, I'll write up some more details and send it to upstream. Agreed, it doesn't look like an architecture-specific bug, at least examining the patch(es) that it bisects down to. However I see this issue *only* on s390x, which leads me to think maybe the patches in question are interacting with some other arch-specific code somewhere that could have a bug. It's also possible the erlang VM is doing something silly and the fact that it ever worked before was dumb luck. We'll see, thanks for taking a look!
Something I somehow forgot to test until now, and is very interesting... On a fresh F29 system, with: [root@ibm-z-37 ~]# rpm -q erlang-erts erlang-erts-20.3.8.22-1.fc29.s390x [root@ibm-z-37 ~]# uname -r 5.3.11-100.fc29.s390x I can't reproduce the problem anymore. So it seems that older erlang doesn't reproduce the problem even with a newer kernel. I'll see if I can bisect down changes in the erlang VM, hopefully narrow down what is going on here. Ideally I'll narrow it down to a very simple reproducer in userspace to trigger the behavior in the kernel.
Bisected down to this rather large and invasive patch in otp: commit c6498571109b524fb319300e1b177b942e556f1b (HEAD, refs/bisect/bad) Author: Lukas Larsson <lukas> Date: Fri Oct 12 18:16:17 2018 +0200 erts: Move fds with active true behaviour to own pollset At start of the VM a poll-set that the schedulers will check is created where fds that have triggered many (at the moment, many means 10) times without being deselected inbetween. In this scheduler specific poll-set fds do not use ONESHOT, which means that the number of syscalls goes down dramatically for such fds. This pollset is introduced in order to handle fds that are used by the erlang distribution and that never change their state from {active, true}. This pollset only handles ready_input events, ready_output is still handled by the poll threads. During overload, polling the scheduler poll-set is done on a 10ms timer. erts/emulator/beam/erl_port.h | 2 + erts/emulator/beam/erl_port_task.c | 81 ++++++++++++++++++++++++++++++---- erts/emulator/beam/erl_port_task.h | 21 ++++++++- erts/emulator/beam/erl_process.c | 122 ++++++++++++++++++++++++++++++++++++++++++++++---- erts/emulator/beam/erl_process.h | 4 +- erts/emulator/sys/common/erl_check_io.c | 310 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++------------------------------------- erts/emulator/sys/common/erl_check_io.h | 16 +------ erts/emulator/sys/common/erl_poll.c | 504 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++---------------------------------------------------- erts/emulator/sys/common/erl_poll.h | 14 +++++- erts/emulator/sys/common/erl_poll_api.h | 4 +- erts/emulator/sys/win32/erl_poll.c | 5 ++- erts/emulator/test/scheduler_SUITE.erl | 27 +++++++----- erts/emulator/test/signal_SUITE.erl | 2 +- 13 files changed, 843 insertions(+), 269 deletions(-)
I've re-enabled s390x in rawhide and built erlang-22.1.8-1.fc32: https://koji.fedoraproject.org/koji/buildinfo?buildID=1415713 On s390x only, we invoke configure with --disable-kernel-poll, which works around the issue. See: https://src.fedoraproject.org/rpms/erlang/c/d286cacc6587d5d47eb7f6a7afe3178abba1d8e2?branch=master
Thanks for your great work once more, John. What do you suggest as the next step? Keep the workaround in the specfile? Let someone look at the s390x kernel? Review the erlang change from comment 16? One thing that's specific to s390x is that everything is virtualized to some degree, so it wouldn't be the first case where an app couldn't cope with highly loaded VMs/LPARs due some bug.
(In reply to Dan Horák from comment #18) > Thanks for your great work once more, John. What do you suggest as the next > step? Keep the workaround in the specfile? Let someone look at the s390x > kernel? Review the erlang change from comment 16? > > One thing that's specific to s390x is that everything is virtualized to some > degree, so it wouldn't be the first case where an app couldn't cope with > highly loaded VMs/LPARs due some bug. We can keep the workaround as long as we need to. In theory it's only a small performance loss. Until we can pin down the root cause I don't have any better ideas. I still owe an email to kernel upstream as I promised in comment #14. While I was trying to summarize my findings for that I started finding other threads to run down (like the erlang patch set). I suspect this is ultimately a kernel bug. The erlang change just happens to be where it began using the epoll interface. The kernel bisect came down to a change in the epoll interface as well. So the erlang bisect result is not really surprising in that context. It's got to be a race somewhere, because it stops reproducing if I run the reproducer under strace or if I add additional debug output to the erlang VM. I *can* however still reproduce it when tracing with perf. I'll detail this more in my summary to come. The biggest mystery to me is why this only happens on s390x, given the kernel epoll change is not arch-specific at all as far as I can tell. But I'll defer to upstream there because I am well out of my comfort zone at that point.
Hi! I added some ExcludeArch's to some of my Erlang packages so I could build them on Rawhide and F31 (they had been FTBFS previously, for other reasons). Now that we have this workaround, do you recommend I remove those and rebuild?
(In reply to Randy Barlow from comment #20) > Hi! > > I added some ExcludeArch's to some of my Erlang packages so I could build > them on Rawhide and F31 (they had been FTBFS previously, for other reasons). > Now that we have this workaround, do you recommend I remove those and > rebuild? Yep, they should work fine now. Let me know if you come across any issues building them.
Reassigning to myself for review.
This report has not received an update in over 90 days. If this issue is still relevant to you, please do not hesitate to update this report with any relevant details on recent investigative steps or changes and we will absolutely work to understand how to best move forward. Otherwise, this bug report will need to be closed in 30 days. No worries, however; should you need still assistance after the report is closed, please do not hesitate to create a new bug report referencing this report and with any new details on the matter. NOTE: This is an automated mass update.
Revisiting this after seven years. The downstream workaround is still in place — erlang.spec as of 27.3.4.17 still carries: # Kernel poll is buggy on s390x for unknown reasons, disable it # See rhbz#1770256 %ifarch s390x %define __without_kernel_poll 1 %endif Looking at what happened upstream to the commits identified in comment #6, all three have since had fixes land. Most directly, commit 289caf5d8f6c ("epoll: check for events when removing a timed out thread from the wait queue", Soheil Hassas Yeganeh, December 2020) carries: Fixes: abc610e01c66 ("fs/epoll: avoid barrier after an epoll_wait(2) timeout") which is exactly the commit the bisect in comment #6 landed on. Its description matches the symptom reported here: After abc610e01c66 ... we break out of the ep_poll loop upon timeout, without checking whether there is any new events available. Prior to that patch-series we always called ep_events_available() after exiting the loop. This can cause races and missed wakeups. [...] Thread 3 can be blocked indefinitely. An indefinite block that clears when the epoll_wait is interrupted is what comment #2 describes. That fix went to stable, so it is present in any kernel from roughly 5.11 onwards. Two others in the same area: - 65759097d804 ("epoll: call final ep_events_available() check under the lock", May 2020) — another missed-wakeup race where ep_events_available() observes empty lists and sleeps. - d679ae94fdd5 ("list: fix a data-race around ep->rdllist", April 2022) — carries Fixes: c5a282e9635e, the other commit in the bisect range from comment #6. I would like to test removing the workaround. The original failure reproduced during erlc inside the build itself, so a successful s390x scratch build without --disable-kernel-poll would be reasonable evidence, and costs nothing if it hangs. Two caveats. This is a plausible match rather than proof: nobody has confirmed that erlc's particular hang was this specific race. And the area is still receiving fixes — a June 2026 eventpoll series includes "Fix epoll_wait() report false negative", another unlocked ep_events_available() race — so it may well have been more than one bug. Will report back with scratch build results.
Confirmed fixed. I removed the --disable-kernel-poll workaround and built erlang-27.3.4.17-2.fc46 for rawhide. s390x built successfully, so erlc now runs with kernel poll enabled for the first time since 2019. To summarise the resolution for anyone finding this later: The bisect in comment #6 identified abc610e01c66 ("fs/epoll: avoid barrier after an epoll_wait(2) timeout"). That commit was fixed upstream by 289caf5d8f6c ("epoll: check for events when removing a timed out thread from the wait queue", December 2020), which carries an explicit Fixes: tag for it and describes exactly the symptom reported here — a thread blocked indefinitely because ep_events_available() was no longer checked after the loop exits on timeout. That fix went to stable, so it has been in Fedora kernels since roughly 5.11. Two related fixes also landed in the same area: 65759097d804 ("epoll: call final ep_events_available() check under the lock", May 2020) and d679ae94fdd5 ("list: fix a data-race around ep->rdllist", April 2022), the latter carrying Fixes: c5a282e9635e, the other commit in the bisect range. Closing as CURRENTRELEASE — the kernel currently shipped contains the fix, and the downstream workaround is no longer needed. Thanks to John Eckersberg for the original bisection work, which is what made this identifiable at all; without the specific commit to search for, matching the upstream fix to this report would not have been possible.