[Bug runtime/11249] New: Tracking executable plus library fails on i386

[Bug runtime/11249] New: Tracking executable plus library fails on i386

[mjw at redhat dot com]

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.

-- 
           Summary: Tracking executable plus library fails on i386
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
        AssignedTo: systemtap at sources dot redhat dot com
        ReportedBy: mjw at redhat dot com


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/11249] Tracking executable plus library fails on i386

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2010-02-04 13:17 -------
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


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/11249] Tracking executable plus library fails on i386

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2010-02-04 13:26 -------
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

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/11249] Tracking executable plus library fails on i386

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2010-02-04 14:13 -------
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

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/11249] Tracking executable plus library fails on i386

[srikar at linux dot vnet dot ibm dot com]

------- Additional Comments From srikar at linux dot vnet dot ibm dot com  2010-03-04 17:45 -------
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.

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |jkenisto at us dot ibm dot
                   |                            |com


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/11249] Tracking executable plus library fails on i386

[jkenisto at us dot ibm dot com]

------- Additional Comments From jkenisto at us dot ibm dot com  2010-03-05 00:41 -------
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.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/11249] Tracking executable plus library fails on i386

[jkenisto at us dot ibm dot com]

------- Additional Comments From jkenisto at us dot ibm dot com  2010-03-05 17:39 -------
(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?

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/11249] Tracking executable plus library fails on i386

[jkenisto at us dot ibm dot com]

------- Additional Comments From jkenisto at us dot ibm dot com  2010-03-05 17:42 -------
Created an attachment (id=4650)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=4650&action=view)
Create stap script to probe all insns in specified func(s) - i386 only

As promised in Comment #6

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/11249] Tracking executable plus library fails on i386

[jkenisto at us dot ibm dot com]

------- Additional Comments From jkenisto at us dot ibm dot com  2010-03-05 17:44 -------
Created an attachment (id=4651)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=4651&action=view)
Create stap script to probe all insns in specified address range - i386 only 

As promised in Comment #6

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug uprobes/11249] uprobes fails on glibc get-pc-thunk call insn probe

[fche at redhat dot com]

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
          Component|runtime                     |uprobes
            Summary|Tracking executable plus    |uprobes fails on glibc get-
                   |library fails on i386       |pc-thunk call insn probe


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug uprobes/11249] uprobes fails on glibc get-pc-thunk call insn probe

[jkenisto at us dot ibm dot com]

------- Additional Comments From jkenisto at us dot ibm dot com  2010-03-13 22:27 -------
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.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=11249

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug uprobes/11249] uprobes fails on glibc get-pc-thunk call insn probe

[fche at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=11249

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
                 CC|                            |fche at redhat dot com
         Resolution|---                         |FIXED

--- Comment #12 from Frank Ch. Eigler <fche at redhat dot com> ---
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

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug uprobes/11249] uprobes fails on glibc get-pc-thunk call insn probe

[jistone at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=11249

--- Comment #11 from Josh Stone <jistone at redhat dot com> 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.

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug uprobes/11249] uprobes fails on glibc get-pc-thunk call insn probe

[jistone at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=11249

Josh Stone <jistone at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |jistone at redhat dot com

--- Comment #10 from Josh Stone <jistone at redhat dot com> 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

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.