Bug 17270 - uprobes_onthefly.exp causing hang on ppc64
Summary: uprobes_onthefly.exp causing hang on ppc64
Status: RESOLVED FIXED
Alias: None
Product: systemtap
Classification: Unclassified
Component: runtime (show other bugs)
Version: unspecified
: P2 normal
Target Milestone: ---
Assignee: Unassigned
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-08-14 19:43 UTC by David Smith
Modified: 2015-01-12 16:56 UTC (History)
1 user (show)

See Also:
Host:
Target:
Build:
Last reconfirmed:


Attachments
stap-report output (8.29 KB, text/plain)
2014-10-10 16:52 UTC, Martin Cermak
Details
test log (1.49 KB, application/x-xz)
2015-01-07 19:55 UTC, Martin Cermak
Details

Note You need to log in before you can comment on or make changes to this bug.
Description David Smith 2014-08-14 19:43:40 UTC
While testing some of the new on-the-fly code, I ran the uprobes_onthefly.exp testcase on RHEL7 ppc64 (3.10.0-131.el7.ppc64). The system hung.

Here's what was on the console:
====
[  190.522633] stap_3d75d6d062d98c196aae3c9439721299_5807: module verification failed: signature and/or required key missing - tainting kernel
[  278.406199] stap module notifier triggered in unexpected state 3
[  282.516143] stap module notifier triggered in unexpected state 3
[  291.866004] stap module notifier triggered in unexpected state 3
[  550.950819] hrtimer: interrupt took 1275312 ns
====
Comment 1 David Smith 2014-08-19 15:27:32 UTC
One of the things the test does is turn on on-the-fly debugging using stap's '-D DEBUG_STP_ON_THE_FLY' flag. Without this flag on, I get a different behaviour. The tests fail of course, but the test runs until the system hangs. Here's the console output:

====
[  260.667249] stap_dcf37cae5885f9b67f9894a335ed6337_3602: module verification failed: signature and/or required key missing - tainting kernel
[  347.786372] stap module notifier triggered in unexpected state 3
[  356.786209] stap module notifier triggered in unexpected state 3
[  362.386105] stap module notifier triggered in unexpected state 3
[  440.444905] INFO: rcu_sched detected stalls on CPUs/tasks: { 0 1 6 7} (detected by 3, t=6002 jiffies, g=1634, c=1633, q=0)
[  440.445177] Task dump for CPU 0:
[  440.445267] swapper/0       R  running task        0     0      0 0x00000000
[  440.445362] Call Trace:
[  440.445403] [c000000001283820] [c00000000011d6c8] .idle_balance+0x128/0x240 (unreliable)
[  440.445521] [c0000000012839f0] [c0000000000a4194] .p970_compute_mmcr+0x8d4/0x9f0
[  440.445630] Task dump for CPU 1:
[  440.445679] swapper/1       R  running task        0     0      1 0x00000800
[  440.445775] Call Trace:
[  440.445811] [c00000022df6b870] [c0000000004511c4] .cpumask_next_and+0x94/0xa0 (unreliable)
[  440.445929] [c00000022df6ba40] [c0000000000a4194] .p970_compute_mmcr+0x8d4/0x9f0
[  440.446039] Task dump for CPU 6:
[  440.446085] swapper/6       R  running task        0     0      1 0x00000800
[  440.446180] Call Trace:
[  440.446215] [c00000022df7f870] [c0000000004511c4] .cpumask_next_and+0x94/0xa0 (unreliable)
[  440.446330] [c00000022df7fa40] [c0000000007683cc] .cmsghdr_from_user_compat_to_kern+0x5c/0x350
[  440.446452] Task dump for CPU 7:
[  440.446503] swapper/7       R  running task        0     0      1 0x00000800
[  440.446595] Call Trace:
[  440.446630] [c00000022c003870] [c0000000008ad548] .__schedule+0x898/0xae0 (unreliable)
[  440.446745] [c00000022c003a40] [c0000000000a4194] .p970_compute_mmcr+0x8d4/0x9f0
====
Comment 2 David Smith 2014-08-19 16:09:59 UTC
The uprobes_onthefly.exp testcase is composed of several subtests. All the tests run with 'run_subtest_valid' work fine:

otf_finish_at_start_disabled, otf_finish_at_start_enabled, otf_start_disabled_iter_1, otf_start_enabled_iter_1, otf_start_disabled_iter_2, otf_start_enabled_iter_2, otf_start_disabled_iter_3, otf_start_enabled_iter_3, otf_start_disabled_iter_4, otf_start_enabled_iter_4, otf_start_disabled_iter_5, otf_start_enabled_iter_5, otf_timer_100ms, and otf_timer_50ms

