[Bug runtime/24416] New: Tests stuck in uprobes_onthefly.exp

[Bug runtime/24416] New: Tests stuck in uprobes_onthefly.exp

[wcohen at redhat dot com]

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

            Bug ID: 24416
           Summary: Tests stuck in uprobes_onthefly.exp
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
          Assignee: systemtap at sourceware dot org
          Reporter: wcohen at redhat dot com
  Target Milestone: ---

When running the "make installcheck" on multiple x86 machines running Fedora 29
and rawhide see that the tests getting stuck when running uprobes_onthefly.exp.
See multiple messages in the output of dmesg of the form from a rawhide machine
running kernel-5.0.5-300.fc30.x86_64:

[86154.130199] INFO: rcu_tasks detected stalls on tasks:
[86154.130202] 00000000c3a1580f: .. nvcsw: 0/0 holdout: 1 idle_cpu: -1/0
[86154.130204] uprobes_onthefl R  running task        0  7087  25897 0x00000000
[86154.130206] Call Trace:
[86154.130212]  ? __schedule+0x264/0x8a0
[86154.130213]  schedule+0x32/0x70
[86154.130215]  exit_to_usermode_loop+0x5c/0xd0
[86154.130217]  prepare_exit_to_usermode+0x59/0x60
[86154.130218]  retint_user+0x8/0x8
[86154.130220] RIP: 0033:0x40113c
[86154.130221] Code: fc 8b 45 ec 8d 14 00 8b 45 fc 01 d0 5d c3 55 48 89 e5 48
83 ec 10 89 7d fc 48 89 75 f0 8b 45 fc 89 c7 e8 cd ff ff ff 89 45 fc <eb> f1 66
90 f3 0f 1e fa 41 57 4c 8d 3d 03 2d 00 00 41 56 49 89 d6
[86154.130222] RSP: 002b:00007ffc66707c60 EFLAGS: 00000286 ORIG_RAX:
ffffffffffffff13
[86154.130223] RAX: 0000000099be4f1b RBX: 0000000000000000 RCX:
00007fe04acdc738
[86154.130223] RDX: 0000000011298a12 RSI: 00007ffc66707d58 RDI:
000000008894c509
[86154.130224] RBP: 00007ffc66707c70 R08: 00007fe04acddd80 R09:
00007fe04ad0f170
[86154.130224] R10: 0000000000000000 R11: 0000000000000022 R12:
0000000000401020
[86154.130225] R13: 00007ffc66707d50 R14: 0000000000000000 R15:
0000000000000000

Can reproduce with:

sudo make installcheck RUNTESTFLAGS="--debug
systemtap.onthefly/uprobes_onthefly.exp"

Looking at the traceback it looks like things could get stuck in
exit_to_usermode_loop if _TIF_NEED_RESCHED never gets set to zero.

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

[Bug runtime/24416] Tests stuck in uprobes_onthefly.exp

[wcohen at redhat dot com]

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

--- Comment #1 from William Cohen <wcohen at redhat dot com> ---
The uprobes_onthefly.exp tests complete successfully (23 passes and 0 failures)
on:

aarch64 f29 kernel-5.0.5-200.fc29.aarch64
x86_64 rhel7 kernel-3.10.0-957.10.1.el7.x86_64
ppc64le f28 kernel-core-5.0.5-100.fc28.ppc64le

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

[Bug runtime/24416] Tests stuck in uprobes_onthefly.exp

[wcohen at redhat dot com]

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

--- Comment #2 from William Cohen <wcohen at redhat dot com> ---
The particular test where the RCU warnings start occurring appears to be the
last one in uprobes_onthefly.exp:

run_subtest_stress "otf_stress_max_iter_5000" 1 5000 max \
   -D STP_ON_THE_FLY_INTERVAL=100000

According to comment below for make_script a lot of tracepoint will be used. 
It is possible that variation in the trace

# Returns a script with some variables replaced.
#     SUBTEST    name of subtest
#     ENABLED    set to 1 to start the target probe as enabled, 0 as disabled
#     MAXTOGGLES number of times we toggle the target probe condition
#     TIMER      if a number, then it's the period of the timer probe which
#                toggles the target probes, if set to 'profile' then instead a
#                timer.profile probe is used to toggle the target probe, if set
#                to 'hardcore' then both a timer.profile probe and a
#                kernel.trace("*") probe is used for toggling, if set to 'max'
#                then a lot of various probe points are used for toggling

