Bug 18460 - tracepoint_onthefly.exp kernel crash
Summary: tracepoint_onthefly.exp kernel crash
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: 2015-05-28 07:47 UTC by Martin Cermak
Modified: 2015-06-15 19:29 UTC (History)
2 users (show)

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


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Cermak 2015-05-28 07:47:07 UTC
With recent upstream bits I see tracepoint_onthefly.exp causing kernel crash on ppc64(le/be) pretty reliably. E.g. using release-2.7-157-g35bd6e1548e9 (or in beaker using older 22cabe6) on top of 3.10.0-229.el7.ppc64 I see:

=======
ibm-p730-06-lp2 login: [1645691.300056] INFO: rcu_sched detected stalls on CPUs/tasks: { 0 2 3 4 5 6 7 8 9 10 11 12
[1645691.300159] Task dump for CPU 0:                                           
[1645691.300166] swapper/0       R  running task        0     0      0 0x00000000
[1645691.300180] Call Trace:                                                    
[1645691.300194] [c00000000130b840] [0005d8af9a1ddff2] 0x5d8af9a1ddff2 (unreliable)
[1645691.300208] [c00000000130ba10] [0000000022002082] 0x22002082               
[1645691.300218] Task dump for CPU 2:                                           
[1645691.300225] swapper/2       R  running task        0     0      1 0x00000804
[1645691.300238] Call Trace:                                                    
[1645691.300248] [c0000003f8d8f890] [c00000000048e63c] .find_next_bit+0x5c/0xf0 (unreliable)
[1645691.300261] [c0000003f8d8fa60] [0000000022000082] 0x22000082               
[1645691.300272] Task dump for CPU 3:                                           
[1645691.300278] swapper/3       R  running task        0     0      1 0x00000800
[1645691.300291] Call Trace:                                                    
[1645691.300298] [c0000003f8d93890] [c0000000004726e8] .cpumask_next_and+0x28/0xa0 (unreliable)
[1645691.300313] [c0000003f8d93a60] [0000000022000082] 0x22000082               
[1645691.300322] Task dump for CPU 4:                                           
[1645691.300329] swapper/4       R  running task        0     0      1 0x00000800
[1645691.300342] Call Trace:                                                    
[1645691.300350] [c0000003f8d97890] [c000000000123d94] .update_cfs_rq_blocked_load+0x34/0x160 (unreliable)
[1645691.300365] [c0000003f8d97a60] [0000000022000082] 0x22000082               
[1645691.300375] Task dump for CPU 5:                                           
[1645691.300381] swapper/5       R  running task        0     0      1 0x00000800
[1645691.300394] Call Trace:                                                    
[1645691.300402] [c0000003f8d9b890] [c0000000008eeb90] .__schedule+0x180/0xa50 (unreliable)
[1645691.300416] [c0000003f8d9ba60] [0000000022000082] 0x22000082               
[1645691.300426] Task dump for CPU 6:                                           
[1645691.300432] swapper/6       R  running task        0     0      1 0x00000800
[1645691.300445] Call Trace:                                                    
[1645691.300453] [c0000003f8d9f890] [c000000000123e84] .update_cfs_rq_blocked_load+0x124/0x160 (unreliable)
[1645691.300468] [c0000003f8d9fa60] [0000000022000082] 0x22000082               
[1645691.300478] Task dump for CPU 7:                                           
[1645691.300484] swapper/7       R  running task        0     0      1 0x00000800
[1645691.300497] Call Trace:                                                    
[1645691.300504] [c0000003f8da3890] [c0000000008eeb90] .__schedule+0x180/0xa50 (unreliable)
[1645691.300518] [c0000003f8da3a60] [0000000022000082] 0x22000082               
[1645691.300527] Task dump for CPU 8:                                           
[1645691.300534] swapper/8       R  running task        0     0      1 0x00000800
[1645691.300546] Call Trace:                                                    
[1645691.300555] [c0000003f8da7890] [c00000000130ae00] init_thread_union+0x2e00/0x4000 (unreliable)
[1645691.300569] [c0000003f8da7a60] [0000000022000082] 0x22000082               
[1645691.300579] Task dump for CPU 9:                                           
[1645691.300585] swapper/9       R  running task        0     0      1 0x00000800
[1645691.300598] Call Trace:                                                    
[1645691.300606] [c0000003f8dab890] [c0000000000698c8] .memcpy_power7+0x128/0x7e0 (unreliable)
[1645691.300620] [c0000003f8daba60] [0000000022000082] 0x22000082               
[1645691.300630] Task dump for CPU 10:                                          
[1645691.300637] swapper/10      R  running task        0     0      1 0x00000800
[1645691.300649] Call Trace:                                                    
[1645691.300656] [c0000003f8daf890] [0005d8a88c18a8f0] 0x5d8a88c18a8f0 (unreliable)
[1645691.300669] [c0000003f8dafa60] [0000000022000082] 0x22000082               
[1645691.300679] Task dump for CPU 11:                                          
[1645691.300685] swapper/11      R  running task        0     0      1 0x00000800
[1645691.300698] Call Trace:                                                    
[1645691.300705] [c0000003f8db3890] [c0000000000684c4] .memset+0xd4/0xfc (unreliable)
[1645691.300718] [c0000003f8db3a60] [0000000022000082] 0x22000082               
[1645691.300728] Task dump for CPU 12:                                          
[1645691.300734] swapper/12      R  running task        0     0      1 0x00000800
[1645691.300747] Call Trace:                                                    
[1645691.300754] [c0000003f8db7890] [c00000000013af60] .cpuacct_charge+0x50/0x60 (unreliable)
[1645691.300768] [c0000003f8db7a60] [0000000022000082] 0x22000082               
[1645691.300778] Task dump for CPU 13:                                          
[1645691.300784] swapper/13      R  running task        0     0      1 0x00000800
[1645691.300797] Call Trace:                                                    
[1645691.300804] [c0000003f8dbb890] [c0000000008eeb54] .__schedule+0x144/0xa50 (unreliable)
[1645691.300818] [c0000003f8dbba60] [0000000022000082] 0x22000082               
[1645691.300828] Task dump for CPU 14:                                          
[1645691.300834] swapper/14      R  running task        0     0      1 0x00000800
[1645691.300846] Call Trace:                                                    
[1645691.300854] [c0000003f8dbf890] [c0000000008eeb90] .__schedule+0x180/0xa50 (unreliable)
[1645691.300867] [c0000003f8dbfa60] [0000000022000082] 0x22000082               
[1645691.300877] Task dump for CPU 15:                                          
[1645691.300883] swapper/15      R  running task        0     0      1 0x00000800
[1645691.300896] Call Trace:                                                    
[1645691.300903] [c0000003f8dc3890] [c00000000048e69c] .find_next_bit+0xbc/0xf0 (unreliable)
[1645691.300916] [c0000003f8dc3a60] [0000000022000082] 0x22000082               
[1645691.300926] Task dump for CPU 16:                                          
[1645691.300932] swapper/16      R  running task        0     0      1 0x00000800
[1645691.300945] Call Trace:                                                    
[1645691.300955] [c0000003f8dc7890] [c000000000129ba4] .update_curr+0xb4/0x2c0 (unreliable)
[1645691.300968] [c0000003f8dc7a60] [0000000022000082] 0x22000082
[1645691.300978] Task dump for CPU 17:                                          
[1645691.300984] swapper/17      R  running task        0     0      1 0x00000800
[1645691.300997] Call Trace:                                                    
[1645691.301004] [c0000003f8dcb890] [c00000000011b26c] .idle_cpu+0x5c/0x60 (unreliable)
[1645691.301017] [c0000003f8dcba60] [0000000022000082] 0x22000082               
[1645691.301027] Task dump for CPU 18:                                          
[1645691.301033] swapper/18      R  running task        0     0      1 0x00000800
[1645691.301046] Call Trace:                                                    
[1645691.301053] [c0000003f8dcf890] [c00000000012f0b0] .find_busiest_group+0x560/0x980 (unreliable)
[1645691.301067] [c0000003f8dcfa60] [0000000022000082] 0x22000082               
[1645691.301077] Task dump for CPU 19:                                          
[1645691.301083] swapper/19      R  running task        0     0      1 0x00000800
[1645691.301096] Call Trace:                                                    
[1645691.301103] [c0000003f8dd3890] [c000000000114798] .update_rq_clock+0x78/0x80 (unreliable)
[1645691.301117] [c0000003f8dd3a60] [0000000022000082] 0x22000082               
[1645691.301127] Task dump for CPU 20:                                          
[1645691.301133] swapper/20      R  running task        0     0      1 0x00000804
[1645691.301146] Call Trace:                                                    
[1645691.301153] [c0000003f8dd7890] [c0000000008f20d4] ._raw_spin_lock_irqsave+0x84/0x110 (unreliable)
[1645691.301168] [c0000003f8dd7a60] [0000000022000082] 0x22000082               
[1645691.301178] Task dump for CPU 22:                                          
[1645691.301184] stapio          R  running task        0 18042  27117 0x00008084
[1645691.301197] Call Trace:                                                    
[1645691.301203] [c000000344fff490] [0002855ba342a604] 0x2855ba342a604 (unreliable)
[1645691.301215] Task dump for CPU 23:                                          
[1645691.301221] swapper/23      R  running task        0     0      1 0x00000804
[1645691.301234] Call Trace:                                                    
[1645691.301241] [c0000003f8de3890] [c000000000129c88] .update_curr+0x198/0x2c0 (unreliable)
[1645691.301254] [c0000003f8de3a60] [0000000022000082] 0x22000082               
[1645691.301264] Task dump for CPU 24:                                          
[1645691.301270] swapper/24      R  running task        0     0      1 0x00000800
[1645691.301283] Call Trace:                                                    
[1645691.301290] [c0000003f8de7890] [c00000000012ea14] .update_group_power+0x154/0x290 (unreliable)
[1645691.301305] [c0000003f8de7a60] [0000000022000082] 0x22000082               
[1645691.301314] Task dump for CPU 25:                                          
[1645691.301321] swapper/25      R  running task        0     0      1 0x00000800
[1645691.301333] Call Trace:                                                    
[1645691.301340] [c0000003f8deb890] [c0000000008eebc8] .__schedule+0x1b8/0xa50 (unreliable)
[1645691.301354] [c0000003f8deba60] [0000000022000082] 0x22000082               
[1645691.301363] Task dump for CPU 26:                                          
[1645691.301370] swapper/26      R  running task        0     0      1 0x00000800
[1645691.301382] Call Trace:                                                    
[1645691.301389] [c0000003f8def890] [c00000000012a6ec] .dequeue_task_fair+0x35c/0xf30 (unreliable)
[1645691.301404] [c0000003f8defa60] [0000000022000082] 0x22000082               
[1645691.301414] Task dump for CPU 27:                                          
[1645691.301420] swapper/27      R  running task        0     0      1 0x00000800
[1645691.301432] Call Trace:                                                    
[1645691.301439] [c0000003f8df3890] [c00000000012ed44] .find_busiest_group+0x1f4/0x980 (unreliable)
[1645691.301455] [c0000003f8df3a60] [0000000022000082] 0x22000082
=======

systemtap.log reads:

=======
Test Run By root on Thu May 28 03:21:55 2015
Native configuration is powerpc64-unknown-linux-gnu

                === systemtap tests === 

Schedule of variations:
    unix

Running target unix
Using /usr/share/dejagnu/baseboards/unix.exp as board description file for target.
Using /usr/share/dejagnu/config/unix.exp as generic interface file for target.
Using ./config/unix.exp as tool-and-target-specific interface file.

Host: Linux ibm-p730-06-lp2.rhts.eng.bos.redhat.com 3.10.0-229.el7.ppc64 #1 SMP Thu Jan 29 18:40:45 EST 2015 ppc64 ppc64 ppc64 GNU/Linux
Snapshot: version 2.8/0.160, commit release-2.7-157-g35bd6e1548e9 + changes
GCC: 4.8.3 [gcc (GCC) 4.8.3 20140911 (Red Hat 4.8.3-9)]
Distro: Red Hat Enterprise Linux Server release 7.1 (Maipo)
SElinux: Disabled


Running ./systemtap.onthefly/tracepoint_onthefly.exp ... 
Executing: kill -INT 17195
Executing: kill -KILL 17195
expected more patterns
got to pattern index -1, but there are 1 patterns
KFAIL: tracepoint_onthefly - otf_finish_at_start_disabled (invalid output) (PRMS: 17256)
Executing: kill -INT 28628
Executing: kill -KILL 28628
PASS: tracepoint_onthefly - otf_finish_at_start_enabled (valid output)
Executing: kill -INT 4068
Executing: kill -KILL 4068
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_1 (invalid output) (PRMS: 17256)
Executing: kill -INT 12361
Executing: kill -KILL 12361
expected more patterns
got to pattern index 1, but there are 3 patterns
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_1 (invalid output) (PRMS: 17256)
Executing: kill -INT 20984
Executing: kill -KILL 20984
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_2 (invalid output) (PRMS: 17256)
Executing: kill -INT 30046
Executing: kill -KILL 30046
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_2 (invalid output) (PRMS: 17256)
Executing: kill -INT 6538
Executing: kill -KILL 6538
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_3 (invalid output) (PRMS: 17256)
Executing: kill -INT 16029
Executing: kill -KILL 16029
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_3 (invalid output) (PRMS: 17256)
Executing: kill -INT 25734
Executing: kill -KILL 25734
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_4 (invalid output) (PRMS: 17256)
Executing: kill -INT 3446
Executing: kill -KILL 3446
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_4 (invalid output) (PRMS: 17256)
Executing: kill -INT 13612
Executing: kill -KILL 13612
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_5 (invalid output) (PRMS: 17256)
Executing: kill -INT 24473
Executing: kill -KILL 24473
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_5 (invalid output) (PRMS: 17256)
Executing: kill -INT 2772
Executing: kill -KILL 2772
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_timer_100ms (invalid output) (PRMS: 17256)
Executing: kill -INT 10607
Executing: kill -KILL 10607
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_timer_50ms (invalid output) (PRMS: 17256)
Executing: kill -INT 18132
Executing: kill -KILL 18132
kill: kill: sending signal to 18132 failed: No such process
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_timer_10ms (invalid output) (PRMS: 17256)
Executing: kill -INT 23737
Executing: kill -KILL 23737
PASS: tracepoint_onthefly - otf_stress_5ms_iter_50 (survived)
Executing: kill -INT 30983
Executing: kill -KILL 30983
PASS: tracepoint_onthefly - otf_stress_1ms_iter_50 (survived)
Executing: kill -INT 5593
Executing: kill -KILL 5593
PASS: tracepoint_onthefly - otf_stress_500us_iter_50 (survived)
Executing: kill -INT 12659
Executing: kill -KILL 12659
PASS: tracepoint_onthefly - otf_stress_100us_iter_50 (survived)
Executing: kill -INT 19950
Executing: kill -KILL 19950
PASS: tracepoint_onthefly - otf_stress_prof_iter_2000 (survived)
=======
Comment 1 Martin Cermak 2015-05-28 10:15:42 UTC
Similarly with the le variant. Console log:

=======
ibm-p8-02-lp5 login: [ 8974.587583] stap_987159ae59b6ed78cce563f4494bef79_6005: module verification failed: signature and/or required key missing - tainting kernel
[ 9110.631939] INFO: rcu_sched detected stalls on CPUs/tasks: { 0 1 3 4 5 6 7 8 9 10 11 13 14 15} (detected by 12, t=6002 jiffies, g=14427, c=14426, q=0)
[ 9110.632023] Task dump for CPU 0:
[ 9110.632031] swapper/0       R  running task        0     0      0 0x00000004
[ 9110.632046] Call Trace:
[ 9110.632059] [c0000000010ab9c0] [c0000000010abcc0] init_thread_union+0x3cc0/0x4000 (unreliable)
[ 9110.632074] Task dump for CPU 1:
[ 9110.632081] swapper/1       R  running task        0     0      1 0x00000800
[ 9110.632095] Call Trace:
[ 9110.632105] [c0000004755afa00] [c0000004755afa40] 0xc0000004755afa40 (unreliable)
[ 9110.632118] Task dump for CPU 3:
[ 9110.632125] swapper/3       R  running task        0     0      1 0x00000804
[ 9110.632139] Call Trace:
[ 9110.632147] [c0000004755b7a00] [c0000004755b7a40] 0xc0000004755b7a40 (unreliable)
[ 9110.632161] Task dump for CPU 4:
[ 9110.632168] swapper/4       R  running task        0     0      1 0x00000800
[ 9110.632181] Call Trace:
[ 9110.632190] [c0000004755bba00] [c0000004755bba40] 0xc0000004755bba40 (unreliable)
[ 9110.632203] Task dump for CPU 5:
[ 9110.632210] swapper/5       R  running task        0     0      1 0x00000800
[ 9110.632223] Call Trace:
[ 9110.632231] [c0000004755bfa00] [c0000004755bfa40] 0xc0000004755bfa40 (unreliable)
[ 9110.632244] Task dump for CPU 6:
[ 9110.632251] swapper/6       R  running task        0     0      1 0x00000800
[ 9110.632265] Call Trace:
[ 9110.632273] [c0000004755c3a00] [c0000004755c3a40] 0xc0000004755c3a40 (unreliable)
[ 9110.632286] Task dump for CPU 7:
[ 9110.632294] swapper/7       R  running task        0     0      1 0x00000800
[ 9110.632307] Call Trace:
[ 9110.632315] [c0000004755c7a00] [c0000004755c7a40] 0xc0000004755c7a40 (unreliable)
[ 9110.632328] Task dump for CPU 8:
[ 9110.632335] swapper/8       R  running task        0     0      1 0x00000800
[ 9110.632348] Call Trace:
[ 9110.632356] [c0000004755cba00] [c0000004755cba40] 0xc0000004755cba40 (unreliable)
[ 9110.632370] Task dump for CPU 9:
[ 9110.632376] swapper/9       R  running task        0     0      1 0x00000804
[ 9110.632390] Call Trace:
[ 9110.632398] [c0000004755cfa00] [c0000004755cfa40] 0xc0000004755cfa40 (unreliable)
[ 9110.632411] Task dump for CPU 10:
[ 9110.632418] swapper/10      R  running task        0     0      1 0x00000808
[ 9110.632432] Call Trace:
[ 9110.632440] [c0000004755d3a00] [c0000004755d3a40] 0xc0000004755d3a40 (unreliable)
[ 9110.632453] Task dump for CPU 11:
[ 9110.632460] swapper/11      R  running task        0     0      1 0x00000800
[ 9110.632473] Call Trace:
[ 9110.632482] [c0000004755d7a00] [c0000004755d7a40] 0xc0000004755d7a40 (unreliable)
[ 9110.632495] Task dump for CPU 13:
[ 9110.632502] stapio          R  running task        0 148680 147101 0x00048080
[ 9110.632515] Call Trace:
[ 9110.632526] [c000000419577620] [c000000000c7ab00] runqueues+0x0/0xa80 (unreliable)
[ 9110.632543] [c0000004195777f0] [c000000000058bbc] hash_page+0x6ec/0x780
[ 9110.632558] [c0000004195778d0] [c00000000000954c] do_hash_page+0x4c/0x58
[ 9110.632663] --- Exception: 301 at _stp_runtime_entryfn_get_context+0x28/0x60 [stap_7237c4e9d18d6bbb2bba7683d3407101_148680]
[ 9110.632663]     LR = enter_real_tracepoint_probe_248+0x74/0x260 [stap_7237c4e9d18d6bbb2bba7683d3407101_148680]
[ 9110.632734] [c000000419577bc0] [d00000000f461360] _stp_hrtimer_start+0xb0/0x130 [stap_7237c4e9d18d6bbb2bba7683d3407101_148680] (unreliable)
[ 9110.632797] [c000000419577c50] [d00000000f44b788] enter_tracepoint_probe_248+0x18/0x30 [stap_7237c4e9d18d6bbb2bba7683d3407101_148680]
[ 9110.632816] [c000000419577c70] [c0000000000fe764] hrtimer_init+0x114/0x130
[ 9110.632875] [c000000419577cb0] [d00000000f4656a4] _stp_ctl_write_cmd+0xa74/0xb80 [stap_7237c4e9d18d6bbb2bba7683d3407101_148680]
[ 9110.632894] [c000000419577dd0] [c0000000002d5f98] SyS_write+0x148/0x390
[ 9110.632908] [c000000419577e30] [c00000000000a0fc] syscall_exit+0x0/0x7c
[ 9110.632919] Task dump for CPU 14:
[ 9110.632926] swapper/14      R  running task        0     0      1 0x00000804
[ 9110.632940] Call Trace:
[ 9110.632948] [c0000004755e3a00] [c0000004755e3a40] 0xc0000004755e3a40 (unreliable)
[ 9110.632961] Task dump for CPU 15:
[ 9110.632968] swapper/15      R  running task        0     0      1 0x00000800
[ 9110.632981] Call Trace:
[ 9110.632989] [c0000004755e7a00] [c0000004755e7a40] 0xc0000004755e7a40 (unreliable)

=======

systemtap.log:

=======
Test Run By root on Thu May 28 06:07:19 2015
Native configuration is powerpc64le-unknown-linux-gnu

                === systemtap tests ===

Schedule of variations:
    unix

Running target unix
Using /usr/share/dejagnu/baseboards/unix.exp as board description file for target.
Using /usr/share/dejagnu/config/unix.exp as generic interface file for target.
Using ./config/unix.exp as tool-and-target-specific interface file.

Host: Linux ibm-p8-02-lp5.rhts.eng.bos.redhat.com 3.10.0-229.ael7b.ppc64le #1 SMP Fri Jan 30 12:03:50 EST 2015 ppc64le ppc64le ppc64le GNU/Linux
Snapshot: version 2.8/0.160, commit release-2.7-157-g35bd6e1548e9 + changes
GCC: 4.8.3 [gcc (GCC) 4.8.3 20140911 (Red Hat 4.8.3-9)]
Distro: Red Hat Enterprise Linux Server release 7.1 Beta (Maipo)
SElinux: Disabled


Running ./systemtap.onthefly/tracepoint_onthefly.exp ...
Executing: kill -INT 3693
Executing: kill -KILL 3693
expected more patterns
got to pattern index -1, but there are 1 patterns
KFAIL: tracepoint_onthefly - otf_finish_at_start_disabled (invalid output) (PRMS: 17256)
Executing: kill -INT 11058
Executing: kill -KILL 11058
PASS: tracepoint_onthefly - otf_finish_at_start_enabled (valid output)
Executing: kill -INT 17432
Executing: kill -KILL 17432
kill: kill: sending signal to 17432 failed: No such process
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_1 (invalid output) (PRMS: 17256)
Executing: kill -INT 23004
Executing: kill -KILL 23004
expected more patterns
got to pattern index 1, but there are 3 patterns
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_1 (invalid output) (PRMS: 17256)
Executing: kill -INT 30452
Executing: kill -KILL 30452
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_2 (invalid output) (PRMS: 17256)
Executing: kill -INT 38761
Executing: kill -KILL 38761
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_2 (invalid output) (PRMS: 17256)
Executing: kill -INT 47078
Executing: kill -KILL 47078
kill: kill: sending signal to 47078 failed: No such process
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_3 (invalid output) (PRMS: 17256)
Executing: kill -INT 54751
Executing: kill -KILL 54751
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_3 (invalid output) (PRMS: 17256)
Executing: kill -INT 64813
Executing: kill -KILL 64813
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_4 (invalid output) (PRMS: 17256)
Executing: kill -INT 75327
Executing: kill -KILL 75327
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_4 (invalid output) (PRMS: 17256)
Executing: kill -INT 85709
Executing: kill -KILL 85709
kill: kill: sending signal to 85709 failed: No such process
expected: * not registering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_disabled_iter_5 (invalid output) (PRMS: 17256)
Executing: kill -INT 95434
Executing: kill -KILL 95434
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_start_enabled_iter_5 (invalid output) (PRMS: 17256)
Executing: kill -INT 106693
Executing: kill -KILL 106693
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_timer_100ms (invalid output) (PRMS: 17256)
Executing: kill -INT 113089
Executing: kill -KILL 113089
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_timer_50ms (invalid output) (PRMS: 17256)
Executing: kill -INT 119006
Executing: kill -KILL 119006
expected: * unregistering (tracepoint) pidx ?
received: toggling
KFAIL: tracepoint_onthefly - otf_timer_10ms (invalid output) (PRMS: 17256)
Executing: kill -INT 124865
Executing: kill -KILL 124865
PASS: tracepoint_onthefly - otf_stress_5ms_iter_50 (survived)
Executing: kill -INT 130709
Executing: kill -KILL 130709
kill: kill: sending signal to 130709 failed: No such process
PASS: tracepoint_onthefly - otf_stress_1ms_iter_50 (survived)
Executing: kill -INT 134369
Executing: kill -KILL 134369
kill: kill: sending signal to 134369 failed: No such process
PASS: tracepoint_onthefly - otf_stress_500us_iter_50 (survived)
Executing: kill -INT 137785
Executing: kill -KILL 137785
kill: kill: sending signal to 137785 failed: No such process
PASS: tracepoint_onthefly - otf_stress_100us_iter_50 (survived)
Executing: kill -INT 141474
Executing: kill -KILL 141474
PASS: tracepoint_onthefly - otf_stress_prof_iter_2000 (survived)
=======
Comment 2 Martin Cermak 2015-05-28 10:17:52 UTC
All other supported rhel-[567] arches seem to survive running this testcase successfully :) For powerpc it's a reliable killer.
Comment 3 Frank Ch. Eigler 2015-05-29 17:01:02 UTC
See also bug #17126 and https://bugzilla.redhat.com/show_bug.cgi?id=1143870 for similar-sounding problems, but those were known to affect only the hcall_{entry,exit} tracepoints.
Comment 4 David Smith 2015-06-15 19:29:05 UTC
Fixed in commit 07939da. This really was an instance of bug #17126 - the hcall tracepoints were causing the crash. The tracepoint_onthefly.exp test case uses '-g', which ignores the kernel tracepoint blacklist. To fix the problem, I modified the test case to probe kernel.trace("[a-gi-z]*") on ppc64.