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