It looks like the x86_64 might be running into a problem similar to the one
addressed in PR17270 by:

commit e6f437adfe6d0f48562ce3204c0fa4dd184b43c9
Author: David Smith <dsmith@redhat.com>
Date:   Wed Dec 17 11:38:45 2014 -0600

    Fixed PR17270 by updating "on the fly" tests for ppc64.

    * translate.cxx (c_unparser::emit_module_refresh): Don't print debug
      message in STAP_SESSION_STOPPING state.
    * testsuite/systemtap.onthefly/hrtimer_onthefly.exp: On ppc64, don't probe
      kernel tracepoints causing a crash.
    * testsuite/systemtap.onthefly/kprobes_onthefly.exp: Ditto.
    * testsuite/systemtap.onthefly/uprobes_onthefly.exp: Ditto.

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

[Bug runtime/24416] Tests stuck in uprobes_onthefly.exp

[wcohen at redhat dot com]

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

--- Comment #3 from William Cohen <wcohen at redhat dot com> ---
There looks to be some very hot tracepoints that are only appearing on the
fedora x86 5.0.x kernels that do not appear on rhel7 x86 or aarch64.  Follow
was run for only a short time:

$ sudo stap -ve 'global counts probe kernel.trace("*"){counts[pp()] <<< 1}'
Pass 1: parsed user script and 492 library scripts using
388652virt/161896res/9176shr/152916data kb, in 320usr/130sys/464real ms.
Pass 2: analyzed script: 758 probes, 1 function, 0 embeds, 1 global using
401280virt/175916res/10224shr/165544data kb, in 140usr/450sys/602real ms.
Pass 3: translated to C into
"/tmp/stapLJpHud/stap_7678d191c1a6333683c0dfbeb77bd4b6_207067_src.c" using
401792virt/176236res/10288shr/166056data kb, in 20usr/0sys/27real ms.
Pass 4: compiled C into "stap_7678d191c1a6333683c0dfbeb77bd4b6_207067.ko" in
44040usr/14440sys/60733real ms.
Pass 5: starting run.
^Ccounts["kernel.trace("lock:lock_release")"] @count=142050 @min=1 @max=1
@sum=142050 @avg=1
counts["kernel.trace("lock:lock_acquire")"] @count=142050 @min=1 @max=1
@sum=142050 @avg=1
counts["kernel.trace("lock:lock_acquired")"] @count=54136 @min=1 @max=1
@sum=54136 @avg=1
counts["kernel.trace("preemptirq:irq_enable")"] @count=53906 @min=1 @max=1
@sum=53906 @avg=1
counts["kernel.trace("preemptirq:irq_disable")"] @count=53906 @min=1 @max=1
@sum=53906 @avg=1
counts["kernel.trace("rcu:rcu_utilization")"] @count=6894 @min=1 @max=1
@sum=6894 @avg=1
counts["kernel.trace("msr:write_msr")"] @count=6275 @min=1 @max=1 @sum=6275
@avg=1
...

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

[Bug runtime/24416] Tests stuck in uprobes_onthefly.exp

[wcohen at redhat dot com]

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

--- Comment #4 from William Cohen <wcohen at redhat dot com> ---
trying to get a scaled down reproducer.  have the following patch in the
uprobes_onthefly.exp to get the stap files that are being run for the various
tests and the will modify the scripts to see if can get a simpler reproducer:

