Bug 11249 - uprobes fails on glibc get-pc-thunk call insn probe
Summary: uprobes fails on glibc get-pc-thunk call insn probe
Status: RESOLVED FIXED
Alias: None
Product: systemtap
Classification: Unclassified
Component: uprobes (show other bugs)
Version: unspecified
: P2 normal
Target Milestone: ---
Assignee: Unassigned
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-02-04 12:59 UTC by Mark Wielaard
Modified: 2020-02-18 21:47 UTC (History)
3 users (show)

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


Attachments
Create stap script to probe all insns in specified func(s) - i386 only (601 bytes, text/plain)
2010-03-05 17:42 UTC, Jim Keniston
Details
Create stap script to probe all insns in specified address range - i386 only (613 bytes, text/plain)
2010-03-05 17:44 UTC, Jim Keniston
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Mark Wielaard 2010-02-04 12:59:41 UTC
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.
Comment 1 Mark Wielaard 2010-02-04 13:17:24 UTC
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
Comment 2 Mark Wielaard 2010-02-04 13:26:04 UTC
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
Comment 3 Mark Wielaard 2010-02-04 14:13:04 UTC
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
Comment 4 Srikar Dronamraju 2010-03-04 17:45:51 UTC
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.
Comment 5 Jim Keniston 2010-03-05 00:41:03 UTC
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.
Comment 6 Jim Keniston 2010-03-05 17:39:42 UTC
(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?
Comment 7 Jim Keniston 2010-03-05 17:42:45 UTC
Created attachment 4650 [details]
Create stap script to probe all insns in specified func(s) - i386 only

As promised in Comment #6
Comment 8 Jim Keniston 2010-03-05 17:44:20 UTC
Created attachment 4651 [details]
Create stap script to probe all insns in specified address range - i386 only 

As promised in Comment #6
Comment 9 Jim Keniston 2010-03-13 22:27:22 UTC
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.
Comment 10 Josh Stone 2010-11-04 01:11:06 UTC
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
Comment 11 Josh Stone 2010-11-17 00:19:44 UTC
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.
Comment 12 Frank Ch. Eigler 2020-02-18 21:47:45 UTC
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