[Bug runtime/9940] New: double calling double calling of uprobes in shared libraries

[Bug runtime/9940] New: double calling double calling of uprobes in shared libraries

[fche at redhat dot com]

On 2.6.27.* fedora kernels, scripts that probe shared libraries
seem to receive double uprobe callbacks per event.

sudo stap -DDEBUG_TASK_FINDER -DDEBUG_TASK_FINDER_VMA -DDEBUG_UPROBES -e 'probe
process ("/lib64/libpthread.so.0").function("__sigaddset") {log(probefunc() . "
" . $$parms)}' -c ls

Running this shows two calls to __sigaddset even though only one is appropriate.
In "dmesg", there are duplicated uprobes register/unregister calls.

....
-uprobe spec 0 index 0 pid 31445 addr 000000302d805455
-uprobe spec 1 index 1 pid 31445 addr 000000302d8074ef
-uprobe spec 0 index 2 pid 31445 addr 000000302d805455
-uprobe spec 1 index 3 pid 31445 addr 000000302d8074ef
-uprobe spec 0 index 4 pid 31445 addr 000000302d805455

I suspect a problem either with task-finder or the translator-generated
uprobes registration loops.

-- 
           Summary: double calling double calling of uprobes in shared
                    libraries
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
        AssignedTo: systemtap at sources dot redhat dot com
        ReportedBy: fche at redhat dot com


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[wenji dot huang at oracle dot com]

------- Additional Comments From wenji dot huang at oracle dot com  2009-03-17 10:08 -------
I found the same problem when I was developing the code of verifying build-id 
for user-space probing.

The inside trick seems like,
1. mprotect cause vma change of interesting dynamic library.
2. the callback stap_uprobe_vmchange_found is triggered more than one time.
3. stap_uprobe_change is accordingly called in the callback.
4. Finally the same probe point will be successfully registered many times
   in stap_uprobe_change. 



-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2009-03-17 14:04 -------
Maybe this affects only specially linked (relro?) shared libraries.
We could try simply ignoring mprotect() (except perhaps PROT_NONE).


-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[wenji dot huang at oracle dot com]

------- Additional Comments From wenji dot huang at oracle dot com  2009-03-18 08:37 -------
Have a deeper investigation. mprotect is not the culprit.

The duplication is from __stp_utrace_task_finder_target_syscall_exit.
When we didn't find a file based vma to store in the syscall_entry
routine, invoking vm_callback with register_p=1 can cause multiple
registering same probe point. 



-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[wenji dot huang at oracle dot com]

------- Additional Comments From wenji dot huang at oracle dot com  2009-03-18 08:40 -------
Created an attachment (id=3828)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=3828&action=view)
Patch to fix it. 


-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[wenji dot huang at oracle dot com]

------- Additional Comments From wenji dot huang at oracle dot com  2009-03-18 08:51 -------
(In reply to comment #3)
> Have a deeper investigation. mprotect is not the culprit.
> 
> The duplication is from __stp_utrace_task_finder_target_syscall_exit.
> When we didn't find a file based vma to store in the syscall_entry
> routine, invoking vm_callback with register_p=1 can cause multiple
> registering same probe point. 
> 
> 
A little clarification. In vm_callback - stap_uprobe_vmchange_found, it is 
map_p=1, finally becomes register_p=1 in stap_uprobe_change.

-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2009-03-19 10:23 -------
I believe this is correct. __stp_call_vm_callbacks_with_vma() needed a map_p
argument to indicate whether the vma was created or deleted. Please do commit.


-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[wenji dot huang at oracle dot com]

------- Additional Comments From wenji dot huang at oracle dot com  2009-03-20 03:07 -------
See commit d2bb12d37037345a77e90aa83512075d78ae968f

PR9940: avoid duplicated calling of uprobes in shared libraries

Add map_p argument to __stp_call_vm_callbacks_with_vma to well
tune the vma callback.

-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2009-03-24 14:08 -------
Unfortunately this seems to cause probing libraries to fail:

$ stap -ve 'probe process("/bin/ls").function("main") { log(pp()); } probe
process("/lib/libc-2.9.so").function("*") { log(pp()); }' -c /bin/ls
Pass 1: parsed user script and 51 library script(s) in 370usr/10sys/368real ms.
Pass 2: analyzed script: 4194 probe(s), 2 function(s), 0 embed(s), 0 global(s)
in 580usr/10sys/607real ms.
Pass 3: translated to C into
"/tmp/stapbUZHx0/stap_843809dfe1ea5d7b533c2e6bfd92db0c_792637.c" in
290usr/140sys/434real ms.
Pass 4, preamble: (re)building SystemTap's version of uprobes.
Pass 4: compiled C into "stap_843809dfe1ea5d7b533c2e6bfd92db0c_792637.ko" in
6470usr/930sys/7618real ms.
Pass 5: starting run.
[... very long pause ...]
ERROR: utrace_detach returned error 115 on pid 31521
WARNING: Number of errors: 0, skipped probes: 4193
Pass 5: run completed in 10usr/65120sys/35972real ms.

Reverting this patch makes this work again.

I'll try to come up with a more contained testcase for our testsuite.

-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2009-03-24 20:47 -------
I added a testcase for this issue that shows the double probe calling in a
shared library.

commit b84e888167b9ecc22497730078759ee3a7c4914e
Author: Mark Wielaard <mjw@redhat.com>
Date:   Tue Mar 24 21:37:30 2009 +0100

    Add testcase for uprobe on shared library (PR9940).
    
    * testsuite/systemtap.base/uprobes_exe.c: New file.
    * testsuite/systemtap.base/uprobes_lib.c: New file.
    * testsuite/systemtap.base/uprobes_lib.exp: New file.
    * testsuite/systemtap.base/uprobes_lib.stp: New file.

This isn't a "regression" BTW. The double calling of the probe is also visible
with stap version 0.7.2/0.137.

-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[dsmith at redhat dot com]

------- Additional Comments From dsmith at redhat dot com  2009-03-25 20:08 -------
(In reply to comment #7)
> See commit d2bb12d37037345a77e90aa83512075d78ae968f
> 
> PR9940: avoid duplicated calling of uprobes in shared libraries
> 
> Add map_p argument to __stp_call_vm_callbacks_with_vma to well
> tune the vma callback.

Unfortunately, as we've seen, this patch isn't correct (and has been reverted).

Here's why.  The __stp_call_vm_callbacks_with_vma() function only gets called
when new vmas have been created.  That is why there isn't a 'register_p' or
'map_p' argument to it and it calls __stp_call_vm_callbacks() with map_p
hardcoded to 1.

-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[dsmith at redhat dot com]

------- Additional Comments From dsmith at redhat dot com  2009-03-26 20:00 -------
After debugging this a bit, I may see what is going on.  The uprobes code asks
the task_finder to notify it about vma changes (by setting the vma_callback). 
So, the task_finder does notify it - about all vma changes.  Here's a longish
description of what is going on:

If you strace Mark's new testcase, you'll see this.

execve("./uprobes_exe", ["uprobes_exe"], [/* 39 vars */]) = 0
...
open("./libuprobes_lib.so", O_RDONLY)   = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300\4\0\0\0\0\0\0@"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0775, st_size=7493, ...}) = 0
...
mmap(NULL, 2099320, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x110000
mprotect(0x111000, 2093056, PROT_NONE)  = 0
mmap(0x310000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE,
3, 0) = 0x310000
close(3)                                = 0
...

If you looked at /proc/PID/maps before the mprotect() call, you'd see something
like this (with some extra info deleted):

  vm_start-vm_end  flags vm_pgoff path
  00110000-00311000 r-xp 00000000 ./libuprobes_lib.so

(1) At this point, the task_finder will call the vm_callback,
stap_uprobe_vmchange_found() with map_p=1.  stap_uprobe_vmchange_found() will
call stap_uprobe_change() which registers the first uprobe.

If you looked at /proc/PID/maps after the mprotect() and 2nd mmap() calls, you'd
see something like this (with some extra info deleted):

  vm_start-vm_end  flags vm_pgoff path
  00110000-00111000 r-xp 00000000 ./libuprobes_lib.so
  00111000-00310000 ---p 00001000 ./libuprobes_lib.so
  00310000-00311000 r-xp 00200000 ./libuprobes_lib.so

The former 1 mmap area has been split into 3 areas.  The task_finder will make
several vm_callbacks here:

(2) It calls the vm_callback with map_p=0 to let the callback know the original
vma is gone.  The stap_uprobe_vmchange_found() function is called with map_p=0.
 Because of a bug in the task_finder, in this case path is NULL, so
stap_uprobe_vmchange_found() exits early and stap_uprobe_change() isn't called.
 This means the uprobe isn't unregistered.
(3-5) It calls the vm_callback with map_p=1 3 times to let the callback know of
the 3 new vmas.  On the first callback, the uprobe gets re-registered by
stap_uprobe_vmchange_found()/stap_uprobe_change().

Note that even if the path was correct in step (2), stap_uprobe_change() never
unregisters uprobes so we'd still have a duplicate uprobe (because of bug #6829).

I'm unsure of the best way to proceed here.



-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[dsmith at redhat dot com]

------- Additional Comments From dsmith at redhat dot com  2009-03-26 21:28 -------
After a bit more debugging, here's what the 2nd mmap() call does - allows
writing to the 3rd vma and changes the offset (I'm unsure of why it does the
latter).  So, the final /proc/PID/maps file would look like this:

  vm_start-vm_end  flags vm_pgoff path
  00110000-00111000 r-xp 00000000 ./libuprobes_lib.so
  00111000-00310000 ---p 00001000 ./libuprobes_lib.so
  00310000-00311000 rw-p 00000000 ./libuprobes_lib.so

Also, for reference's sake, here are the vm_callbacks that the task_finder would
make (since this system has been rebooted, the addressed changed):

(1) after the 1st mmap():

tsk 3649, map_p 1, path ./libuprobes_lib.so, start 0x009cf000, end 0x00bd0000,
offset 0x0

(2) after the mprotect():

tsk 3649, map_p 0, path NULL, start 0x009cf000, end 0x00bd0000, offset 0x0
tsk 3649, map_p 1, path ./libuprobes_lib.so, start 0x009cf000, end 0x009d0000,
offset 0x0
tsk 3649, map_p 1, path ./libuprobes_lib.so, start 0x009d0000, end 0x00bcf000,
offset 0x1000
tsk 3649, map_p 1, path ./libuprobes_lib.so, start 0x00bcf000, end 0x00bd0000,
offset 0x200000

(3) after the 2nd mmap():

tsk 3649, map_p 0, path NULL, start 0x00bcf000, end 0x00bd0000, offset 0x200000
tsk 3649, map_p 1, path ./libuprobes_lib.so, start 0x00bcf000, end 0x00bd0000,
offset 0x0



-- 


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

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

[Bug runtime/9940] double calling double calling of uprobes in shared libraries

[fche at redhat dot com]

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
         AssignedTo|systemtap at sources dot    |dsmith at redhat dot com
                   |redhat dot com              |
             Status|NEW                         |ASSIGNED


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

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