The stress tests (run with 'run_subtset_stress') are where the problem lies. Here is what happens when you run each individually:

- otf_stress_10ms_iter_50: passes
- otf_stress_5ms_iter_50: passes
- otf_stress_1ms_iter_50: passes
- otf_stress_500us_iter_50: passes, but causes the "stap module notifier triggered in unexpected state 3" message on the console
- otf_stress_100us_iter_50: ditto
- otf_stress_prof_iter_2000: ditto
- otf_stress_hard_iter_2000: hangs the system with the following on the console:

[ 1902.414132] INFO: rcu_sched detected stalls on CPUs/tasks: { 0 2 5 6} (detected by 4, t=6002 jiffies, g=4654, c=4653, q=0)
[ 1902.414422] Task dump for CPU 0:
[ 1902.414471] swapper/0       R  running task        0     0      0 0x00000000
[ 1902.414570] Call Trace:
[ 1902.414616] [c000000001283820] [c00000000046cc78] .find_next_bit+0x38/0xf0 (unreliable)
[ 1902.414734] [c0000000012839f0] [c0000000000a4194] .p970_compute_mmcr+0x8d4/0x9f0
[ 1902.414844] Task dump for CPU 2:
[ 1902.414889] swapper/2       R  running task        0     0      1 0x00000800
[ 1902.414986] Call Trace:
[ 1902.415022] [c00000022df6f870] [c0000000008ad580] .__schedule+0x8d0/0xae0 (unreliable)
[ 1902.415131] [c00000022df6fa40] [c0000000000a4194] .p970_compute_mmcr+0x8d4/0x9f0
[ 1902.415243] Task dump for CPU 5:
[ 1902.415290] swapper/5       R  running task        0     0      1 0x00000800
[ 1902.415387] Call Trace:
[ 1902.415429] [c00000022df7b870] [000001ac274bfdaa] 0x1ac274bfdaa (unreliable)
[ 1902.415538] [c00000022df7ba40] [c0000000000a4194] .p970_compute_mmcr+0x8d4/0x9f0
[ 1902.415647] Task dump for CPU 6:
[ 1902.415693] swapper/6       R  running task        0     0      1 0x00000800
[ 1902.415785] Call Trace:
[ 1902.415818] [c00000022df7f870] [c0000000008ad574] .__schedule+0x8c4/0xae0 (unreliable)
[ 1902.415925] [c00000022df7fa40] [c0000000000a4194] .p970_compute_mmcr+0x8d4/0x9f0

- otf_stress_max_iter_5000: causes a system hang with no output on the console

(BTW, the unexpected state 3 in the "stap module notifier triggered in unexpected state 3" message is STAP_SESSION_STOPPING.)
Comment 3 David Smith 2014-08-26 14:32:57 UTC
OK, I think I know what is going on here. I think there are actually 2 separate problems here:

1) The "stap module notifier triggered in unexpected state 3" message happens when the session is shutting down but the uprobe hasn't been unregistered yet. I think we can change the code to not output this message if we in the STAP_SESSION_STOPPING state.

2) The hang happens in the 'otf_stress_hard_iter_2000' and 'otf_stress_max_iter_5000' subtests. These tests also probe 'kernel.trace("*")', and are hitting bug #17126 (tracepoints.exp testcase causing stalls/hang on ppc64). When that one gets solved, the hangs should stop here also. If I take the 'kernel.trace("*")' probing out of those subtests, they pass just fine.
Comment 4 Jonathan Lebon 2014-09-01 17:28:32 UTC
Hey David,

Glad you found the cause of the issue.

> 1) The "stap module notifier triggered in unexpected state 3" message happens
> when the session is shutting down but the uprobe hasn't been unregistered
> yet.

This can also occur if there is still a work item left on the workqueue after
we changed to the STAP_SESSION_STOPPING state. This is probably why this
error message occurs more frequently during stress subtests.

> I think we can change the code to not output this message if we in the
> STAP_SESSION_STOPPING state.

Agreed!

Jonathan
Comment 5 Martin Cermak 2014-09-04 12:27:24 UTC
Not only uprobes_onthefly.exp, but also hrtimer_onthefly.exp seems to cause stalls on ppc64 pretty regualrly. For reference see e.g. https://url.corp.redhat.com/d8cbb4b.
Comment 6 Martin Cermak 2014-10-10 16:52:54 UTC
Created attachment 7826 [details]
stap-report output

