SIGQUIT only reports backtrace for one capability
SIGQUIT is intended to mirror the same signal's functionality provided by the JVM. That is, provide a snapshot of a processes' state in the form of backtraces on stderr. However, GHC's implementation currently only prints a backtrace for a single, arbitrary thread (namely that running via on the main capability). This should be fixed.
Activity
changed milestone to %8.8.1
added RTS Tbug Trac import labels
There is the question of what the precise semantics of SIGQUIT should be. Should we dump the state of all threads, all schedulable threads, or only currently scheduled threads? My feeling is the latter.
This isn't entirely trivial to implement, especially given that we need to ensure that the output is readable (e.g. prevent interleaving of output from different capabilities). One option would be to add a new Message variety which can be used to request a backtrace from a capability. The thread handling the SIGQUIT could then send this message to each capability and wait for their replies and print the result. This sounds complex for a debugging feature, however.
-
changed milestone to %8.10.1
added Pnormal label
mentioned in issue #17451
It will help my situation (trouble-shooting 100% ~ 400% CPU hogging) a lot more to just print the stack trace on busy capabilities.
But I have no experience with libdw, do you think it feasible to snapshot all busy thread's frames from the signal handling thread? I intend to work on such a tiny improvement if that's possible.
I see https://gitlab.haskell.org/ghc/ghc/-/blob/master/rts/Libdw.c#L274-276
static pid_t next_thread(Dwfl *dwfl, void *arg, void **thread_argp) { /* there is only the current thread */ if (*thread_argp != NULL) return 0; *thread_argp = arg; return dwfl_pid(dwfl); }Maybe iteration of more threads can be done here? But seems our code is responsible to figure out the list of TIDs, I have no clue on how to obtain the list of busy threads at the moment, some insights please?
Edited by Compl YueLooked into libdwfl, seems like we can iterate threads via dwfl_getthreads and obtain frames via dwfl_thread_getframes, then print like currently done.
I'm wondering whether need to check a thread be serving as a capability, or that just doesn't matter, if needed, how to?
I'll tinkering with it and report back later.
I'v got limited success by propagating SIGQUIT to all threads of capabilities, with some patch (against 8.10.3 src-dist) like this:
diff --git a/rts/Libdw.c b/rts/Libdw.c --- a/rts/Libdw.c +++ b/rts/Libdw.c Backtrace *libdwGetBacktrace(LibdwSession *session) { if (session->cur_bt != NULL) { sysErrorBelch("Already collecting backtrace. Uh oh."); return NULL; } Backtrace *bt = backtraceAlloc(); session->cur_bt = bt; session->max_depth = max_backtrace_depth; - int pid = getpid(); - int ret = dwfl_getthread_frames(session->dwfl, pid, + pid_t curr_tid = pthread_self(); + int ret = dwfl_getthread_frames(session->dwfl, curr_tid, getBacktraceFrameCb, session); if (ret == -1) sysErrorBelch("Failed to get stack frames of current process: %s", dwfl_errmsg(dwfl_errno())); session->cur_bt = NULL; return bt; } static pid_t next_thread(Dwfl *dwfl, void *arg, void **thread_argp) { - /* there is only the current thread */ - if (*thread_argp != NULL) + /* always return current thread only */ + pid_t *last_tid = thread_argp; + pid_t curr_tid = pthread_self(); + if( curr_tid == *last_tid) { return 0; - - *thread_argp = arg; - return dwfl_pid(dwfl); + } + *last_tid = curr_tid; + return *last_tid; }diff --git a/rts/posix/Signals.c b/rts/posix/Signals.c --- a/rts/posix/Signals.c +++ b/rts/posix/Signals.c /* ----------------------------------------------------------------------------- * SIGQUIT handler. * * We try to give the user an indication of what we are currently doing * in response to SIGQUIT. * -------------------------------------------------------------------------- */ static void backtrace_handler(int sig STG_UNUSED) { #if USE_LIBDW + +#if defined(THREADED_RTS) + /* propagate SIGQUIT to all threads running as a capability */ + static OSThreadId sigReceiverThId = 0; + + OSThreadId propagatorThId = ACQUIRE_LOAD(&sigReceiverThId); + OSThreadId currThId = osThreadId(); + if (propagatorThId == 0) { + propagatorThId = currThId; + RELEASE_STORE(&sigReceiverThId, propagatorThId); + } + if (currThId == propagatorThId) { + for (uint32_t i=0; i < n_capabilities; i++) { + Task *cap_task = ACQUIRE_LOAD(&capabilities[i]->running_task); + if (!cap_task) { continue; } + OSThreadId tid = ACQUIRE_LOAD(&cap_task->id); + if (tid != currThId) { + /* TODO need chg after USE_LIBDW doesn't imply pthread anymore */ + pthread_kill(tid, SIGQUIT); + } + } + } +#endif /* THREADED_RTS */ + LibdwSession *session = libdwInit(); Backtrace *bt = libdwGetBacktrace(session); fprintf(stderr, "\nCaught SIGQUIT; Backtrace:\n"); libdwPrintBacktrace(session, stderr, bt); backtraceFree(bt); libdwFree(session); #else fprintf(stderr, "This build does not support backtraces.\n"); #endif }I'm not sure the dump result can help pinpoint my bug with 2 fake busy loop concurrently running like this:
$ cabal run els Up to date >> Đ (Edh) Language Server << ℹ️ /home/m3c3/edh-universe/e-wrks/nedh/edh_modules/net/repl.edh:19:24 Đ (Edh) web REPL listening: ws://127.0.0.1:2723 ℹ️ /home/m3c3/edh-universe/e-wrks/nedh/edh_modules/net/repl.edh:42:20 Đ (Edh) web REPL listening: http://127.0.0.1:2716 ℹ️ /home/m3c3/edh_modules/els/__main__.edh:30:6 Đ (Edh) Language Server listening: Addr('127.0.0.1', 1709) ⚠️ /home/m3c3/edh_modules/els/__main__.edh:43:18 Failed reporting els port 1709 to fd 3 ^\ Caught SIGQUIT; Backtrace: 0x3f68e62 set_initial_registers (rts/Libdw.c:291.0) 0x7f6711a6fc58 dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.170.so) 0x7f6711a7013c dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.170.so) 0x3f6952d libdwGetBacktrace (rts/Libdw.c:260.0) 0x3f8b7df backtrace_handler (/usr/include/x86_64-linux-gnu/bits/stdio2.h:97.0) 0x7f67128c397f (null) (/lib/x86_64-linux-gnu/libpthread-2.27.so) 0x7f67128bead2 pthread_cond_wait@@GLIBC_2.3.2 (../sysdeps/unix/sysv/linux/futex-internal.h:88.0) 0x3f8af69 waitCondition (rts/posix/OSThreads.c:117.0) Caught SIGQUIT; Backtrace: 0x3f617cb yieldCapability (rts/Capability.c:708.0) 0x3f5e7b2 schedule (rts/Schedule.c:690.0) 0x3f68e62 set_initial_registers (rts/Libdw.c:291.0) 0x7f6711a6fc58 dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.170.so) 0x7f6711a7013c dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.170.so) 0x3f5fc3e scheduleWaitThread (rts/Schedule.c:2612.0) 0x3f6952d libdwGetBacktrace (rts/Libdw.c:260.0) 0x3f72e9e hs_main (rts/RtsMain.c:73.0) 0x3f8b7df backtrace_handler (/usr/include/x86_64-linux-gnu/bits/stdio2.h:97.0) 0x7f67128c397f (null) (/lib/x86_64-linux-gnu/libpthread-2.27.so) 0x415a08 (null) (/home/m3c3/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 0x7f6712260bf7 __libc_start_main (../csu/libc-start.c:344.0) 0x3f906aa stg_ap_0_fast (rts/Apply.cmm:79.9) 0x3f95958 stg_restore_cccs_info (rts/StgMiscClosures.cmm:51.1) 0x41203a _start (/home/m3c3/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 0x3f98df8 stg_ap_pp_info (rts/dist/build/AutoApply.cmm:958.1) 0x3f98df8 stg_ap_pp_info (rts/dist/build/AutoApply.cmm:958.1) 0x3f98df8 stg_ap_pp_info (rts/dist/build/AutoApply.cmm:958.1) 0x3f98df8 stg_ap_pp_info (rts/dist/build/AutoApply.cmm:958.1) 0x3f98df8 stg_ap_pp_info (rts/dist/build/AutoApply.cmm:958.1) ...I'm try reproduce my real situation and see what's dumped.
Meanwhile I appreciate it if you can review my patch, and see any potential problem or give directions.
Hi, this is cool! Could you post this as a merge request?
I don't have much insight on libdw, but a few comments:
- Your
sigRecieverThIdlogic looks racy. I would use acas(&sigRecieverThid, 0, currThId) - You don't set
sigRecieverThIdback to 0 when you're finished. I guess this mostly works, the same thread is always the propogator, but it would be more robust to set back to 0. - As bgamari mentions in the comments above, your output callstacks can be interleaved. One (disgusting) way to achieve this would be to build a linked list with
cass, then have the propogator busy-wait checking if the list is the right length, then writing the stacktraces and free the memory. I believe your posted callstacks actually are interleaved, e.g. theyieldCapabilityandscheduleentries at the top of the second stack belong to the first stack. - n_capabilities can increase. It would be safest to have
n_caps = RELAXED_LOAD(&n_capabilities)at the start and usen_caps, especially if you end up doing more logic with it.
Edited by Douglas Wilson- Your
@duog Thanks for your encouragement, I've further polished the code and opened !4786 (closed) , please continue review on it.
I gave up the propagator thread logic, as I figured out it won't work on other posix systems other than Linux, as the first receiver thread won't always be the sole receiver afterward, per posix signal delivery spec, any thread not blocking SIGQUIT can receive it from the os, and the solution to block SIGQUIT from all threads except one will not work, because when the propagated SIGQUIT is blocked, we can't be triggered to dump backtrace then.
Setting
sigRecieverThIdback to 0 is a solution hadn't come into my mind before I drafted the other solution in that MR, it might be a valid solution too, let's consider it along too.The output above is actually truncated from seemingly infinite looping spitting the last line, anyhow, I later find all sort of strange things (partial trace backs and even no trace back at all e.g.) if I don't
rm -rf ~/.cabal/store/ghc-8.10.3/andcabal cleanbeforecabal runagain, after GHC rebuilt with slight source modification. A freshcabal runwith cleared intermediate artifacts (update: not stably)printed much more sane output.RELAXED_LOAD(&n_capabilities)should definitely be incorporated, and also I readfprintf()is not safe to be used from a signal handler, so I'd put more thought on how to make it safer, that may even need a separate serializer thread I feel, I'll experiment some and update the MR for more discussion & review.Edited by Compl Yue@duog a second thought on setting
sigRecieverThIdback to 0, I think it is still racy for other threads to see it set or cleared, when another thread responding to a propagated SIGQUIT but seessigRecieverThIdbeing 0, it will wrongly decide to further propagate the signal, thus causing storms of echos, I don't think we can safely instruct the 0-clearing by propagator thread to happen-after all other threads seeing a non-zero value, as those seeings are in signal handler code, usual mutex-like sync seems dangerous. Or do we have such options?And I remembered that the original idea is to have it record the thread that ever received the very first SIGQUIT sent to the process, and given I wrongly assumed that subsequent SIGQUIT will be solely delivered to that very same thread later on (though that's true on Linux in usual cases), the expected protocol was
sigRecieverThIdget set once and remain unchanged since on. I later realized it won't work on other posix systems so abandoned the solution.I opened !4787 which rebased !4786 (closed) onto master FYI.
I later find all sort of strange things (partial trace backs and even no trace back at all e.g.) if I don't
rm -rf ~/.cabal/store/ghc-8.10.3/andcabal cleanYes, it can be tricky working on your own ghcs. cabal has a
--store-dirflag which you can use to point it a separate global store. If you are working with master branch then https://ghc.gitlab.haskell.org/head.hackage/ is a collection of patches to make various packages work.I read fprintf() is not safe to be used from a signal handler, Me too! I created #19205 for this. My understanding is that it's probably fine if you don't try to print floats. I don't think you should worry about this too much.
I see what you mean about the storm of echos. Unfortunately I don't think your timing solution solves this either. Processes can have arbitrarily long gaps between time slices; this can manifest on a system under heavy load, beeing oomkilled, waking from suspend, or if the process is SIGSTOPped.
usual mutex-like sync seems dangerous. Or do we have such options? We don't really have such options. We can busy-wait though.
while(SEQ_CST_LOAD(&still_going)) { busy_wait_nop(); }may even need a separate serializer thread This would likely be too high a cost to pay for a niche feature. However having an existing thread serialise the output may be a solution(bgamari elaborates in a comment above).
and the solution to block SIGQUIT from all threads except one will not work, because when the propagated SIGQUIT is blocked,
This is true, but there is nothing special about SIGQUIT here. We could use SIGQUIT for the leader, then it could send a SIG??? to follower threads. I don't know what a good choice is, and this would have to be documented.
I'm interested in how you intend to deal with interleaved output. I think a good first step is to print the threadId in each frame, so that we can easily see the interleaving. My inclination would be to have the leader busy-wait for each follower to finish, then do all the printing itself, which helps solve the "storm of echos" too.
Edited by Douglas WilsonI don't think your timing solution solves this either.
It's not perfect, but at least I think it will work in usual cases, and won't crash or flush in extreme situations, is there potential worst case failure unacceptable that I'm not aware of?
I'm interested in how you intend to deal with interleaved output.
I hesitate to add any form of wait to a signal handler, a more sophisticated solution in my mind might be something like Android's circular log buffer in the kernel, which can be consumed by its
logcatutility.Then here we still need a rival of
logcat, could that be an external process, or an in-process thread, to dump async payload to stderr.A full featured in-process circular log buffer is good to have IMHO, just how its cost justify given where we are, I'm glad to work on a basic version if we can agree on an implementation simple enough. Then maybe an RTS option controlled in-process thread, to keep dumping the payload to stderr.
Anyway, the unstable output as in !4787 is blocking my proceeding, it's meaningless before we can get stable meaningful stack traces from dwarf, I really need some hint to get over it first ...
I think a good first step is to print the threadId in each frame
Sure will do that.
maybe an RTS option controlled in-process thread, to keep dumping the payload to stderr.
On my mind now is something like a broadcast
TChanfor simplicity, instead of a real circular buffer consists of binary blocks to be filled with bytes; but C doesn't have garbage collector, so the desirable feature of a broadcastTChan, i.e. incoming items get simply discarded when no receiver attached, will not work right away, seems a dedicated thread is unavoidable, to at leastfreethe malloc'ed payload, if configured not to really dump to stderr.Or do you think we can just implement it using a real broadcast
TChan, then add Haskell api to dup & read-print-loop? (But I'm not sure how safe it is toatomicallywrite to aTChanfrom a signal handler).Edited by Compl Yue
mentioned in merge request !4786 (closed)
mentioned in merge request !4787
790 /* Return *PC (program counter) for thread-specific frame STATE. 791 Set *ISACTIVATION according to DWARF frame "activation" definition. 792 Typically you need to subtract 1 from *PC if *ACTIVATION is false to safely 793 find function of the caller. ACTIVATION may be NULL. PC must not be NULL. 794 Function returns false if it failed to find *PC. */ 795 bool dwfl_frame_pc (Dwfl_Frame *state, Dwarf_Addr *pc, bool *isactivation) 796 __nonnull_attribute__ (1, 2);Typically you need to subtract 1 from *PC if *ACTIVATION is false to safely ...
I understand it should imply
if (!is_activation) pc -= 1;but seems the contrary is done:https://gitlab.haskell.org/ghc/ghc/-/blob/master/rts/Libdw.c#L240-241
// Remember that we are traversing from the inner-most to the outer-most frame static int getBacktraceFrameCb(Dwfl_Frame *frame, void *arg) { LibdwSession *session = arg; Dwarf_Addr pc; bool is_activation; if (! dwfl_frame_pc(frame, &pc, &is_activation)) { // failed to find PC backtracePush(session->cur_bt, 0x0); } else { if (is_activation) pc -= 1; // TODO: is this right? backtracePush(session->cur_bt, (StgPtr) (uintptr_t) pc); } session->max_depth--; if (session->max_depth == 0) { return DWARF_CB_ABORT; } else { return DWARF_CB_OK; } }Is it a bug or my understanding should be corrected?
For the record I don't really understand whatever libdw's semantics about the ACTIVATION, just interpreted the sentence literally. And TBH I'm really confused by the
subtract 1thing, I'm no expert in that low level, but gut feeling tells me that function entry addresses should be aligned to 8-bytes or so, that1means 1 byte offset, then what's the hell?Edited by Compl YueYes it looks like a bug to me. in C adding(or subtracting) 1 from a pointer modifies the value by the size of the pointers type. It works the same as arrays ,so
(p + 1) == p[1]. Also(uint64_t)p + sizeof(*p) == (uint64_t)(p + 1).Having said that, all backtraces will have a
set_initial_registersframe at the top, so I'd be surprised if this bug is causing issues here.Yes, I can be sure it's a bug by referencing libdw's
print_frames(), but fixing it didn't change the symptom in apparent ways, then I found another quirk to workaround (!4787 (ddc679a5)) , so the back traces can be stably obtained now.
374 Dwarf_Addr pc = frames->frame[nr].pc; 375 bool isactivation = frames->frame[nr].isactivation; 376 Dwarf_Addr pc_adjusted = pc - (isactivation ? 0 : 1);So it should be a bug.
I think a good first step is to print the threadId in each frame
I did it and the result shows interleaving really a problem:
$ cabal run els Up to date >> Đ (Edh) Language Server << ^\ Caught SIGQUIT; Backtrace of thread 84903 : 84903 0x00000003f63fa7 set_initial_registers (rts/Libdw.c:301.5) 84903 0x007fb559c91bbf dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84903 0x007fb559c920d3 dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84903 0x00000003f646a3 libdwGetBacktrace (rts/Libdw.c:270.15) 84903 0x00000003f874c2 backtrace_handler (rts/posix/Signals.c:574.21) 84903 0x007fb55a0a53c0 __restore_rt (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so) 84903 0x007fb559e5e48b sigprocmask (../sysdeps/unix/sysv/linux/sigprocmask.c:39.10) 84903 0x00000003f78060 GarbageCollect (rts/sm/GC.c:267.5) 84903 0x00000003f67e03 scheduleDoGC (rts/Schedule.c:1849.5) 84903 0x00000003f68aa7 schedule (rts/Schedule.c:564.7) 84903 0x00000003f6a0a0 scheduleWorker (rts/Schedule.c:2623.11) 84903 0x00000003f6535c workerStart (rts/Task.c:446.5) 84903 0x007fb55a099608 start_thread (/build/glibc-ZN95T4/glibc-2.31/nptl/pthread_create.c:477.8) 84903 0x007fb559f3a292 __clone (../sysdeps/unix/sysv/linux/x86_64/clone.S:95.0) ℹ️ /home/cyue/edh-universe/e-wrks/nedh/edh_modules/net/repl.edh:19:24 Đ (Edh) web REPL listening: ws://127.0.0.1:2721 ℹ️ /home/cyue/edh-universe/e-wrks/nedh/edh_modules/net/repl.edh:42:20 Đ (Edh) web REPL listening: http://127.0.0.1:2714 ^\ Caught SIGQUIT; Backtrace of thread 84899 : 84899 0x00000003f63fa7 set_initial_registers (rts/Libdw.c:301.5) 84899 0x007fb559c91bbf dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84899 0x007fb559c920d3 dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84899 0x00000003f646a3 libdwGetBacktrace (rts/Libdw.c:270.15) 84899 0x00000003f874c2 backtrace_handler (rts/posix/Signals.c:574.21) 84899 0x007fb55a0a53c0 __restore_rt (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so) 84899 0x007fb55a0a0376 pthread_cond_wait@@GLIBC_2.3.2 (../sysdeps/nptl/futex-internal.h:183.13) 84899 0x00000003f86c0c waitCondition (rts/posix/OSThreads.c:117.11) els: Failed to get stack frames of current process: no matching address range: Success Caught SIGQUIT; Backtrace of thread 84903 : 84899 0x00000003f5c0ca yieldCapability (rts/Capability.c:708.28) 84903 0x00000003f63fa7 set_initial_registers (rts/Libdw.c:301.5) 84903 0x007fb559c91bbf dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84903 0x007fb559c920d3 dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84899 0x00000003f68ac1 schedule (rts/Schedule.c:687.25) 84903 0x00000003f646a3 libdwGetBacktrace (rts/Libdw.c:270.15) 84899 0x00000003f6a061 scheduleWaitThread (rts/Schedule.c:2606.11) 84899 0x00000003f6d182 hs_main (rts/RtsMain.c:72.9) 84899 0x00000000415f1f main (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f874c2 backtrace_handler (rts/posix/Signals.c:574.21) 84903 0x007fb55a0a53c0 __restore_rt (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so) 84899 0x007fb559e3f0b2 __libc_start_main (../csu/libc-start.c:308.16) 84903 0x00000003c32cf0 base_GHCziNum_zdfNumIntzuzdcfromInteger_info (libraries/base/GHC/Num.hs:101.5) 84899 0x0000000041254d _start (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/debug.edh:20:24-20:28 Đ semantics: possible misspelled member reference ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/debug.edh:31:36-31:40 Đ semantics: possible misspelled member reference ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/debug.edh:38:29-38:33 Đ semantics: possible misspelled member reference ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/debug.edh:56:22-56:26 Đ semantics: possible misspelled member reference ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/debug.edh:74:22-74:26 Đ semantics: possible misspelled member reference ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/debug.edh:96:37-96:41 Đ semantics: possible misspelled member reference ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/debug.edh:99:47-99:54 Đ semantics: possible misspelled member reference ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/concur.edh:35:23-35:26 Đ semantics: possible misspelled member reference ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/ho.edh:16:12-16:16 Đ semantics: possible misspelled member reference ⚠️ /home/cyue/edh-universe/e-wrks/edh/edh_modules/batteries/root/ho.edh:27:19-27:22 Đ semantics: dynamic attribute reference ℹ️ /home/cyue/edh_modules/els/__main__.edh:25:6 Đ (Edh) Language Server listening: Addr('127.0.0.1', 1707) ⚠️ /home/cyue/edh_modules/els/__main__.edh:38:18 Failed reporting els port 1707 to fd 3 ^\ Caught SIGQUIT; Backtrace of thread 84899 : 84899 0x00000003f63fa7 set_initial_registers (rts/Libdw.c:301.5) 84899 0x007fb559c91bbf dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84899 0x007fb559c920d3 dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84899 0x00000003f646a3 libdwGetBacktrace (rts/Libdw.c:270.15) 84899 0x00000003f874c2 backtrace_handler (rts/posix/Signals.c:574.21) 84899 0x007fb55a0a53c0 __restore_rt (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so) 84899 0x007fb55a0a0376 pthread_cond_wait@@GLIBC_2.3.2 (../sysdeps/nptl/futex-internal.h:183.13) els: Failed to get stack frames of current process: no matching address range: Success Caught SIGQUIT; Backtrace of thread 84903 : 84899 0x00000003f86c0c waitCondition (rts/posix/OSThreads.c:117.11) 84899 0x00000003f5c0ca yieldCapability (rts/Capability.c:708.28) 84903 0x00000003f63fa7 set_initial_registers (rts/Libdw.c:301.5) 84903 0x007fb559c91bbf dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84903 0x007fb559c920d3 dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84903 0x00000003f646a3 libdwGetBacktrace (rts/Libdw.c:270.15) 84899 0x00000003f68ac1 schedule (rts/Schedule.c:687.25) 84899 0x00000003f6a061 scheduleWaitThread (rts/Schedule.c:2606.11) 84903 0x00000003f874c2 backtrace_handler (rts/posix/Signals.c:574.21) 84903 0x007fb55a0a53c0 __restore_rt (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so) 84899 0x00000003f6d182 hs_main (rts/RtsMain.c:72.9) 84899 0x00000000415f1f main (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84899 0x007fb559e3f0b2 __libc_start_main (../csu/libc-start.c:308.16) 84899 0x0000000041254d _start (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f79d97 dirty_TVAR (rts/sm/Storage.c:1227.8) 84903 0x00000003f6fe2a stmCommitTransaction (rts/STM.c:316.3) 84903 0x00000003f8fb21 stg_atomically_frame_info (rts/PrimOps.cmm:1207.1) 84903 0x00000003f8faf7 (null) (rts/PrimOps.cmm:1171.1) 84903 0x000000039db40f base_GHCziBase_zdfMonadIO1_info (libraries/base/GHC/Base.hs:1530.1) ^\ Caught SIGQUIT; Backtrace of thread 84899 : 84899 0x00000003f63fa7 set_initial_registers (rts/Libdw.c:301.5) 84899 0x007fb559c91bbf dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84899 0x007fb559c920d3 dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84899 0x00000003f646a3 libdwGetBacktrace (rts/Libdw.c:270.15) 84899 0x00000003f874c2 backtrace_handler (rts/posix/Signals.c:574.21) 84899 0x007fb55a0a53c0 __restore_rt (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so) 84899 0x007fb55a0a0376 pthread_cond_wait@@GLIBC_2.3.2 (../sysdeps/nptl/futex-internal.h:183.13) 84899 0x00000003f86c0c waitCondition (rts/posix/OSThreads.c:117.11) els: Failed to get stack frames of current process: no matching address range: Success Caught SIGQUIT; Backtrace of thread 84903 : 84899 0x00000003f5c0ca yieldCapability (rts/Capability.c:708.28) 84903 0x00000003f63fa7 set_initial_registers (rts/Libdw.c:301.5) 84903 0x007fb559c91bbf dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84903 0x007fb559c920d3 dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84903 0x00000003f646a3 libdwGetBacktrace (rts/Libdw.c:270.15) 84899 0x00000003f68ac1 schedule (rts/Schedule.c:687.25) 84899 0x00000003f6a061 scheduleWaitThread (rts/Schedule.c:2606.11) 84903 0x00000003f874c2 backtrace_handler (rts/posix/Signals.c:574.21) 84903 0x007fb55a0a53c0 __restore_rt (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so) 84899 0x00000003f6d182 hs_main (rts/RtsMain.c:72.9) 84899 0x00000000415f1f main (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x0000000382cc78 base_DataziFoldable_null_info (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84899 0x007fb559e3f0b2 __libc_start_main (../csu/libc-start.c:308.16) 84899 0x0000000041254d _start (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) ^\ Caught SIGQUIT; Backtrace of thread 84899 : 84899 0x00000003f63fa7 set_initial_registers (rts/Libdw.c:301.5) 84899 0x007fb559c91bbf dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84899 0x007fb559c920d3 dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84899 0x00000003f646a3 libdwGetBacktrace (rts/Libdw.c:270.15) 84899 0x00000003f874c2 backtrace_handler (rts/posix/Signals.c:574.21) 84899 0x007fb55a0a53c0 __restore_rt (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so) 84899 0x007fb55a0a0376 pthread_cond_wait@@GLIBC_2.3.2 (../sysdeps/nptl/futex-internal.h:183.13) 84899 0x00000003f86c0c waitCondition (rts/posix/OSThreads.c:117.11) Caught SIGQUIT; Backtrace of thread 84903 : 84899 0x00000003f5c0ca yieldCapability (rts/Capability.c:708.28) 84903 0x00000003f63fa7 set_initial_registers (rts/Libdw.c:301.5) 84903 0x007fb559c91bbf dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84903 0x007fb559c920d3 dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.176.so) 84903 0x00000003f646a3 libdwGetBacktrace (rts/Libdw.c:270.15) 84899 0x00000003f68ac1 schedule (rts/Schedule.c:687.25) 84899 0x00000003f6a061 scheduleWaitThread (rts/Schedule.c:2606.11) 84899 0x00000003f6d182 hs_main (rts/RtsMain.c:72.9) 84903 0x00000003f874c2 backtrace_handler (rts/posix/Signals.c:574.21) 84903 0x007fb55a0a53c0 __restore_rt (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so) 84899 0x00000000415f1f main (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84899 0x007fb559e3f0b2 __libc_start_main (../csu/libc-start.c:308.16) 84903 0x00000003f883c4 stg_upd_frame_info (rts/Updates.cmm:31.1) 84899 0x0000000041254d _start (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f916df (null) (rts/StgMiscClosures.cmm:51.1) 84903 0x00000003f883bf (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f916a7 (null) (rts/StgMiscClosures.cmm:28.1) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) 84903 0x00000003f92a77 (null) (/home/cyue/edh-universe/dist-newstyle/build/x86_64-linux/ghc-8.10.3/els-0.1.0.0/x/els/noopt/build/els/els) ... repeating forever ...Out of curiosity, quoting https://www.linuxjournal.com/article/2121
So a common way of handling asynchronous signals in a multi-threaded program is to mask signals in all the threads, and then create a separate thread (or threads) whose sole purpose is to catch signals and handle them. The signal-handler thread catches signals by calling the function sigwait() with details of the signals it wishes to wait for.
How possible for GHC RTS to adopt this fashion?
@bgamari I looked at how JVM has implemented it, turns out they do use a dedicated signal handling thread in the fashion described in the above article.
The mentioned "Signal Dispatcher" thread is created here:
// Setup JavaThread for processing signals const char thread_name[] = "Signal Dispatcher"; ... JavaThread* signal_thread = new JavaThread(&signal_thread_entry); ...The dump of all Java threads' backtrace, happens in this thread here:
case SIGBREAK: { #if INCLUDE_SERVICES ... #endif // Print stack traces // Any SIGBREAK operations added here should make sure to flush // the output stream (e.g. tty->flush()) after output. See 4803766. // Each module also prints an extra carriage return after its output. VM_PrintThreads op; VMThread::execute(&op); ...Actual dumping work done for
VM_PrintThreadsoperation is here:// Threads::print_on() is called at safepoint by VM_PrintThreads operation. void Threads::print_on(outputStream* st, bool print_stacks, bool internal_format, bool print_concurrent_locks, bool print_extended_info) { ... ALL_JAVA_THREADS(p) { ResourceMark rm; p->print_on(st, print_extended_info); if (print_stacks) { if (internal_format) { p->trace_stack(); } else { p->print_stack_on(st); } } st->cr(); #if INCLUDE_SERVICES ... #endif // INCLUDE_SERVICES } ...I kinda believe by
safepoint, they mean the world is stopped with all Java threads pending, so all threads' stack can be observed and dumped. Nevertheless when the outputStream pends flow due to back pressure, I believe they are letting the whole world to wait.Do we have a counterpart concept/mechanism in GHC/RTS as of
safepointin JVM?If we can afford a dedicated thread to receive and handle/dispatch signals, that thread will be the perfect location to do the log dumping work safely wrt back pressure from stderr, in responding to SIGQUIT. Just what the JVM be doing all the years.
Btw they alias SIGQUIT to SIGBREAK like this:
// SIGBREAK is sent by the keyboard to query the VM state #ifndef SIGBREAK #define SIGBREAK SIGQUIT #endif-
Sorry for taking so long to get back to this.
Do we have a counterpart concept/mechanism in GHC/RTS as of
safepointin JVM?We do. GHC "capabilities" (which can be thought of as OS threads running Haskell code) can be interrupted by starting a "sync" event. This is, for instance, how garbage collection is initiated.
I think the best model to follow here is that of the non-moving GC's remembered set flush. Specifically, the non-moving collector triggers all capabilities to synchronize with the GC by way of a flush. The relevant moving parts are:
-
nonmovingBeginFlush, which callsstopAllCapabilitiesWith(..., SYNC_FLUSH_UPD_REM_SET) -
stopAllCapabilitiessets theinterruptflag for each capability - When a capability hits a yield point it will see that the
interruptflag is set and enter the scheduler, which will eventually enteryieldCapability -
yieldCapabilitylooks at the sync type and does the appropriate thing. - execution continues
To implement backtracing I would simply introduce a new sync type which prints a backtrace. This should be relatively simple. However, it does mean that threads that are stuck in non-allocating loops (which won't encounter a safepoint) won't produce backtraces. Nevertheless, I think this is acceptable; in such a case the user can just whip out
gdb. -
This is promising. Back when I was tinkering with the codebase, I saw capability sync very appealing for useful things to be done with it, but as it seems "hard-coded" and connected to many things I can't understand by far, I was frightened off to play with it.
That said I'm still worried about what backtraces to be printed out, as my case has shown, costcenter stacks appear way more useful, i.e. backtraces hitting scheduling code or GC code reveals nothing about misbehaving of the application code, such hits, even with a handful of stack frames (program-counter addresses) based on hardware call convention, will be of little information but majorly noise wrt the diagnostic practice.
It appears not as effective as expected, to simply print out the dwarf unwound stack frames, as show in this log file:
I reproduced my situation with 2 threads hogging the CPU, but the most seemingly useful hot spots as captured will stop at functions like
textzm1zi2zi4zi1_DataziText_length_info (libraries/text/src/Data/Text.hs:630.1)(null) (Text/Megaparsec/Internal.hs:317.33)megaparseczm9zi0zi1zmf1fe707daa2bef8db9d3ff7f9f72aee8df8d35fd20edcae7fcf9b53d5659e4b5_TextziMegaparsecziInternal_zdfFunctorParsecT1_info (Text/Megaparsec/Internal.hs:159.3), I'm not sure that's the effect of TCO (tail call optimization)?Rest captures caught scheduling, GC, profiling spots as shown in the attached log.
Please help to see if anything wrong with such result, and then maybe we should resort to Haskell stack frames instead of the hardware call-convention based stack?
ping @bgamari
@duog I think I did it:
$ cat cabal.project.local profiling: True profiling-detail: all-functions optimization: 0 package * debug-info: 2 $ $ cat cabal.project -- Please change Cabal project settings per your needs -- FOLLOWING CONTENTS GONNA BE OVERWRITTEN BY EPM -- -- * this file should be: -- /home/cyue/edh-universe/cabal.project packages: ./e-wrks/els/host.hs/els.cabal ./e-wrks/haskit/host.hs/haskit.cabal ./e-wrks/sedh/host.hs/sedh.cabal ./e-wrks/hasdim/host.hs/hasdim.cabal ./e-wrks/edh/lossless-decimal/lossless-decimal.cabal ./e-wrks/edh/host.hs/edh.cabal ./e-wrks/edh/elr/elr.cabal ./e-wrks/nedh/host.hs/nedh.cabal $
I looked deeper into the code, and got this idea to instead print backtrace of
CostCentreStackwith sth likefprintCCS_stderr()from each thread:-
Have a global counter, increased per SIGQUIT received (then the signal handler just need the very safe atomic increase)
-
Add a per-thread counter field to
struct StgTSO_, make it follow the global counter as the thread get scheduled -
The following up action be performed at each Haskell yield point, when thread's counter does not match global counter, do print the
CostCentreStackof either just-done or next-coming work, or both maybe, then update thread's counter to match global counter -
Interleaving of output may be solved the same way however parallel
traceis mitigated.
That might be really useful in diagnosing CPU hogging as in my situation, do you think it feasible?
-
I made a proof-of-concept in this commit complyue/ghc@ad2ade54 of https://gitlab.haskell.org/complyue/ghc/-/tree/8.8-ccs-bt
Backtraces won't be printed immediately when CPUs are idle, otherwise the result looks like ccs-bt-210125.log
I'll try to reproduce my situation and see if such backtraces can help tracking down the bug.
Edited by Compl Yuementioned in merge request !4891
Turns out cost center based backtraces are more informative than dwarf ones, I tracked down my CPU hogging bug (excessive STM retries due to mis-usage).
Shortcomings are apparent, especially a backtrace won't be printed out as soon as Ctrl^\ is pressed, unless the thread is busy on CPU. Though that's not a problem in hogging cases. And as it is currently implemented, the backtrace reveals what work will be scheduled after Ctrl^\ is pressed, not what has been keeping the CPU busy at that time, this also not quite a problem when the CPU is hogged for a long time, when the culprit code keeps coming back all the time.
It currently depends on a profiling build, I wonder if the implicit
?callStackparameter can be leveraged for builds without profiling enabled, but have no idea where to look for that.Please review MR !4891 and suggest if/how we can go further this way.