diff --git a/testsuite/systemtap.onthefly/uprobes_onthefly.exp
b/testsuite/systemtap.onthefly/uprobes_onthefly.exp
index 78975e9d9..6dba88a88 100644
--- a/testsuite/systemtap.onthefly/uprobes_onthefly.exp
+++ b/testsuite/systemtap.onthefly/uprobes_onthefly.exp
@@ -16,6 +16,10 @@ if {![installtest_p] || ![inode_uprobes_p]} {
 proc run_stap {subtest args script} {
    global test

+   set fid [open "/home/wcohen/$subtest.stp" "w"]
+   puts $fid $script
+   close $fid
+
    # Now start the application
    set pid [exec ./$test.x &]

@@ -31,7 +35,8 @@ proc run_stap {subtest args script} {
    # threshold in the harder subtests. Disable overload checking.
    set args "$args -DSTP_NO_OVERLOAD"

-   # Run stap and catch any errors (we will rethrow it later)
+    # Run stap and catch any errors (we will rethrow it later)
+    puts "eval exec stap -e {$script} $args"
    set err [catch {eval exec stap -e {$script} $args} out]

    # Kill app

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

[Bug runtime/24416] Tests stuck in uprobes_onthefly.exp

[wcohen at redhat dot com]

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

--- Comment #5 from William Cohen <wcohen at redhat dot com> ---
Created attachment 11722
  --> https://sourceware.org/bugzilla/attachment.cgi?id=11722&action=edit
reproducer script pr24416b.stp

Copied the uprobes_onthefly.x when the uprobes_onthefly.exp was running and had
the modified uprobes_onthefly.exp spit out the scripts running.

Now going removing bits and pieces otf_stress_max_iter_5000.stp to see what
part of the script is causing the problem. This one has the println removed. 
Then run the following to reproduce the problem:

$ ./uprobes_onthefly.x &
$ sudo stap pr24416b.stp -D STP_ON_THE_FLY_INTERVAL=100000
--suppress-handler-errors -w -DDEBUG_STP_ON_THE_FLY -DMAXMAPENTRIES=100000
-DSTP_NO_OVERLOAD

End up with the following in the output of dmesg:

[  276.951464] stap_0066c50c29eeff618305b0bdc059b380_5_1600: loading
out-of-tree module taints kernel.
[  276.951853] stap_0066c50c29eeff618305b0bdc059b380_5_1600: module
verification failed: signature and/or required key missing - tainting kernel
[  277.135240] stap_0066c50c29eeff618305b0bdc059b380_5_1600 (pr24416a.stp):
systemtap: 4.1/0.176, base: 000000007b148777, memory:
768data/448text/0ctx/2063net/11246alloc kb, probes: 1073
[  492.715121] INFO: task kworker/0:2:149 blocked for more than 122 seconds.
[  492.715130]       Tainted: G           OE     5.1.0-0.rc3.git1.1.fc31.x86_64
#1
[  492.715131] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[  492.715133] kworker/0:2     D13080   149      2 0x80000000
[  492.715139] Workqueue: events kprobe_optimizer
[  492.715141] Call Trace:
[  492.715148]  ? __schedule+0x36a/0xbe0
[  492.715152]  ? __lock_acquire+0xd6d/0x1060
[  492.715155]  ? wait_for_completion+0x10d/0x170
[  492.715158]  schedule+0x39/0x80
[  492.715160]  schedule_timeout+0x317/0x4e0
[  492.715165]  ? wait_for_completion+0x10d/0x170
[  492.715167]  ? mark_held_locks+0x50/0x80
[  492.715169]  ? _raw_spin_unlock_irq+0x29/0x40
[  492.715173]  ? wait_for_completion+0x10d/0x170
[  492.715175]  wait_for_completion+0x12c/0x170
[  492.715177]  ? wake_up_q+0x60/0x60
[  492.715182]  __wait_rcu_gp+0x157/0x170
[  492.715186]  synchronize_rcu_tasks+0x35/0x50
[  492.715188]  ? rcu_read_lock_held+0x60/0x60
[  492.715190]  ? __bpf_trace_rcu_utilization+0x10/0x10
[  492.715195]  ? wait_for_completion+0x48/0x170
[  492.715197]  kprobe_optimizer+0x12b/0x280
[  492.715201]  process_one_work+0x272/0x5e0
[  492.715208]  worker_thread+0x50/0x3b0
[  492.715213]  kthread+0x108/0x140
[  492.715215]  ? process_one_work+0x5e0/0x5e0
[  492.715216]  ? kthread_park+0x90/0x90
[  492.715219]  ret_from_fork+0x3a/0x50
[  492.715249] INFO: task stapio:1600 blocked for more than 122 seconds.
[  492.715250]       Tainted: G           OE     5.1.0-0.rc3.git1.1.fc31.x86_64
#1
[  492.715251] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[  492.715252] stapio          D13168  1600   1595 0x80000000
[  492.715255] Call Trace:
[  492.715259]  ? __schedule+0x36a/0xbe0
[  492.715261]  ? kvm_sched_clock_read+0x14/0x30
[  492.715267]  schedule+0x39/0x80
[  492.715269]  schedule_preempt_disabled+0x11/0x20
[  492.715271]  __mutex_lock+0x312/0x930
[  492.715275]  ? register_kprobe+0x1b2/0x630
[  492.715283]  ? register_kprobe+0x1b2/0x630
[  492.715285]  register_kprobe+0x1b2/0x630
[  492.715305]  ? _stp_kmodule_relocate.part.0+0x82/0xb0
[stap_0066c50c29eeff618305b0bdc059b380_5_1600]
[  492.715322]  stapkp_register_probe+0xdd/0x1d0
[stap_0066c50c29eeff618305b0bdc059b380_5_1600]
[  492.715346]  ? _stp_ctl_write_cmd.cold+0x1df/0x209d
[stap_0066c50c29eeff618305b0bdc059b380_5_1600]
[  492.715354]  ? full_proxy_write+0x56/0x80
[  492.715358]  ? vfs_write+0xcb/0x1c0
[  492.715361]  ? ksys_write+0x52/0xc0
[  492.715365]  ? do_syscall_64+0x5c/0xa0
[  492.715368]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  492.715376] 
               Showing all locks held in the system:
[  492.715379] 1 lock held by khungtaskd/18:
[  492.715381]  #0: 0000000090410079 (rcu_read_lock){....}, at:
debug_show_all_locks+0x15/0x174
[  492.715386] 5 locks held by kworker/0:2/149:
[  492.715387]  #0: 00000000071df764 ((wq_completion)events){+.+.}, at:
process_one_work+0x1e9/0x5e0
[  492.715391]  #1: 0000000039ff1fe5 ((optimizing_work).work){+.+.}, at:
process_one_work+0x1e9/0x5e0
[  492.715394]  #2: 00000000eb5a22fb (kprobe_mutex){+.+.}, at:
kprobe_optimizer+0x19/0x280
[  492.715397]  #3: 000000004d3336d3 (cpu_hotplug_lock.rw_sem){++++}, at:
kprobe_optimizer+0x1e/0x280
[  492.715399]  #4: 0000000090fda3fd (module_mutex){+.+.}, at:
kprobe_optimizer+0x2c/0x280
[  492.715409] 4 locks held by stapio/1600:
[  492.715410]  #0: 0000000090ca70bd (&f->f_pos_lock){+.+.}, at:
__fdget_pos+0x4d/0x60
[  492.715414]  #1: 00000000bcaba9e5 (sb_writers#16){.+.+}, at:
vfs_write+0x152/0x1c0
[  492.715417]  #2: 0000000087e54606 (cmd_mutex){+.+.}, at:
_stp_ctl_write_cmd+0xe0/0xb20 [stap_0066c50c29eeff618305b0bdc059b380_5_1600]
[  492.715431]  #3: 00000000eb5a22fb (kprobe_mutex){+.+.}, at:
register_kprobe+0x1b2/0x630

[  492.715435] =============================================

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

[Bug runtime/24416] Tests stuck in uprobes_onthefly.exp

[fche at redhat dot com]

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

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |fche at redhat dot com

--- Comment #6 from Frank Ch. Eigler <fche at redhat dot com> ---
This sounds like a kernel bug, and furthermore one we've encountered recently
with bpf testing too.

Try 
# echo 0 > /proc/sys/debug/kprobes-optimization
on a new vm, and then rerun the test.

We may have to turn back on this staprun/staprun.c kernel-bug workaround.
See also bug #13193, bug #1548.

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

[Bug runtime/24416] Tests stuck in uprobes_onthefly.exp

[wcohen at redhat dot com]

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

--- Comment #7 from William Cohen <wcohen at redhat dot com> ---
Turning off kprobes-optimization allowed both the reproducer and
uprobes_onthefly.exp test to complete.  That seems to indicate there is a
problem with the x86_64 kprobe optimization.

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

[Bug runtime/24416] Tests stuck in uprobes_onthefly.exp

[wcohen at redhat dot com]

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

--- Comment #8 from William Cohen <wcohen at redhat dot com> ---
There is a fedora bug filed for this as it seems to be an issue with the
kernel's kprobe optimization:

https://bugzilla.redhat.com/show_bug.cgi?id=1697531

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

[Bug runtime/24416] Tests stuck in uprobes_onthefly.exp

[wcohen at redhat dot com]

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

William Cohen <wcohen at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED

--- Comment #9 from William Cohen <wcohen at redhat dot com> ---
Disabled kprobe optimization with git commit 288c538926 to prevent this problem
from occurring.  Will reenable once known what specific issue in the kernels is
causing the problem.

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