[Bug dyninst/20052] New: pthreadprobes.exp stall

["mcermak at redhat dot com" <sourceware-bugzilla at sourceware dot org>]

https://sourceware.org/bugzilla/show_bug.cgi?id=20052

            Bug ID: 20052
           Summary: pthreadprobes.exp stall
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: dyninst
          Assignee: systemtap at sourceware dot org
          Reporter: mcermak at redhat dot com
  Target Milestone: ---

On x86_64, the pthreadprobes.exp testcase seems to cause relatively well
reproducible stall in one of its dyninst subtests, both on
f23/release-3.0-67-ge6eea51baebb and rhel7/devtoolset-4 rpm 2.9-3s.el7. 

The testcase generates binary pthreadprobes which as such runs for a few
seconds, then finishes. `stap --dyninst xxx.stp -c ./pthreadprobes`, where
xxx.stp is listed below, seems to almost always stall.

=======
# cat xxx.stp 
  global cond_broadcast, cond_destroy, cond_init, cond_signal,
    cond_timedwait, cond_wait, mutex_acquired, mutex_destroy,
    mutex_entry, mutex_init, mutex_release, mutex_timedlock_acquired,
    mutex_timedlock_entry, pthread_create, pthread_join,
    pthread_join_ret, pthread_start, rdlock_entry, rwlock_destroy,
    wrlock_entry

  probe process("/lib64/libpthread.so.0").mark("cond_broadcast") {
cond_broadcast++ }
  probe process("/lib64/libpthread.so.0").mark("cond_destroy") { cond_destroy++
}
  probe process("/lib64/libpthread.so.0").mark("cond_init") { cond_init++ }
  probe process("/lib64/libpthread.so.0").mark("cond_signal") { cond_signal++ }
  probe process("/lib64/libpthread.so.0").mark("cond_timedwait") {
cond_timedwait++ }
  probe process("/lib64/libpthread.so.0").mark("cond_wait") { cond_wait++ }
  probe process("/lib64/libpthread.so.0").mark("mutex_acquired") {
mutex_acquired++ }
  probe process("/lib64/libpthread.so.0").mark("mutex_destroy") {
mutex_destroy++ }
  probe process("/lib64/libpthread.so.0").mark("mutex_entry") { mutex_entry++ }
  probe process("/lib64/libpthread.so.0").mark("mutex_init") { mutex_init++ }
  probe process("/lib64/libpthread.so.0").mark("mutex_release") {
mutex_release++ }
  probe process("/lib64/libpthread.so.0").mark("mutex_timedlock_acquired") {
    mutex_timedlock_acquired++ }
  probe process("/lib64/libpthread.so.0").mark("mutex_timedlock_entry") {
    mutex_timedlock_entry++ }
  probe process("/lib64/libpthread.so.0").mark("pthread_create") {
pthread_create++ }
  probe process("/lib64/libpthread.so.0").mark("pthread_join") { pthread_join++
}
  probe process("/lib64/libpthread.so.0").mark("pthread_join_ret") {
pthread_join_ret++ }
  probe process("/lib64/libpthread.so.0").mark("pthread_start") {
pthread_start++ }
  probe process("/lib64/libpthread.so.0").mark("rdlock_entry") { rdlock_entry++
}
  probe process("/lib64/libpthread.so.0").mark("rwlock_destroy") {
rwlock_destroy++ }
  probe process("/lib64/libpthread.so.0").mark("wrlock_entry") { wrlock_entry++
}
  probe end {
    printf("cond_broadcast=%d\n", cond_broadcast)
    printf("cond_destroy=%d\n", cond_destroy)
    printf("cond_init=%d\n", cond_init)
    printf("cond_signal=%d\n", cond_signal)
    printf("cond_timedwait=%d\n", cond_timedwait)
    printf("cond_wait=%d\n", cond_wait)
    printf("mutex_acquired=%d\n", mutex_acquired)
    printf("mutex_destroy=%d\n", mutex_destroy)
    printf("mutex_entry=%d\n", mutex_entry)
    printf("mutex_init=%d\n", mutex_init)
    printf("mutex_release=%d\n", mutex_release)
    printf("mutex_timedlock_acquired=%d\n", mutex_timedlock_acquired)
    printf("mutex_timedlock_entry=%d\n", mutex_timedlock_entry)
    printf("pthread_create=%d\n", pthread_create)
    printf("pthread_join=%d\n", pthread_join)
    printf("pthread_join_ret=%d\n", pthread_join_ret)
    printf("pthread_start=%d\n", pthread_start)
    printf("rdlock_entry=%d\n", rdlock_entry)
    printf("rwlock_destroy=%d\n", rwlock_destroy)
    printf("wrlock_entry=%d\n", wrlock_entry)
  }
#
=======

The stall looks thusly:

