Summary: | tracepoints.exp testcase causing stalls/hang on ppc64 | ||
---|---|---|---|
Product: | systemtap | Reporter: | David Smith <dsmith> |
Component: | runtime | Assignee: | Frank Ch. Eigler <fche> |
Status: | RESOLVED FIXED | ||
Severity: | normal | CC: | fche, hemkshaw |
Priority: | P2 | ||
Version: | unspecified | ||
Target Milestone: | --- | ||
Host: | Target: | ppc64 | |
Build: | Last reconfirmed: |
Description
David Smith
2014-07-08 14:32:50 UTC
From some more debugging, it appears to be something going on with tracepoints that start with 'h'. If I change tracepoints.stp to probe 'kernel.trace("[a-gi-z]*")', the testcase works fine. Here are the tracepoints that start with 'h': ==== # stap -l 'kernel.trace("h*")' kernel.trace("hcall_entry") kernel.trace("hcall_exit") kernel.trace("host1x_cdma_begin") kernel.trace("host1x_cdma_end") kernel.trace("host1x_cdma_push") kernel.trace("host1x_cdma_push_gather") kernel.trace("host1x_channel_open") kernel.trace("host1x_channel_release") kernel.trace("host1x_channel_submit") kernel.trace("host1x_channel_submit_complete") kernel.trace("host1x_channel_submitted") kernel.trace("host1x_syncpt_load_min") kernel.trace("host1x_syncpt_wait_check") kernel.trace("host1x_wait_cdma") kernel.trace("hrtimer_cancel") kernel.trace("hrtimer_expire_entry") kernel.trace("hrtimer_expire_exit") kernel.trace("hrtimer_init") kernel.trace("hrtimer_start") ==== So, there are basically 3 sets: hcall_*, host1x_*, and hrtimer_*. Each of those sets works fine individually. I haven't quite found the combination that causes the stall. After some more testing, it appears that any combination of the hrtimer_* tracepoints with the hcall_* tracepoints cause the stall/hang. The hcall_* tracepoints are ppc64 specific. I believe 'hcall' is short for hypervisor call. Using "perf" (via the following command) doesn't show the stall. # perf record -e 'timer:hrtimer_*' -e 'powerpc:hcall_*' -a ls Using "stap -DSTP_ALIBI" (which ifdef's out probe bodies) doesn't show the stall either. This means that something the probe body is doing is causing the hang. Over in __trace_hcall_entry() (in arch/powerpc/platforms/pseries/lpar.c), I see the following comment: /* * We cannot call tracepoints inside RCU idle regions which * means we must not trace H_CEDE. */ I wonder if a specific hcall opcode triggers this stall. Hi, I am trying to reproduce this bug on a RHEL7 system. But due to some reasons, stap is not able to find the trace points related to hcall. # uname -r 3.10.0-123.el7.ppc64 And the debug and devel pkgs for this kernel are also installed : # rpm -qa | grep kernel-de kernel-devel-3.10.0-123.el7.ppc64 kernel-debug-3.10.0-123.el7.ppc64 But, # stap -l 'kernel.trace("hcall_*")' shows nothing! Although, perf is able to show them, # perf list tracepoints | grep hcall powerpc:hcall_entry [Tracepoint event] powerpc:hcall_exit [Tracepoint event] However, stap is able to show the events related to hrtimer and is also able to probe into these events, viz. # stap -l 'kernel.trace("hrtimer_*")' kernel.trace("hrtimer_cancel") kernel.trace("hrtimer_expire_entry") kernel.trace("hrtimer_expire_exit") kernel.trace("hrtimer_init") kernel.trace("hrtimer_start") Since, the problem is due to the combination of probing into hrtimer_* and hcall_*, I am unable to produce this bug as systemtap is failing to probe into hcall_* : # stap -v -e 'probe kernel.trace("hcall_*") { printf("hcall hit!"); }' Pass 1: parsed user script and 97 library script(s) using 153600virt/35968res/7936shr/24640data kb, in 220usr/10sys/233real ms. semantic error: while resolving probe point: identifier 'kernel' at <input>:1:7 source: probe kernel.trace("hcall_*") { printf("hcall hit!"); } ^ semantic error: no match (similar functions: kfree, kmalloc, console, kvm_fpu, cpu_idle) Pass 2: analyzed script: 0 probe(s), 0 function(s), 0 embed(s), 0 global(s) using 164416virt/46144res/11648shr/28608data kb, in 60usr/180sys/243real ms. Pass 2: analysis failed. [man error::pass2] Thanks, Hemant Please install the kernel-debuginfo-3.10.0-123.el7.ppc64 package, not the kernel-debug-3.10.0-123.el7.ppc64 package. The former contains kernel sources and debugging object files; the latter contains kernel binaries for a completely separate configuration/build. Thanks Frank, I installed the kernel-debuginfo and kernel-debuginfo-common packages for the required kernel. But, even after installation of kernel-debuginfo-3.10.0-123.el7.ppc64 package, the problem still persists. # rpm -qa | grep kernel-debuginfo kernel-debuginfo-3.10.0-123.el7.ppc64 kernel-debuginfo-common-ppc64-3.10.0-123.el7.ppc64 # stap -l' kernel.trace("hcall_*")' # I looked into /proc/kallsysms to find where this hcall related symbols differ from others, but the hcall related symbols and hrtimer related symbols were similar. The /proc/kallsyms have entries for __tracepoint_ptr_hcall_entry and __tracepoint_ptr_hrtimer_init. I strace'd stap to try and find out where actually stap is failing to find the hcall_* events, but stap is going through all the usual files it needs. So far, I didn't notice anything unusual on the strace o/p. Thanks, Hemant (In reply to hemkshaw@in.ibm.com from comment #7) > Thanks Frank, I installed the kernel-debuginfo and kernel-debuginfo-common > packages for the required kernel. > But, even after installation of kernel-debuginfo-3.10.0-123.el7.ppc64 > package, the problem still persists. > > # rpm -qa | grep kernel-debuginfo > kernel-debuginfo-3.10.0-123.el7.ppc64 > kernel-debuginfo-common-ppc64-3.10.0-123.el7.ppc64 > > # stap -l' kernel.trace("hcall_*")' > # Does "perf list tracepoint" show the hcall tracepoints on your system? Hi David, (In reply to David Smith from comment #8) > (In reply to hemkshaw@in.ibm.com from comment #7) > > Thanks Frank, I installed the kernel-debuginfo and kernel-debuginfo-common [SNIP] > > # stap -l' kernel.trace("hcall_*")' > > # > > Does "perf list tracepoint" show the hcall tracepoints on your system? Yes, perf list tracepoints show the hcall events : # perf list tracepoints | grep hcall powerpc:hcall_entry [Tracepoint event] powerpc:hcall_exit [Tracepoint event] Thanks, Hemant Can you run % stap --poison-cache -k --vp 05000 -L 'kernel.trace("hcall_*")' and check out the resulting messages & /var/tmp/stapFOO directory, as to processing of the arch/powerpc/include/asm/trace.h tracepoints? Hi, If I try to reproduce this bug with systemtap-2.6.0 and (upstream)kernel v3.17, I can't reproduce this. # cat my_probes.stp probe kernel.trace("hcall_entry") { printf("hcall_entry\n"); } probe kernel.trace("hcall_exit") { printf("hcall_exit\n"); } probe kernel.trace("hrtimer*") { printf("hrtimer_\n"); } # stap -v my_probes.stp hrtimer_ hrtimer_ hrtimer_ ... I just tried tracepoints.exp on 3.10.0-188.el7.ppc64 and HEAD systemtap. I still get the hang, both with the traceponts.exp testcase and the following 1-line script: # stap -ve 'probe kernel.trace("hcall_*"), kernel.trace("hrtimer_*") { printf("%s\n", ppfunc()) }' Note that however I do get different behavior. With the tracepoints.exp testcase the system's console reported a backtrace similar to comment #1. With the 1-liner, I get a hard system hang with nothing reported on the console. I don't see any changes in __trace_hcall_entry()/__trace_hcall_exit() between RHEL7's source and the latest kernel sources. (In reply to David Smith from comment #13) > I don't see any changes in __trace_hcall_entry()/__trace_hcall_exit() > between RHEL7's source and the latest kernel sources. Ok, I didn't see this bug with kernel 3.17 (upstream). Although, I was able to reproduce this bug in RHEL7 ppc64 (3.10.0-123.el7.ppc64). Both with the same versions of systemtap. (In reply to hemkshaw@in.ibm.com from comment #14) > (In reply to David Smith from comment #13) > > I don't see any changes in __trace_hcall_entry()/__trace_hcall_exit() > > between RHEL7's source and the latest kernel sources. > > Ok, I didn't see this bug with kernel 3.17 (upstream). Although, I was able > to reproduce this bug in RHEL7 ppc64 (3.10.0-123.el7.ppc64). Both with the > same versions of systemtap. I'm glad to know you were able to reproduce it on RHEL7, which I don't think I knew. Since you didn't see on on 3.17, I noted that I don't see any difference between the source for the hcall trace functions between the 2 kernels. But it does potentially sound like a RHEL7 kernel bug if you've used the same version of systemtap on both the crashing and non-crashing kernels. Thanks for continuing to look at this. commit c4a048331603 works around the kernel problem via a translator blacklist |