release build perturb_only test failure on Linux

[derekbruening]

From [email protected] on April 08, 2014 17:11:33

The following tests FAILED:
43 - perturb_FLAKY (Failed)
Errors while running CTest

It only happens in release build

Original issue: http://code.google.com/p/drmemory/issues/detail?id=1516

[derekbruening]

From [email protected] on April 08, 2014 14:16:04

When run DrM release and DR debug build:

./bin/drmemory -dr ../build_x86_drm_dbg.git/dynamorio -dr_debug -dr_ops "-msgbox_mask 0xc" -perturb_only -- ./tests/pthread_test
<Starting application /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/tests/pthread_test (8327)>
<Paste into GDB to debug DynamoRIO clients:
set confirm off
add-symbol-file '/usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/release/libdrmemorylib.so' 0x73810000
add-symbol-file '/usr/lib32/libgcc_s.so.1' 0xf6fe2f50
add-symbol-file '/lib32/libc.so.6' 0xf6e4ff10
add-symbol-file '/lib/ld-linux.so.2' 0xf7545820

<Initial options = -no_dynamic_options -logdir '/tmp/Dr. Memory/dynamorio' -client_lib '/usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/release/libdrmemorylib.so;0;-perturb_only -logdir /tmp/Dr. Memory -symcache_dir /tmp/Dr. Memory/symcache -resfile 8327 ' -code_api -msgbox_mask 12 -stack_size 56K -disable_traces -no_enable_traces -max_elide_jmp 0 -max_elide_call 0 -max_bb_instrs 256 -no_shared_traces -bb_ibl_targets -bb_single_restore_prefix -no_shared_trace_ibl_routine -no_enable_reset -no_reset_at_switch_to_os_at_vmm_limit -reset_at_vmm_percent_free_limit 0 -no_reset_at_vmm_full -reset_at_commit_free_limit 0K -reset_every_nth_pending 0 -vm_size 262144K -no_inline_ignored_syscalls -native_exec_default_list '' -no_native_exec_managed_code -no_indcall2direct >
Dr.M Dr. Memory version 1.6.1878
Estimation of pi is 3.142425985001098
<Stopping application /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/tests/pthread_test (8327)>

After the Stopping printout, it takes awhile to exit, or not even exit.
Attaching gdb on: two threads

(gdb) where
#0 syscall_0args () at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/x86/x86.asm:1249
#1 0xf7398ff4 in ?? () from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/../build_x86_drm_dbg.git/dynamorio/lib32/debug/libdynamorio.so
#2 0xf71ddb61 in synch_thread_yield () at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/synch.c:783
#3 0xf71dfd0a in synch_with_all_threads (desired_synch_state=THREAD_SYNCH_TERMINATED_AND_CLEANED, threads_out=0x46c46a10, num_threads_out=0x46c46a14,
cur_state=THREAD_SYNCH_NO_LOCKS_NO_XFER, flags=2) at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/synch.c:1343
#4 0xf7078ea0 in synch_with_threads_at_exit (synch_res=THREAD_SYNCH_TERMINATED_AND_CLEANED) at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/dynamo.c:1126
#5 0xf7078ff8 in dynamo_process_exit_cleanup () at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/dynamo.c:1189
#6 0xf70791d3 in dynamo_process_exit () at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/dynamo.c:1281
#7 0xf7267c77 in cat_done_saving_dstack () at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/x86/x86.asm:597
#8 0xf7267cd0 in cat_have_lock () at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/x86/x86.asm:721
#9 0x46c47000 in ?? ()
#10 0x46be5480 in ?? ()
#11 0x5e5b0000 in ?? ()
#12 0x55c35d5f in ?? ()
Backtrace stopped: previous frame inner to this frame (corrupt stack?)
(gdb) thread 2
[Switching to thread 2 (Thread 0xf4e33b40 (LWP 8334))]
#0 syscall_0args () at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/x86/x86.asm:1249
1249 pop REG_XDI
(gdb) where
#0 syscall_0args () at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/x86/x86.asm:1249
#1 0x0000002d in ?? ()
#2 0x0000002d in ?? ()
#3 0x46deee84 in ?? ()
#4 0xf7286c92 in dr_sleep (time_ms=0) at /home/zhaoqin/Workspace/DrMemory/drmemory.git/dynamorio/core/x86/instrument.c:4337
#5 0x7386be20 in do_delay (type=0) at /home/zhaoqin/Workspace/DrMemory/drmemory.git/drmemory/perturb.c:134
#6 0x46c1e919 in ?? ()
#7 0xf774bd4c in start_thread (arg=0xf4e33b40) at pthread_create.c:308
#8 0xf768abae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

