The following works fine on x86_64: $ stap -e 'probe process("/bin/ls").function("*").call, probe process("/lib64/libc.so.6").function("*").call { log(pp()) }' -c /bin/ls producing logs of function calls in both the process and the library. But on i386 (use /lib/libc.so.6) it only produces some of the calls in the library, none in the executable: $ stap -e 'probe process("/bin/ls").function("*").call, process("/lib/libc.so.6").function("*").call { log(pp()) }' -c /bin/ls process("/lib/libc.so.6").function("__sigprocmask@../sysdeps/unix/sysv/linux/sigprocmask.c:38").call process("/lib/libc.so.6").function("execvp@/usr/src/debug/glibc-2.11.1/posix/execvp.c:26").call process("/lib/libc.so.6").function("__execvpe@/usr/src/debug/glibc-2.11.1/posix/execvpe.c:50").call process("/lib/libc.so.6").function("__execve@../sysdeps/unix/sysv/linux/execve.c:28").call process("/lib/libc.so.6").function("__new_getrlimit@../sysdeps/unix/sysv/linux/i386/getrlimit.c:40").call process("/lib/libc.so.6").function("__sysconf@../sysdeps/unix/sysv/linux/x86_64/sysconf.c:32").call process("/lib/libc.so.6").function("__getpagesize@../sysdeps/unix/sysv/linux/getpagesize.c:27").call And that is it. Only probing the process itself and not the library correctly logs all executable function calls.
Something odd is going on. From dmesg: stap_a934f5697b50b5a7f1b65d1171d4cbc2_644519: systemtap: 1.1/0.144, base: fb370000, memory: 1032data/19text/2ctx/13net/17alloc kb, probes: 2794 Task died at uprobe probepoint: pid/tgid = 28028/28028, probepoint = 0x1e3150
after prelinking (I unprelinked to make sure that wasn't it) the address is more static as 0x508c150: stap_ebbb100cec9993486cbb1d77665f331c_465562: systemtap: 1.1/0.144, base: fbf22000, memory: 825data/19text/2ctx/13net/17alloc kb, probes: 1989 Task died at uprobe probepoint: pid/tgid = 28629/28629, probepoint = 0x508c150 (gdb) disassemble 0x508c150 Dump of assembler code for function __getpagesize: 0x0508c150 <__getpagesize+0>: call 0x50d3c08 <__i686.get_pc_thunk.cx> 0x0508c155 <__getpagesize+5>: add $0x9de9f,%ecx [...] which corresponds to the last output: process("/lib/libc.so.6").function("__getpagesize@../sysdeps/unix/sysv/linux/getpagesize.c:27").call
So the simpler reproducer with just one probe is: $ stap -DDEBUG_UPROBES -DDEBUG_TASK_FINDER -DEBUG_TASK_FINDER_VMA -e 'probe process("/lib/libc.so.6").function("__getpagesize").call { log(pp()) }' -c /bin/ls stap_start_task_finder:1552: attach count: 2, inuse count: 0 stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process stapio[1183] addr 0060b150 pp process("/lib/libc.so.6").function("__getpagesize@../sysdeps/unix/sysv/linux/getpagesize.c:27").call stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process ls[1183] reloc 0060b150 pp process("/lib/libc.so.6").function("__getpagesize@../sysdeps/unix/sysv/linux/getpagesize.c:27").call stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process ls[1183] addr 0508c150 pp process("/lib/libc.so.6").function("__getpagesize@../sysdeps/unix/sysv/linux/getpagesize.c:27").call process("/lib/libc.so.6").function("__getpagesize@../sysdeps/unix/sysv/linux/getpagesize.c:27").call stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process ls[1183] reloc 0508c150 pp process("/lib/libc.so.6").function("__getpagesize@../sysdeps/unix/sysv/linux/getpagesize.c:27").call stap_stop_task_finder:1564: attach count: 0, inuse count: 0 stap_utrace_detach_ops:360: attach count: 0, inuse count: 0 stap_utrace_detach_ops:360: attach count: 0, inuse count: 0 stap_stop_task_finder:1567: attach count: 0, inuse count: 0 stap_stop_task_finder:1583: attach count: 0, inuse count: 0 dmesg tail: stap_839: systemtap: 1.1/0.144, base: f7dd2000, memory: 34data/19text/2ctx/13net/17alloc kb, probes: 1 Task died at uprobe probepoint: pid/tgid = 1183/1183, probepoint = 0x508c150
The instruction in question is "call <__i686.get_pc_thunk.cx>" For __getpagesize, this is the first instruction of the function. Functions that exihibit similar problem are gnu_get_libc_release, gnu_get_libc_version,__errno_location, __gconv_get_modules_db, __gconv_get_alias_db etc. The interesting thing being in all these functions "call <__i686.get_pc_thunk.cx>" is the first instruction. On Subsequent analysis, We make a copy of this particular instruction to the ssol vma (in one of the slots of ssol vma). When we singlestep on that slot, we get a general protection fault. The simplest way to reproduce this is $ cat /tmp/a.c #include <gnu/libc-version.h> #include <stdlib.h> #include <stdio.h> int main(int argc, char *argv[]) { printf("GNU libc version: %s\n", gnu_get_libc_version()); printf("GNU libc release: %s\n", gnu_get_libc_release()); exit(EXIT_SUCCESS); } /* END */ $ $ make /tmp/a $ stap -v -v -e 'probe process("/lib/libc.so.6").function("gnu_get_libc_version").call { log(pp()) }' -c /tmp/a $ $ Running a instrumented uprobes for the above program shows --> func=register_uprobe <-- func=register_uprobe return=0 --> func=uprobe_report_signal active_ppt=(null) utask->state=UTASK_RUNNING regs->ip=00788b61 signo=5 <-- func=uprobe_report_signal active_ppt=f4c11680 utask->state=UTASK_SINGLESTEP regs->ip=bfe03020 return=19 --> func=uprobe_report_signal active_ppt=f4c11680 utask->state=UTASK_SINGLESTEP regs->ip=bfe03020 signo=11 <-- func=uprobe_report_signal active_ppt=f4c11680 utask->state=UTASK_SINGLESTEP regs->ip=bfe03020 return=51 So it shows that we hit a probepoint, which we singlestepped. However uprobes signal callback was called because of SIGSEGV after it we requested for singlestep and the ip(bfe03020) still points to the slot in ssol vma. If we have a WARN_ON(ppt) in uprobe_report_exit(), the trace looks something like this. [<c0435982>] warn_slowpath+0x7c/0xa4 [<c044baa5>] ? __put_cred+0x1f/0x21 [<c04abffb>] ? put_cred+0x21/0x23 [<c04ac677>] ? do_coredump+0x67a/0x74d [<fa110d9b>] uprobe_report_exit+0x3a/0x15b [uprobes] [<c0465210>] utrace_report_exit+0x84/0xcc [<c043897a>] do_exit+0x7e/0x705 [<c04659be>] ? utrace_get_signal+0x563/0x595 [<c0439075>] do_group_exit+0x74/0x9b [<c04416f2>] get_signal_to_deliver+0x33c/0x363 [<c0717501>] ? do_general_protection+0x0/0x22c [<c0408904>] do_notify_resume+0x6e/0x62c [<c0428b52>] ? task_rq_unlock+0xf/0x11 [<c042ef43>] ? try_to_wake_up+0x226/0x231 [<c043fcb5>] ? complete_signal+0x119/0x120 [<c043fe64>] ? send_signal+0x1a8/0x1bd [<c0440d69>] ? force_sig_info+0xa2/0xac [<c0717501>] ? do_general_protection+0x0/0x22c [<c0409649>] work_notifysig+0x13/0x1a I was using 2.6.29.4-167.fc11.i686.PAE in my analysis. Whats interesting is if we run a 2.6.33-rc4 git kernel from branch utrace-gdbstub-uprobes from location git://web.elastic.org/~fche/utrace-ext.git on the same machine, the problem disappears. Though it needs commits 21e8e579ef10942bf2db3e1514026a6d132b1502 and 4c5ce7a55108edb5203b3d69949f09c2284f1963 from systemtap git tree to be reverted to make systemtap work. I dont see any difference in the ssol vma area is setup in uprobes embedded in SystemTap and the one in branch utrace-gdbstub-uprobes branch that could be causing this.
The general protection fault on the call suggests that the destination address of the call is bad. (I think the IP is left at the faulting instruction.) The destination is computed by adding the displacement in the call instruction to the address of the next instruction. If you're in a big vma (e.g., libc-x.x.so), that displacement can be big. If you move the call instruction to the (1-page) SSOL area, that big displacement can take you out of the SSOL vma, to a potentially unmapped address. Does that warrant a GP fault? Uprobes adjusts the IP after the call, so it's back in the probed vma, but by then it may be too late. I haven't explicitly tested uprobes on relative calls and jumps, so maybe they've never worked. Perhaps all the calls and [conditional] jumps listed in Comment #4 of PR #5509 are suspect. (If that turns out to be the case, I have an idea of how to support these instructions correctly.) This hypothesis doesn't explain why Srikar doesn't see the problem in utrace-gdbstub-uprobes.
(In reply to comment #5) ... > > I haven't explicitly tested uprobes on relative calls and jumps, so maybe > they've never worked. Perhaps all the calls and [conditional] jumps listed in > Comment #4 of PR #5509 are suspect. Come to think of it, a couple of years ago I ran tests where I put a uprobe on every instruction in a specified function or address range. (They took advantage of the fact that for x86_32, the address in the objdump -d output was the virtual address in the running process.) They worked only when stap supported probe process(pid).statement(addr).absolute[.return] which it didn't for many months after dwarf support was added. I'll attach the awk scripts that generated the stap scripts. Anyway, those tests definitely probed some relative jumps and calls -- but not in libraries. It might be worthwhile to try them again. (Srikar and/or Ananth are picking this up investigation again.) Is it possible you're seeing a situation where the destination address, when the call/jump instruction is in the SSOL area, is past 0xc0000000?
Created attachment 4650 [details] Create stap script to probe all insns in specified func(s) - i386 only As promised in Comment #6
Created attachment 4651 [details] Create stap script to probe all insns in specified address range - i386 only As promised in Comment #6
After applying the patch from PR #11376, to get stap to emit correct code for stap scripts generated by probe*.awk, I ran some a couple of simple tests, and verified that uprobes still seems to support probing of relative jumps and calls, at least in executable binaries. I didn't test shared libs, where addressing is more complicated.
I think I'm hitting this same problem, easily reproduced on i686 but not x86_64. http://sourceware.org/ml/systemtap/2010-q4/msg00168.html
Belated update... later in that thread, I theorized that the GPF may be the CPU's check that the call target is within the segment boundaries. Roland helped me dig into this, and after "sysctl -w kernel.print-fatal-signals=1", I got: > [ 259.933657] #GPF(0[seg:0]) at bfb19020, CPU#0. > [ 259.934104] exec_limit: bfb1a000, user_cs: 0000fb19/00cbfb00. > [ 259.934707] stap/1684: potentially unexpected fatal signal 11. > [ 259.934709] code at bfb19020: e8 05 ea 00 00 8d 85 a8 fa ff ff 89 5c 24 08 89 > [ 259.934768] Pid: 1684, comm: stap Not tainted 2.6.35.6-45.fc14.i686 #1 /Bochs > [ 259.934771] EIP: 0073:[<bfb19020>] EFLAGS: 00010346 CPU: 0 > [ 259.934779] EIP is at 0xbfb19020 > [ 259.934781] EAX: 00000000 EBX: bfb169f4 ECX: bfb16950 EDX: bfb163e0 > [ 259.934783] ESI: 00000002 EDI: 00000000 EBP: bfb16938 ESP: bfb16140 > [ 259.934785] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b > [ 259.934788] Process stap (pid: 1684, ti=dce12000 task=ddcf9940 task.ti=dce12000) > [ 259.935379] > [ 259.935381] Call Trace: > [ 259.937563] Task died at uprobe probepoint: pid/tgid = 1684/1684, probepoint = 0x80538f6 Notice in particular the exec_limit at bfb1a000. Our instruction at bfb19020 is 5 bytes, "e8 05 ea 00 00 : call +0xea05", which puts the call target at 0xbfb27a2a. So indeed, we appear to be leaving the segment. That's before uprobes corrects the IP, of course, but the CPU doesn't give us that chance. This is on a non-PAE kernel. Roland informed me that i686.PAE and x86_64 kernels don't put any bounds on the code segment, so I tried on a PAE kernel and could not reproduce the issue. (And we already knew x86_64 was ok). (In reply to comment #4) > I was using 2.6.29.4-167.fc11.i686.PAE in my analysis. > > Whats interesting is if we run a 2.6.33-rc4 git kernel from branch > utrace-gdbstub-uprobes from location git://web.elastic.org/~fche/utrace-ext.git > on the same machine, the problem disappears. Srikar's PAE result casts this into doubt, unless in F11 times the PAE kernel still kept segment limits. Or he misreported. ;) But I tried on F12-14 and RHEL5, and consistently the non-PAE would fail while the PAE worked fine. RHEL6 is always PAE, and also works fine. So - if we care about non-PAE kernels, we'll need to either refuse to probes these relative instructions, or figure out a pre_ssout correction to keep the target in bounds. But at least on i686.PAE and x86_64, it seems ok.
uprobes on 32-bit -calls- to .get_pc_thunk. functions appear to be working on rhel7+. .return probes don't, and this is fixed via commit 2303f9f86