hrtimer_onthefly.exp causes kernel crash on s390x too:

[ 2362.636690] stap module notifier triggered in unexpected state 3 
[ 2365.185234] stap module notifier triggered in unexpected state 3 
[ 2365.185331] stap module notifier triggered in unexpected state 3 
[ 2365.195695] Unable to handle kernel pointer dereference at virtual kernel add 
ress           (null) 
[ 2365.195737] Oops: 0004 [#1] SMP 
[ 2365.195740] Modules linked in: stap_67b0151b97c8e1dde8dcd8264a8bbe13__32658(O 
F) nfsv3 rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache binfmt_misc ipt_MASQUERA 
DE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack 
nf_conntrack ipt_REJECT xt_CHECKSUM iptable_mangle tun bridge stp llc ip6table_f 
ilter ip6_tables iptable_filter ip_tables ebtable_nat ebtables sg qeth_l2 vmur n 
fsd auth_rpcgss nfs_acl lockd sunrpc xfs libcrc32c dasd_fba_mod lcs ctcm fsm das 
d_eckd_mod qeth qdio dasd_mod ccwgroup dm_mirror dm_region_hash dm_log dm_mod [l 
ast unloaded: stap_cd7de823793eceac21f7a774e5b77a25__27834] 
[ 2365.195807] CPU: 0 PID: 32658 Comm: stapio Tainted: GF          O------------ 
--   3.10.0-123.8.1.el7.s390x #1 
[ 2365.195813] task: 000000007ced8910 ti: 000000005dbd4000 task.ti: 000000005dbd 
4000 
[ 2365.195886] Krnl PSW : 0704d00180000000 00000000005af91e (mutex_lock+0x2e/0x6 
0) 
[ 2365.195892]            R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:1 PM:0 EA: 
3 
Krnl GPRS: 0000000000000081 0000000000000001 00000000ffffffff 0000000000000000 
[ 2365.195896]            0000000000999f70 0000000000000001 0000000000000000 000 
0000000000000 
[ 2365.195905]            0000000000000008 0000000000000020 0000000000000001 000 
003ffffbebd74 
[ 2365.195925]            000000005dbd7d68 0000000000000020 000000005dbd7ca0 000 
000005dbd7c80 
[ 2365.195936] Krnl Code: 00000000005af916: 5830d000            l       %r3,0(%r 
13) 
           00000000005af91a: 1823               lr      %r2,%r3 
          #00000000005af91c: 1b21               sr      %r2,%r1 
          >00000000005af91e: ba32d000           cs      %r3,%r2,0(%r13) 
           00000000005af922: a744fffc           brc     4,5af91a 
           00000000005af926: ec24000d007e       cij     %r2,0,4,5af940 
           00000000005af92c: e31003100004       lg      %r1,784 
           00000000005af932: e310d018002401: HCPGSP2629I The virtual machine is 
placed in CP mode due to a SIGP stop from 
 CPU 01. 
       stg     %r1,24(%r13) 
[ 2365.196063] Call Trace: 
[ 2365.196065] ([<0000000000936ba8>] uaccess+0x0/0x50) 
[ 2365.196069]  [<0000000000150ff0>] flush_workqueue+0x78/0x5a8 
[ 2365.196073]  [<000003ff803050de>] _stp_cleanup_and_exit+0xe6/0x5f8 [stap_67b0 
151b97c8e1dde8dcd8264a8bbe13__32658] 
[ 2365.196094]  [<000003ff8030581c>] _stp_ctl_write_cmd+0x22c/0x458 [stap_67b015 
1b97c8e1dde8dcd8264a8bbe13__32658] 
[ 2365.196111]  [<000000000027650a>] vfs_write+0xa2/0x1c8 
[ 2365.196116]  [<0000000000277018>] SyS_write+0x60/0xb0 
[ 2365.196119]  [<00000000005b28a4>] sysc_tracego+0x14/0x1a 
[ 2365.196124]  [<000003fffd76f3e8>] 0x3fffd76f3e8 
[ 2365.196129] Last Breaking-Event-Address: 
[ 2365.196132]  [<0000000000150fea>] flush_workqueue+0x72/0x5a8 
[ 2365.196136] 
[ 2365.196139] Kernel panic - not syncing: Fatal exception: panic_on_oops 
[ 2365.196201] Stap trace buffer for processor 0 sub-buffer 0: 
[ 2365.196205] The following may not have been sent to the display: 
[ 2365.196208] toggling 
[ 2365.196212] systemtap_module_init:59253: not starting (hrtimer) pidx 0 
[ 2365.196236] toggling 
[ 2365.196237] toggling 
[ 2365.196242] toggling 
[ 2365.196254] toggling 
[ 2365.196255] toggling 
[ 2365.196256] toggling 
[ 2365.196257] toggling 
[ 2365.196257] toggling 
[ 2365.196258] toggling 
[ 2365.196259] toggling 
[ 2365.196259] toggling 
[ 2365.196260] toggling 
[ 2365.196261] toggling 
[ 2365.196262] toggling 
[ 2365.196262] toggling 

[ ... ]
Comment 7 Martin Cermak 2014-10-13 10:30:17 UTC
Another, very similar issue: kprobes_onthefly.exp causes kernel oops on s390x (stap-0f2e612, 3.10.0-123.8.1.el7.s390x):

[-- MARK -- Mon Oct 13 10:05:00 2014] 
[ 2038.634784] stap_cdf292d12c8ba9d0963faee8c05fb1c7_10782: module verification 
failed: signature and/or required key missing - tainting kernel 
[-- MARK -- Mon Oct 13 10:10:00 2014] 
[ 2184.533935] Unable to handle kernel pointer dereference at virtual kernel add 
ress           (null) 
[ 2184.534007] Oops: 0004 [#1] SMP 
[ 2184.534011] Modules linked in: stap_5053927516a0f778e4fccdbbd2ca2985__62883(O 
F) nfsv3 rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ipt_MASQUERADE iptable_n 
at nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack 
 ipt_REJECT xt_CHECKSUM iptable_mangle tun bridge stp llc ip6table_filter ip6_ta 
bles iptable_filter ip_tables ebtable_nat ebtables sg qeth_l2 vmur nfsd auth_rpc 
gss nfs_acl lockd sunrpc xfs libcrc32c dasd_fba_mod dasd_eckd_mod dasd_mod qeth 
qdio lcs ctcm ccwgroup fsm dm_mirror dm_region_hash dm_log dm_mod [last unloaded 
: stap_b8a904592537701ddfebecd680ea95e2__40242] 
[ 2184.534087] CPU: 0 PID: 62883 Comm: stapio Tainted: GF          O------------ 
--   3.10.0-123.8.1.el7.s390x #1 
[ 2184.534093] task: 0000000075361220 ti: 00000000510c8000 task.ti: 00000000510c 
8000 
[ 2184.534097] Krnl PSW : 0704d00180000000 00000000005af91e (mutex_lock+0x2e/0x6 
0) 
[ 2184.534151]            R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:1 PM:0 EA: 
3 
Krnl GPRS: 0000000000000081 0000000000000001 00000000ffffffff 0000000000000000 
[ 2184.534159]            0000000000999f70 0000000000000001 0000000000000000 000 
0000000000000 
[ 2184.534161]            0000000000000008 0000000000000020 0000000000000001 000 
003ffff8ac4d4 
[ 2184.534163]            00000000510cbd68 0000000000000020 00000000510cbca0 000 
00000510cbc80 
[ 2184.534196] Krnl Code: 00000000005af916: 5830d000            l       %r3,0(%r 
13) 
           00000000005af91a: 1823               lr      %r2,%r3 
          #00000000005af91c: 1b21               sr      %r2,%r1 
          >00000000005af91e: ba32d000           cs      %r3,%r2,0(%r13) 
           00000000005af922: a744fffc           brc     4,5af91a 
           00000000005af926: ec24000d007e       cij     %r2,0,4,5af940 
           00000000005af92c: e31003100004       lg      %r1,784 
           00000000005af932: e310d0180024       stg     %r1,24(%r13) 
[ 2184.534264] Call Trace: 
01: HCPGSP2629I The virtual machine is placed in CP mode due to a SIGP stop from 
 CPU 01. 
[ 2184.534300] ([<0000000000936ba8>] uaccess+0x0/0x50) 
[ 2184.534330]  [<0000000000150ff0>] flush_workqueue+0x78/0x5a8 
[ 2184.534334]  [<000003ff80252ce6>] _stp_cleanup_and_exit+0xe6/0x608 [stap_505 
927516a0f778e4fccdbbd2ca2985__62883] 
[ 2184.534391]  [<000003ff80253434>] _stp_ctl_write_cmd+0x22c/0x458 [stap_505392 
7516a0f778e4fccdbbd2ca2985__62883] 
[ 2184.534417]  [<000000000027650a>] vfs_write+0xa2/0x1c8 
[ 2184.534423]  [<0000000000277018>] SyS_write+0x60/0xb0 
[ 2184.534426]  [<00000000005b28a4>] sysc_tracego+0x14/0x1a 
[ 2184.534431]  [<000003fffd0483e8>] 0x3fffd0483e8 
[ 2184.534440] Last Breaking-Event-Address: 
[ 2184.534443]  [<0000000000150fea>] flush_workqueue+0x72/0x5a8 
[ 2184.534448] 
[ 2184.534450] Kernel panic - not syncing: Fatal exception: panic_on_oops 
[ 2184.534528] Stap trace buffer for processor 0 sub-buffer 0: 
[ 2184.534533] hit 
[ 2184.534536] rethit 
[ 2184.534540] toggling 
[ 2184.534543] toggling 
[ 2184.534546] hit 
[ 2184.534549] rethit 
[ 2184.534553] toggling 
[ 2184.534556] toggling 
[ 2184.534560] hit 
[ 2184.534596] rethit 
[ 2184.534597] toggling 
[ 2184.534615] toggling 

[ ... ]


=======

(gdb) list *(flush_workqueue+0x72)
0x150fea is in flush_workqueue (kernel/workqueue.c:2581).
2581            mutex_lock(&wq->mutex);
Comment 8 David Smith 2014-12-17 17:46:40 UTC
Commit e6f437a works around this problem, by:

1) As mentioned in comment #4, the "stap module notifier triggered in unexpected state 3" message will not be printed in the STAP_SESSION_STOPPING state.

2) The fix for bug #17126 fixed the probing of 'kernel.trace("*")' issues by adding a tracepoint blacklist. However, the 'onthefly' tests use systemtap's '-g' option, which disables the tracepoint blacklist. So, the commit modifies the 'onthefly' tests to not probe the h* tracepoints on ppc64.
Comment 9 Martin Cermak 2015-01-07 19:55:43 UTC
Created attachment 8053 [details]
test log