(gdb) x/20i 0x46c1e8e1
0x46c1e8e1: mov %fs:0x8,%ecx
0x46c1e8e8: mov %eax,%fs:0x0
0x46c1e8ee: mov %fs:0x10,%eax
0x46c1e8f4: mov %esp,0xc(%eax)
0x46c1e8f7: mov 0x168(%eax),%esp
0x46c1e8fd: mov %fs:0x0,%eax
0x46c1e903: lea -0x144(%esp),%esp
0x46c1e90a: call 0x46c125c0
0x46c1e90f: push $0x0
0x46c1e914: call 0x7386bdd0 <do_delay>
0x46c1e919: lea 0x4(%esp),%esp
0x46c1e91d: call 0x46c12640
0x46c1e922: mov %eax,%fs:0x0
0x46c1e928: mov %fs:0x10,%eax
0x46c1e92e: mov 0xc(%eax),%esp
0x46c1e931: mov %fs:0x0,%eax
0x46c1e937: xchg %edi,%ebx
0x46c1e939: cmp $0xfffff000,%eax
0x46c1e93e: ja 0x46c2aa20

So it is a thread with inserted clean call do_delay. So it is more likely the delay took so long so often that it is hard to reach a safe place for DR to handle the signal and do proper exit.

[derekbruening]

From [email protected] on April 09, 2014 09:41:47

If skip the syscall for dr_delay, we still see the test hang, where every threads hang at mutex lock system call.

Every caller is at dynamo_thread_exit_common on line 2251:

static int
dynamo_thread_exit_common(dcontext_t *dcontext, thread_id_t id,
IF_WINDOWS_(bool detach_stacked_callbacks) bool other_thread)
{
...
if (!other_thread)
mutex_lock(&thread_initexit_lock);

[derekbruening]

From [email protected] on April 09, 2014 09:48:42

(gdb) x/60x $esp
0x52966c38: 0x00000001 0xf716d284 0x00000000 0xf715eff4
0x52966c48: 0xf710f6c1 0x000000f0 0x00000006 0xf716d284
0x52966c58: 0x00000000 0x00000001 0x00000000 0x00000000
0x52966c68: 0x00000000 0xf715eff4 0xf70fd4b1 0xf716d284
0x52966c78: 0x00000001 0xf715eff4 0xf716d284 0x00000000
0x52966c88: 0xf7166660 0xf7065fc8 0xf716d284 0xf7065f67
0x52966c98: 0xf715eff4 0x527e7540 0xf7041476 0xf716d284
0x52966ca8: 0x738eda00 0x00000001 0x00007276 0x00000001
0x52966cb8: 0x52966d20 0x73883a80 0x7386c06d 0x52969000
0x52966cc8: 0x52974550 0x52966ca4 0xf715eff4 0x527e7540
0x52966cd8: 0xf715eff4 0x52966cfc 0xf7041822 0x00000000
0x52966ce8: 0x52967000 0x00000000 0xf70e466a 0xf70e46bc
0x52966cf8: 0x52967000 0xf70f2eba 0x527e7540 0x00000001
0x52966d08: 0x00000000 0x007fc000 0x00000000 0x00000004
0x52966d18: 0xf47fab40 0x527e7540 0x529742cc 0x7390053c

(gdb) x/x 0xf716d284
0xf716d284 <thread_initexit_lock>: 0x00000001
(gdb) x/i 0xf710f6c1-5
0xf710f6bc <ksynch_wait+92>: call 0xf70e46ca <dynamorio_syscall>
(gdb) x/i 0xf70fd4b1-5
0xf70fd4ac <mutex_wait_contended_lock+108>: call 0xf710f660 <ksynch_wait>
(gdb) x/i 0xf7065fc8-5
0xf7065fc3 <mutex_lock+99>: call 0xf70fd440 <mutex_wait_contended_lock>
(gdb) x/i 0xf7041476-5
0xf7041471 <dynamo_thread_exit_common+561>: call 0xf7065f60 <mutex_lock>
(gdb) x/i 0xf7041822-5
0xf704181d <dynamo_thread_exit+45>: call 0xf7041240 <dynamo_thread_exit_common>
(gdb) x/i 0xf70e466a-5
0xf70e4665 <cat_thread_only>: call 0xf70417f0 <dynamo_thread_exit>
(gdb) x/i 0xf70e46bc
0xf70e46bc <global_do_syscall_int>: int $0x80
(gdb) x/i 0xf70f2eba-5
0xf70f2eb5 <handle_exit+549>: call 0xf70e460f <cleanup_and_terminate>

(gdb) info threads
Id Target Id Frame
11 Thread 0xf67feb40 (LWP 29297) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so
10 Thread 0xf6fffb40 (LWP 29298) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so
9 Thread 0xf5ffdb40 (LWP 29299) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so
8 Thread 0xf57fcb40 (LWP 29300) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so
7 Thread 0xf4ffbb40 (LWP 29301) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so

• 6 Thread 0xf47fab40 (LWP 29302) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
  from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so
  5 Thread 0xf3ff9b40 (LWP 29303) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
  from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so
  4 Thread 0xf37f8b40 (LWP 29304) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
  from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so
  3 Thread 0xf2ff7b40 (LWP 29305) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
  from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so
  2 Thread 0xf27f6b40 (LWP 29306) "pthread_test" (Exiting) 0xf70e470e in syscall_0args ()
  from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so
  1 Thread 0xf75746c0 (LWP 29293) "pthread_test" 0xf70e470e in syscall_0args ()
  from /usr/local/google/home/zhaoqin/Workspace/DrMemory/builds/build_x86_drm_rel.git/bin/../dynamorio/lib32/release/libdynamorio.so