* [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries
@ 2009-03-12 6:29 fche at redhat dot com
2009-03-17 16:53 ` [Bug runtime/9940] " wenji dot huang at oracle dot com
` (12 more replies)
0 siblings, 13 replies; 14+ messages in thread
From: fche at redhat dot com @ 2009-03-12 6:29 UTC (permalink / raw)
To: systemtap
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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
@ 2009-03-17 16:53 ` wenji dot huang at oracle dot com
2009-03-17 19:33 ` fche at redhat dot com
` (11 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: wenji dot huang at oracle dot com @ 2009-03-17 16:53 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
2009-03-17 16:53 ` [Bug runtime/9940] " wenji dot huang at oracle dot com
@ 2009-03-17 19:33 ` fche at redhat dot com
2009-03-18 14:58 ` wenji dot huang at oracle dot com
` (10 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: fche at redhat dot com @ 2009-03-17 19:33 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
2009-03-17 16:53 ` [Bug runtime/9940] " wenji dot huang at oracle dot com
2009-03-17 19:33 ` fche at redhat dot com
@ 2009-03-18 14:58 ` wenji dot huang at oracle dot com
2009-03-18 15:15 ` wenji dot huang at oracle dot com
` (9 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: wenji dot huang at oracle dot com @ 2009-03-18 14:58 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (2 preceding siblings ...)
2009-03-18 14:58 ` wenji dot huang at oracle dot com
@ 2009-03-18 15:15 ` wenji dot huang at oracle dot com
2009-03-18 15:28 ` wenji dot huang at oracle dot com
` (8 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: wenji dot huang at oracle dot com @ 2009-03-18 15:15 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (3 preceding siblings ...)
2009-03-18 15:15 ` wenji dot huang at oracle dot com
@ 2009-03-18 15:28 ` wenji dot huang at oracle dot com
2009-03-19 15:09 ` mjw at redhat dot com
` (7 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: wenji dot huang at oracle dot com @ 2009-03-18 15:28 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (4 preceding siblings ...)
2009-03-18 15:28 ` wenji dot huang at oracle dot com
@ 2009-03-19 15:09 ` mjw at redhat dot com
2009-03-20 3:39 ` wenji dot huang at oracle dot com
` (6 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: mjw at redhat dot com @ 2009-03-19 15:09 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (5 preceding siblings ...)
2009-03-19 15:09 ` mjw at redhat dot com
@ 2009-03-20 3:39 ` wenji dot huang at oracle dot com
2009-03-24 15:13 ` mjw at redhat dot com
` (5 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: wenji dot huang at oracle dot com @ 2009-03-20 3:39 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (6 preceding siblings ...)
2009-03-20 3:39 ` wenji dot huang at oracle dot com
@ 2009-03-24 15:13 ` mjw at redhat dot com
2009-03-24 23:24 ` mjw at redhat dot com
` (4 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: mjw at redhat dot com @ 2009-03-24 15:13 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (7 preceding siblings ...)
2009-03-24 15:13 ` mjw at redhat dot com
@ 2009-03-24 23:24 ` mjw at redhat dot com
2009-03-26 6:08 ` dsmith at redhat dot com
` (3 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: mjw at redhat dot com @ 2009-03-24 23:24 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (8 preceding siblings ...)
2009-03-24 23:24 ` mjw at redhat dot com
@ 2009-03-26 6:08 ` dsmith at redhat dot com
2009-03-26 22:58 ` dsmith at redhat dot com
` (2 subsequent siblings)
12 siblings, 0 replies; 14+ messages in thread
From: dsmith at redhat dot com @ 2009-03-26 6:08 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (9 preceding siblings ...)
2009-03-26 6:08 ` dsmith at redhat dot com
@ 2009-03-26 22:58 ` dsmith at redhat dot com
2009-03-26 22:58 ` dsmith at redhat dot com
2009-03-31 23:56 ` fche at redhat dot com
12 siblings, 0 replies; 14+ messages in thread
From: dsmith at redhat dot com @ 2009-03-26 22:58 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (10 preceding siblings ...)
2009-03-26 22:58 ` dsmith at redhat dot com
@ 2009-03-26 22:58 ` dsmith at redhat dot com
2009-03-31 23:56 ` fche at redhat dot com
12 siblings, 0 replies; 14+ messages in thread
From: dsmith at redhat dot com @ 2009-03-26 22:58 UTC (permalink / raw)
To: systemtap
------- 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.
^ permalink raw reply [flat|nested] 14+ messages in thread
* [Bug runtime/9940] double calling double calling of uprobes in shared libraries
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
` (11 preceding siblings ...)
2009-03-26 22:58 ` dsmith at redhat dot com
@ 2009-03-31 23:56 ` fche at redhat dot com
12 siblings, 0 replies; 14+ messages in thread
From: fche at redhat dot com @ 2009-03-31 23:56 UTC (permalink / raw)
To: systemtap
--
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.
^ permalink raw reply [flat|nested] 14+ messages in thread
end of thread, other threads:[~2009-03-31 21:32 UTC | newest]
Thread overview: 14+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2009-03-12 6:29 [Bug runtime/9940] New: double calling double calling of uprobes in shared libraries fche at redhat dot com
2009-03-17 16:53 ` [Bug runtime/9940] " wenji dot huang at oracle dot com
2009-03-17 19:33 ` fche at redhat dot com
2009-03-18 14:58 ` wenji dot huang at oracle dot com
2009-03-18 15:15 ` wenji dot huang at oracle dot com
2009-03-18 15:28 ` wenji dot huang at oracle dot com
2009-03-19 15:09 ` mjw at redhat dot com
2009-03-20 3:39 ` wenji dot huang at oracle dot com
2009-03-24 15:13 ` mjw at redhat dot com
2009-03-24 23:24 ` mjw at redhat dot com
2009-03-26 6:08 ` dsmith at redhat dot com
2009-03-26 22:58 ` dsmith at redhat dot com
2009-03-26 22:58 ` dsmith at redhat dot com
2009-03-31 23:56 ` fche at redhat dot com
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).