Using kernel-3.10.0-220.el7.ppc64 and stap based on commit 772e206 I'm getting following results for the hrtimer testcases:

=======

make RUNTESTFLAGS='hrtimer_onthefly.exp kprobes_onthefly.exp uprobes_onthefly.exp' installcheck

... stuff deleted ...

Running ./systemtap.onthefly/hrtimer_onthefly.exp ...
Running ./systemtap.onthefly/kprobes_onthefly.exp ...
FAIL: kprobes_onthefly - otf_finish_at_start_disabled (invalid output)
FAIL: kprobes_onthefly - otf_start_disabled_iter_1 (invalid output)
FAIL: kprobes_onthefly - otf_start_enabled_iter_1 (invalid output)
FAIL: kprobes_onthefly - otf_start_disabled_iter_2 (invalid output)
FAIL: kprobes_onthefly - otf_start_enabled_iter_2 (invalid output)
FAIL: kprobes_onthefly - otf_start_disabled_iter_3 (invalid output)
FAIL: kprobes_onthefly - otf_start_enabled_iter_3 (invalid output)
FAIL: kprobes_onthefly - otf_start_disabled_iter_4 (invalid output)
FAIL: kprobes_onthefly - otf_start_enabled_iter_4 (invalid output)
FAIL: kprobes_onthefly - otf_start_disabled_iter_5 (invalid output)
FAIL: kprobes_onthefly - otf_start_enabled_iter_5 (invalid output)
FAIL: kprobes_onthefly - otf_timer_100ms (invalid output)
FAIL: kprobes_onthefly - otf_timer_50ms (invalid output)
FAIL: kprobes_onthefly - otf_timer_10ms (invalid output)
Running ./systemtap.onthefly/uprobes_onthefly.exp ...

                === systemtap Summary ===

# of expected passes            54
# of unexpected failures        14

=======

Full test log attached.
Comment 10 David Smith 2015-01-08 21:15:31 UTC
(In reply to Martin Cermak from comment #9)
> Created attachment 8053 [details]
> test log
> 
> Using kernel-3.10.0-220.el7.ppc64 and stap based on commit 772e206 I'm
> getting following results for the hrtimer testcases:

... test failures reported ...

Could you create a new bug with these failures? If the uprobes_onthefly.exp test didn't hang the system, this bug is fixed. Plus, this bug is filed against uprobes_onthefly.exp, and your failures are in kprobes_onthefly.exp (although your description above says it happened in the hrtimer testcase). If the kprobes_onthefly.exp problems were related to this bug, the system would have hung, you wouldn't have just gotten test failures.
Comment 11 Martin Cermak 2015-01-12 16:56:37 UTC
Yup, filed PR17831. Thank you for fixing this one. Verified.