[Mono-dev] FW: Random hangs while running mono app

Rodrigo Kumpera kumpera at gmail.com
Fri Jun 3 20:02:14 UTC 2016 

Hi,

The cue card output on itself is not useful.
I need the cue card output with the matched thread dump as that allows me
to see what's going on on the problematic thread.

--
Rodrigo


On Fri, Jun 3, 2016 at 12:42 PM, George, Glover E ERDC-RDE-ITL-MS CIV <
Glover.E.George at erdc.dren.mil> wrote:

> Hi Rodrigo,
>
> I didn¹t realize our previous emails were off thread.  I was able to get
> the STAT CUE CARD output.  See below:
>
> STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any
> number)
>         0x0     - starting (GOOD, unless the thread is running managed
> code)
>         0x1     - running (BAD, unless it's the gc thread)
>         0x2     - detached (GOOD, unless the thread is running managed
> code)
>         0x?03   - async suspended (GOOD)
>         0x?04   - self suspended (GOOD)
>         0x?05   - async suspend requested (BAD)
>         0x?06   - self suspend requested (BAD)
>         0x*07   - blocking (GOOD)
>         0x?08   - blocking with pending suspend (GOOD)
> --thread 0xa38b30 id 0x7fffec637700 [(nil)] state 105
> --thread 0x9d8640 id 0x7fffedae7780 [(nil)] state 1  GC INITIATOR
> WAITING for 1 threads, got 0 suspended
> suspend_thread suspend took 200 ms, which is more than the allowed 200 ms
> STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any
> number)
>         0x0     - starting (GOOD, unless the thread is running managed
> code)
>         0x1     - running (BAD, unless it's the gc thread)
>         0x2     - detached (GOOD, unless the thread is running managed
> code)
>         0x?03   - async suspended (GOOD)
>         0x?04   - self suspended (GOOD)
>         0x?05   - async suspend requested (BAD)
>         0x?06   - self suspend requested (BAD)
>         0x*07   - blocking (GOOD)
>         0x?08   - blocking with pending suspend (GOOD)
> --thread 0xa38b30 id 0x7fffec637700 [(nil)] state 105
> --thread 0x9d8640 id 0x7fffedae7780 [(nil)] state 1  GC INITIATOR
> WAITING for 1 threads, got 0 suspended
> suspend_thread suspend took 200 ms, which is more than the allowed 200 ms
> STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any
> number)
>         0x0     - starting (GOOD, unless the thread is running managed
> code)
>         0x1     - running (BAD, unless it's the gc thread)
>         0x2     - detached (GOOD, unless the thread is running managed
> code)
>         0x?03   - async suspended (GOOD)
>         0x?04   - self suspended (GOOD)
>         0x?05   - async suspend requested (BAD)
>         0x?06   - self suspend requested (BAD)
>         0x*07   - blocking (GOOD)
>         0x?08   - blocking with pending suspend (GOOD)
> --thread 0xa38b30 id 0x7fffec637700 [(nil)] state 105
> --thread 0x9d8640 id 0x7fffedae7780 [(nil)] state 1  GC INITIATOR
> WAITING for 1 threads, got 0 suspended
> suspend_thread suspend took 200 ms, which is more than the allowed 200 ms
> STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any
> number)
>         0x0     - starting (GOOD, unless the thread is running managed
> code)
>         0x1     - running (BAD, unless it's the gc thread)
>         0x2     - detached (GOOD, unless the thread is running managed
> code)
>         0x?03   - async suspended (GOOD)
>         0x?04   - self suspended (GOOD)
>         0x?05   - async suspend requested (BAD)
>         0x?06   - self suspend requested (BAD)
>         0x*07   - blocking (GOOD)
>         0x?08   - blocking with pending suspend (GOOD)
> --thread 0xa38b30 id 0x7fffec637700 [(nil)] state 105
> --thread 0x9d8640 id 0x7fffedae7780 [(nil)] state 1  GC INITIATOR
> WAITING for 1 threads, got 0 suspended
> suspend_thread suspend took 200 ms, which is more than the allowed 200 ms
> STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any
> number)
>         0x0     - starting (GOOD, unless the thread is running managed
> code)
>         0x1     - running (BAD, unless it's the gc thread)
>         0x2     - detached (GOOD, unless the thread is running managed
> code)
>         0x?03   - async suspended (GOOD)
>         0x?04   - self suspended (GOOD)
>         0x?05   - async suspend requested (BAD)
>         0x?06   - self suspend requested (BAD)
>         0x*07   - blocking (GOOD)
>         0x?08   - blocking with pending suspend (GOOD)
> --thread 0xa38b30 id 0x7fffec637700 [(nil)] state 105
> --thread 0x9d8640 id 0x7fffedae7780 [(nil)] state 1  GC INITIATOR
> WAITING for 1 threads, got 0 suspended
> suspend_thread suspend took 200 ms, which is more than the allowed 200 ms
> STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any
> number)
>         0x0     - starting (GOOD, unless the thread is running managed
> code)
>         0x1     - running (BAD, unless it's the gc thread)
>         0x2     - detached (GOOD, unless the thread is running managed
> code)
>         0x?03   - async suspended (GOOD)
>         0x?04   - self suspended (GOOD)
>         0x?05   - async suspend requested (BAD)
>         0x?06   - self suspend requested (BAD)
>         0x*07   - blocking (GOOD)
>         0x?08   - blocking with pending suspend (GOOD)
> --thread 0xa38b30 id 0x7fffec637700 [(nil)] state 105
> --thread 0x9d8640 id 0x7fffedae7780 [(nil)] state 1  GC INITIATOR
> WAITING for 1 threads, got 0 suspended
> suspend_thread suspend took 200 ms, which is more than the allowed 200 ms
> STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any
> number)
>         0x0     - starting (GOOD, unless the thread is running managed
> code)
>         0x1     - running (BAD, unless it's the gc thread)
>         0x2     - detached (GOOD, unless the thread is running managed
> code)
>         0x?03   - async suspended (GOOD)
>         0x?04   - self suspended (GOOD)
>         0x?05   - async suspend requested (BAD)
>         0x?06   - self suspend requested (BAD)
>         0x*07   - blocking (GOOD)
>         0x?08   - blocking with pending suspend (GOOD)
> --thread 0xa38b30 id 0x7fffec637700 [(nil)] state 105
> --thread 0x9d8640 id 0x7fffedae7780 [(nil)] state 1  GC INITIATOR
>
>
> ‹ ‹ ‹
> Glover E. George
> Computer Scientist
> Information Technology Laboratory
> US Army Engineer Research and Development Center
> Vicksburg, MS 39180
> 601-634-4730
>
>
>
>
>
> From:  Rodrigo Kumpera <kumpera at gmail.com>
> Date:  Friday, April 29, 2016 at 9:12 AM
> To:  Glover George <glover.e.george at erdc.dren.mil>
> Cc:  "mono-devel-list at lists.ximian.com" <mono-devel-list at lists.ximian.com>
> Subject:  Re: [Mono-dev] FW: Random hangs while running mono app
>
>
> This looks like a shutdown bug in mono.
>
> Do you have a reliable way to reproduce it?
> How loaded are the machines running your workload?
>
>
> On Thu, Apr 28, 2016 at 6:41 PM, George, Glover E ERDC-RDE-ITL-MS CIV
> <Glover.E.George at erdc.dren.mil> wrote:
>
> One more important point I forgot to mention, when this occurs, it is
> generally only a few mono instances out of the 500+ simultaneous mono
> instances.  Most of them terminate.  And more importantly, the mono
> instances that do hang actually complete their
>  work!  It seems to be when mono is trying to close down.
>
> This has occurred with mono 4.2.x, 4.3.x, 4.4.x, and current git.
>
> Happened today with this configuration:
> Mono JIT compiler version 4.3.2 (Stable 4.3.2.467/ba2e5e4 Tue Mar 15
> 11:44:06 CDT 2016)
> Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors.
> Blockedwww.mono-project.comBlocked
> <Blockedhttp://www.mono-project.comBlocked>
> TLS:           __thread
> SIGSEGV:       altstack
> Notifications: epoll
> Architecture:  amd64
> Disabled:      none
> Misc:          bigarrays softdebug
> LLVM:          supported, not enabled.
> GC:            sgen
>
>
>
>
> From: <mono-devel-list-bounces at lists.ximian.com> on behalf of Glover
> George <glover.e.george at erdc.dren.mil>
> Date: Thursday, April 28, 2016 at 5:25 PM
> To: "mono-devel-list at lists.ximian.com" <mono-devel-list at lists.ximian.com>
> Subject: [Mono-dev] Random hangs while running mono app
>
>
> Hi all,
>
> Quick background: We¹re running mono on an HPC platform (SGI ICE-X / SUSE
> Enterprise Linux 11) with a Lustre filesystem.  For several months, I¹ve
> noticed random hangs with our application.  In a given batch job, we run
> 500+ instances of mono in parallel
>  (no interprocess communication).   I haven¹t been able to reliably
> reproduce the issue which leads me to believe it¹s a timing issue, and
> more specifically, I have reason to believe it may be an issue with the
> interaction of mono and the filesystem.  Being
>  a clustered file-system, the load on the backing stores can vary due to
> other users.
>
> When I notice that my job hasn¹t finished in a reasonable amount of time,
> I log into the compute node and do a  ³ ps -efL | grep mono ³ which
> reveals:
>
> george  16728 16575 16728  6    3 16:13 ?        00:03:58 mono
> --runtime=v4.0.30319 /app/MyConsole.exe
> ggeorge  16728 16575 16768  0    3 16:13 ?        00:00:02 mono
> --runtime=v4.0.30319 /app/MyConsole.exe
> ggeorge  16728 16575 16815  0    3 16:13 ?        00:00:04 mono
> --runtime=v4.0.30319 /app/MyConsole.exe
>
>
> 16728 is the top proc which spawns 16768 and 16815 (main, gc and maybe
> finalizer thread?).
>
> Attaching to each of these 3 pid¹s with gdb and doing a backtrace reveals
> the traces below.
>
> 1.  Is it possible this is a GC hang?
>
> 2.  Is it possible this is a race condition that has anything to do with
> the filesystem?
>
> 3.  Any idea how this sequence could occur?  If there¹s a way to gather
> more information, please let me know.
>
> The reason for the file system suspicion is my app writes several small
> files, times the number of mono instances (500+).  It only happens
> randomly, but seems to be more frequent the more mono instances I run.
>
> Any help is HIGHLY appreciated.
>
> PID 16728
> ‹‹‹
> (gdb) bt
> #0  0x00007fffecccd324 in __lll_lock_wait () from /lib64/libpthread.so.0
> #1  0x00007fffeccc8684 in _L_lock_1091 () from /lib64/libpthread.so.0
> #2  0x00007fffeccc84f6 in pthread_mutex_lock () from /lib64/libpthread.so.0
> #3  0x00007fffed8f6dcc in _dl_open () from /lib64/ld-linux-x86-64.so.2
> #4  0x00007fffec842530 in do_dlopen () from /lib64/libc.so.6
> #5  0x00007fffed8f2e86 in _dl_catch_error () from
> /lib64/ld-linux-x86-64.so.2
> #6  0x00007fffec8425e5 in dlerror_run () from /lib64/libc.so.6
> #7  0x00007fffec8426d7 in __libc_dlopen_mode () from /lib64/libc.so.6
> #8  0x00007fffec81d2e5 in init () from /lib64/libc.so.6
> #9  0x00007fffecccbd03 in pthread_once () from /lib64/libpthread.so.0
> #10 0x00007fffec81d43c in backtrace () from /lib64/libc.so.6
> #11 0x00000000004ac025 in mono_handle_native_sigsegv (signal=<optimized
> out>, ctx=<optimized out>, info=<optimized out>)
>     at mini-exceptions.c:2309
> #12 <signal handler called>
> #13 0x00007fffec75e875 in raise () from /lib64/libc.so.6
> #14 0x00007fffec75fe51 in abort () from /lib64/libc.so.6
> #15 0x000000000064528a in monoeg_log_default_handler (log_domain=0x0,
> log_level=G_LOG_LEVEL_ERROR, message=
>     0x1ac7660 "suspend_thread suspend took 200 ms, which is more than the
> allowed 200 ms", unused_data=0x0) at goutput.c:233
> #16 0x0000000000645077 in monoeg_g_logv (log_domain=0x0,
> log_level=G_LOG_LEVEL_ERROR, format=
>     0x7015d8 "suspend_thread suspend took %d ms, which is more than the
> allowed %d ms", args=0x7fffffffce58) at goutput.c:113
> #17 0x000000000064512d in monoeg_g_log (log_domain=0x0,
> log_level=G_LOG_LEVEL_ERROR, format=
>     0x7015d8 "suspend_thread suspend took %d ms, which is more than the
> allowed %d ms") at goutput.c:123
> #18 0x000000000063a13f in mono_threads_wait_pending_operations () at
> mono-threads.c:238
> #19 0x000000000063a8cd in suspend_sync (interrupt_kernel=1,
> tid=140737159329536) at mono-threads.c:877
> #20 suspend_sync_nolock (interrupt_kernel=1, id=140737159329536) at
> mono-threads.c:892
> #21 mono_thread_info_safe_suspend_and_run (id=140737159329536,
> interrupt_kernel=interrupt_kernel at entry=1, callback=callback at entry=
>     0x58d5c0 <abort_thread_critical>,
> user_data=user_data at entry=0x7fffffffd3e0) at mono-threads.c:935
> #22 0x0000000000591a86 in abort_thread_internal
> (thread=thread at entry=0x7fffec6e0230,
> install_async_abort=install_async_abort at entry=1,
>     can_raise_exception=1) at threads.c:4728
> #23 0x0000000000591b29 in mono_thread_internal_stop
> (thread=0x7fffec6e0230) at threads.c:2385
> ---Type <return> to continue, or q <return> to quit---
> #24 0x00000000005b123e in mono_gc_cleanup () at gc.c:842
> #25 0x00000000005aab8e in mono_runtime_cleanup
> (domain=domain at entry=0x9d9e00) at appdomain.c:356
> #26 0x0000000000426c8b in mini_cleanup (domain=0x9d9e00) at
> mini-runtime.c:4017
> #27 0x000000000047fac6 in mono_main (argc=11, argv=<optimized out>) at
> driver.c:2115
> #28 0x0000000000424c68 in mono_main_with_options (argv=0x7fffffffd698,
> argc=11) at main.c:20
> #29 main (argc=<optimized out>, argv=<optimized out>) at main.c:53
>
> Thread 16768
> ‹‹‹
> (gdb) bt
> #0  0x00007fffeccca66c in pthread_cond_wait@@GLIBC_2.3.2 () from
> /lib64/libpthread.so.0
> #1  0x000000000060c873 in mono_os_cond_wait (mutex=0x97e640 <lock>,
> cond=0x97e600 <work_cond>) at ../../mono/utils/mono-os-mutex.h:105
> #2  thread_func (thread_data=0x0) at sgen-thread-pool.c:118
> #3  0x00007fffeccc6806 in start_thread () from /lib64/libpthread.so.0
> #4  0x00007fffec80a9bd in clone () from /lib64/libc.so.6
> #5  0x0000000000000000 in ?? ()
> (gdb)
>
>
> Thread 16815
> ‹‹‹‹
> Thread #0  0x00007fffec75ec8b in sigsuspend () from /lib64/libc.so.6
> #1  0x000000000063cda6 in suspend_signal_handler (_dummy=<optimized out>,
> info=<optimized out>, context=0x7fffec633dc0)
>     at mono-threads-posix-signals.c:209
> #2  <signal handler called>
> #3  0x00007fffed8faf97 in open64 () from /lib64/ld-linux-x86-64.so.2
> #4  0x00007fffed8ea82d in open_verify () from /lib64/ld-linux-x86-64.so.2
> #5  0x00007fffed8eade0 in open_path () from /lib64/ld-linux-x86-64.so.2
> #6  0x00007fffed8ece7c in _dl_map_object () from
> /lib64/ld-linux-x86-64.so.2
> #7  0x00007fffed8f7400 in dl_open_worker () from
> /lib64/ld-linux-x86-64.so.2
> #8  0x00007fffed8f2e86 in _dl_catch_error () from
> /lib64/ld-linux-x86-64.so.2
> #9  0x00007fffed8f6e3b in _dl_open () from /lib64/ld-linux-x86-64.so.2
> #10 0x00007fffecedcf9b in dlopen_doit () from /lib64/libdl.so.2
> #11 0x00007fffed8f2e86 in _dl_catch_error () from
> /lib64/ld-linux-x86-64.so.2
> #12 0x00007fffecedd33c in _dlerror_run () from /lib64/libdl.so.2
> #13 0x00007fffecedcf01 in dlopen@@GLIBC_2.2.5 () from /lib64/libdl.so.2
> #14 0x0000000000630b79 in mono_dl_open (name=name at entry=0x1c02790
> "libSystem.Data", flags=flags at entry=1, error_msg=error_msg at entry=
>     0x7fffec634e80) at mono-dl.c:150
> #15 0x000000000054b9f0 in cached_module_load (name=name at entry=0x1c02790
> "libSystem.Data", err=err at entry=0x7fffec634e80, flags=1)
>     at loader.c:1398
>
>
>
>
>
>
>
>
> _______________________________________________
> Mono-devel-list mailing list
> Mono-devel-list at lists.ximian.com
> Blockedhttp://lists.ximian.com/mailman/listinfo/mono-devel-listBlocked
>
>
>
>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ximian.com/pipermail/mono-devel-list/attachments/20160603/1c660cb6/attachment-0001.html>

More information about the Mono-devel-list mailing list