=======
# stap -vvvvvv --dyninst  xxx.stp -c ./pthreadprobes
... stuff deleted ...
Pass 5: starting run.
Running /opt/rh/devtoolset-4/root/usr/bin/stapdyn -v -v -v -v -v -c
./pthreadprobes /tmp/stap4YZyZj/stap_60b2c3beb0fcbec36141257abd333339_7328.so
stapdyn: target "/usr/lib64/libpthread-2.17.so" has 29 probes
stapdyn:   offset:0xbe10 semaphore:0 flags:0
stapdyn:   offset:0xb4d4 semaphore:0 flags:0
stapdyn:   offset:0xb479 semaphore:0 flags:0
stapdyn:   offset:0xbd30 semaphore:0 flags:0
stapdyn:   offset:0xb95c semaphore:0 flags:0
stapdyn:   offset:0xb615 semaphore:0 flags:0
stapdyn:   offset:0x5d61 semaphore:0 flags:0
stapdyn:   offset:0x9c11 semaphore:0 flags:0
stapdyn:   offset:0x6621 semaphore:0 flags:0
stapdyn:   offset:0x1039c semaphore:0 flags:0
stapdyn:   offset:0x9ba0 semaphore:0 flags:0
stapdyn:   offset:0x9bdb semaphore:0 flags:0
stapdyn:   offset:0x1036b semaphore:0 flags:0
stapdyn:   offset:0x9b67 semaphore:0 flags:0
stapdyn:   offset:0x6123 semaphore:0 flags:0
stapdyn:   offset:0x6132 semaphore:0 flags:0
stapdyn:   offset:0xab54 semaphore:0 flags:0
stapdyn:   offset:0xabde semaphore:0 flags:0
stapdyn:   offset:0xa3c8 semaphore:0 flags:0
stapdyn:   offset:0xa8c7 semaphore:0 flags:0
stapdyn:   offset:0xa9f7 semaphore:0 flags:0
stapdyn:   offset:0xa2df semaphore:0 flags:0
stapdyn:   offset:0x8420 semaphore:0 flags:0
stapdyn:   offset:0x8e8d semaphore:0 flags:0
stapdyn:   offset:0x8f33 semaphore:0 flags:0
stapdyn:   offset:0x7db3 semaphore:0 flags:0
stapdyn:   offset:0xade0 semaphore:0 flags:0
stapdyn:   offset:0xadd0 semaphore:0 flags:0
stapdyn:   offset:0xb000 semaphore:0 flags:0
stapdyn: pid 1518 has 17 registers available: rax rbx rsp rbp r10 r11 r12 r13
r14 r15 r8 r9 rcx rdx rsi rdi eflags
stapdyn: dlopen "stap_60b2c3beb0fcbec36141257abd333339_7328.so", pid = 1518
stapdyn: found object "/root/work/tmp.LPzQswb90L/pthreadprobes" in pid 1518
stapdyn: found object
"/opt/rh/devtoolset-4/root/usr/lib64/dyninst/libdyninstAPI_RT.so.9.1.0" in pid
1518
stapdyn: found object "/usr/lib64/libpthread-2.17.so" in pid 1518
stapdyn: found target "/usr/lib64/libpthread-2.17.so" in pid 1518, inserting 29
probes
stapdyn: found object "/usr/lib64/librt-2.17.so" in pid 1518
stapdyn: found object "/usr/lib64/libc-2.17.so" in pid 1518
stapdyn: found object "/usr/lib64/libdl-2.17.so" in pid 1518
stapdyn: found object
"/tmp/stap4YZyZj/stap_60b2c3beb0fcbec36141257abd333339_7328.so" in pid 1518
stapdyn: calling function 'stp_dyninst_shm_connect' in pid 1518
stapdyn: continuing execution of pid 1518
^C^C^CToo many interrupts received, exiting.
 7.2 S x86_64 [4] # stap -V
Systemtap translator/driver (version 2.9/0.166, devtoolset-4 rpm 2.9-3s.el7)
=======

Once, among couple of test runs, I saw the testcase to finish though, whereas
subsequent run of exactly the same thing was running overnight and didn't
finish.

=======
[root@dhcp-1-147 ~]# stap --dyninst xxx.stp -c ./pthreadprobes 
stapdyn: WARNING: Couldn't instrument the function containing 0x7fd7ce818a08,
/usr/lib64/libpthread-2.22.so+0xba08
stapdyn: WARNING: Couldn't instrument the function containing 0x7fd7ce818fc3,
/usr/lib64/libpthread-2.22.so+0xbfc3
cond_broadcast=0
cond_destroy=0
cond_init=0
cond_signal=0
cond_timedwait=0
cond_wait=0
mutex_acquired=1
mutex_destroy=0
mutex_entry=1
mutex_init=1
mutex_release=1
mutex_timedlock_acquired=0
mutex_timedlock_entry=0
pthread_create=1
pthread_join=0
pthread_join_ret=0
pthread_start=0
rdlock_entry=0
rwlock_destroy=0
wrlock_entry=0
[root@dhcp-1-147 ~]# stap --dyninst xxx.stp -c ./pthreadprobes 
stapdyn: WARNING: Couldn't instrument the function containing 0x7f21271bca08,
/usr/lib64/libpthread-2.22.so+0xba08
stapdyn: WARNING: Couldn't instrument the function containing 0x7f21271bcfc3,
/usr/lib64/libpthread-2.22.so+0xbfc3
^C^C^CToo many interrupts received, exiting.
=======

-- 
You are receiving this mail because:
You are the assignee for the bug.