| Summary: | Leakage of stap_uprobes slots | ||
|---|---|---|---|
| Product: | systemtap | Reporter: | William Cohen <wcohen> |
| Component: | translator | Assignee: | Josh Stone <jistone> |
| Status: | RESOLVED FIXED | ||
| Severity: | normal | ||
| Priority: | P2 | ||
| Version: | unspecified | ||
| Target Milestone: | --- | ||
| Host: | Target: | ||
| Build: | Last reconfirmed: | ||
| Attachments: |
Script to probe python interpreter
Script to exhaust the number of userspace probe slots output of problem script with -DDEBUG_UPROBES Output with stap -DDEBUG_UPROBES -DDEBUG_TASK_FINDER_VMA strace python ~/pyhello.py output |
||
Created attachment 4503 [details]
Script to probe python interpreter
This script demonstrates the leakage of userspace probe slots.
Created attachment 4504 [details]
Script to exhaust the number of userspace probe slots
This runs python many times to fill up the userspace slots. On the last
iteration of the loop the pytrace2.stp script will fail because there no more
free slots.
In this test, I'm getting appropriate results:
% sudo ./stap -v -t -DDEBUG_UPROBES -e 'probe process("ls").function("main")
{log(pp())}' &
% ls
stap_uprobe_change_plus:558: +uprobe spec 0 idx 0 process ls[8907] addr 08050ae0
pp process("/bin/ls").function("main@/usr/src/debug/coreutils-8.2/src/ls.c:1226")
process("/bin/ls").function("main@/usr/src/debug/coreutils-8.2/src/ls.c:1226")
stap_uprobe_change_minus:636: -uprobe spec 0 idx 0 process ls[8907] reloc
08050ae0 pp
process("/bin/ls").function("main@/usr/src/debug/coreutils-8.2/src/ls.c:1226")
% ls
stap_uprobe_change_plus:558: +uprobe spec 0 idx 0 process ls[8907] addr 08050ae0
pp process("/bin/ls").function("main@/usr/src/debug/coreutils-8.2/src/ls.c:1226")
process("/bin/ls").function("main@/usr/src/debug/coreutils-8.2/src/ls.c:1226")
stap_uprobe_change_minus:636: -uprobe spec 0 idx 0 process ls[8907] reloc
08050ae0 pp
process("/bin/ls").function("main@/usr/src/debug/coreutils-8.2/src/ls.c:1226")
% ls
stap_uprobe_change_plus:558: +uprobe spec 0 idx 0 process ls[8907] addr 08050ae0
pp process("/bin/ls").function("main@/usr/src/debug/coreutils-8.2/src/ls.c:1226")
process("/bin/ls").function("main@/usr/src/debug/coreutils-8.2/src/ls.c:1226")
stap_uprobe_change_minus:636: -uprobe spec 0 idx 0 process ls[8907] reloc
08050ae0 pp
process("/bin/ls").function("main@/usr/src/debug/coreutils-8.2/src/ls.c:1226")
Created attachment 4509 [details] output of problem script with -DDEBUG_UPROBES The pr11151.log has the output from running the following commands in separate windows: stap -v -m x -k pytrace2.stp -DDEBUG_UPROBES >& /tmp/pr11151.log and: ~/pyloop.sh Unlike the debug output for the probed ls in comment #3, the pr11151.log doesn't appear to have the probes removed while the script is running. Only see them removed in the systemtap_module_exit. I am wondering when task finder reports that the shared library's memory is being unmapped. If task_finder reports that the memory is being unmapped after the unmap operation is complete then the instrumentation is going to have a hard time changing the semaphore value and the entry will not be removed from stap_uprobes. Reran with: stap -v -m x -k pytrace2.stp -DDEBUG_UPROBES -DDEBUG_TASK_FINDER_VMA >& /tmp/pr11151b.log Looked for +mmap and -mmap in log. __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7c21000 __stp_call_mmap_callbacks:581: pid 13229, a/l/o/p/path 0x7ffff7c21000 0x3b6000 0x0 r-xp /usr/lib64/libpython2.6.so.1.0 stap_uprobe_mmap_found:622: +mmap R-X pid 13229 path /usr/lib64/libpython2.6.so.1.0 addr 00007ffff7c21000 length 3891200 offset (null) stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 stap_uprobe_change_plus:494: +uprobe spec 0 idx 0 process python[13229] addr 00007ffff7cf8cc4 pp process("/usr/lib64/libpython2.6.so.1.0").statement(883908) stap_uprobe_change_plus:494: +uprobe spec 1 idx 1 process python[13229] addr 00007ffff7cf9394 pp process("/usr/lib64/libpython2.6.so.1.0").statement(885652) __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7c21000 __stp_call_mmap_callbacks:581: pid 13229, a/l/o/p/path 0x7ffff7c21000 0x3b6000 0x0 r-xp /usr/lib64/libpython2.6.so.1.0 _stp_tf_mmap_cb:50: mmap_cb: tsk 13229:13229 path /usr/lib64/libpython2.6.so.1.0, addr 0x7ffff7c21000, length 0x003b6000, offset 0x0, flags 0x8000075 _stp_tf_mmap_cb:61: vm_cb: matched path /usr/lib64/libpython2.6.so.1.0 to module (for sec: .dynamic) __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7f8e000 __stp_call_mmap_callbacks:581: pid 13229, a/l/o/p/path 0x7ffff7f8e000 0x3b000 0x16d000 rw-p /usr/lib64/libpython2.6.so.1.0 stap_uprobe_mmap_found:627: +mmap RW- pid 13229 path /usr/lib64/libpython2.6.so.1.0 addr 00007ffff7f8e000 length 241664 offset 000000000016d000 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 stap_uprobe_change_semaphore_plus:557: +semaphore 0x1 @ 0x7ffff7fc865c spec 0 idx 0 task 13229 stap_uprobe_change_semaphore_plus:557: +semaphore 0x1 @ 0x7ffff7fc865e spec 1 idx 1 task 13229 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7f8e000 __stp_call_mmap_callbacks:581: pid 13229, a/l/o/p/path 0x7ffff7f8e000 0x3b000 0x16d000 rw-p /usr/lib64/libpython2.6.so.1.0 Do not see matching -semaphore operations for the -mmap: __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7fd7000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7fd7000 length 154176 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7fd7000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7bdb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7bdb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffc000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffc000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffc000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7ffc000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffc000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffc000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffc000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffc000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7ffc000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffc000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b9a000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b9a000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7ffb000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7ffb000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7ffb000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7ffb000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7ffb000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7ffb000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7ffb000 _stp_tf_exec_cb:28: tsk 13226:13226 , register_p: 0, process_p: 1 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7ffb000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7ffb000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b69000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b69000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b68000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b68000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b68000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b68000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b68000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b68000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b68000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b68000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b68000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b68000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b68000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b68000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b68000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b68000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b68000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b28000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b28000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b26000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b26000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b26000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b26000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b26000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found mmap(0x0), returned 0x7ffff7b27000 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 stap_uprobe_munmap_found:636: -mmap pid 13229 addr 00007ffff7b27000 length 4096 stf ffffffffa039d1a0 ffffffffa039d1a0 path /usr/lib64/libpython2.6.so.1.0 __stp_utrace_task_finder_target_syscall_exit:1400: tsk 13229 found munmap(0x7ffff7b27000), returned 0x0 Created attachment 4517 [details]
Output with stap -DDEBUG_UPROBES -DDEBUG_TASK_FINDER_VMA
Had a very simple python script to run in pyhello.py:
print "hello"
Generated a log with
stap -vv -m x -k -DDEBUG_UPROBES -DDEBUG_TASK_FINDER_VMA \
pytrace2.stp -c 'python -c ~/pyhello.py' >& /tmp/trace.log
In the trace.log see the probe points be placed in reasonable places:
stap_uprobe_mmap_found:297: +mmap R-X pid 9635 path
/usr/lib64/libpython2.6.so.1.0 addr 00007ffff7c21000 length 3891200 offset
(null) stf ffffffffa021e660 ffffffffa021e660 path
/usr/lib64/libpython2.6.so.1.0
stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process python[9635] addr
00007ffff7cf8cc4 pp process("/usr/lib64/libpython2.6.so.1.0").statement(883908)
stap_uprobe_change_plus:67: +uprobe spec 1 idx 1 process python[9635] addr
00007ffff7cf9394 pp process("/usr/lib64/libpython2.6.so.1.0").statement(885652)
The addresses match up with the executable part of the libpython2.6.so.1.0 in
the memory map:
00007ffff7c21000 1464K r-x-- /usr/lib64/libpython2.6.so.1.0
00007ffff7d8f000 2044K ----- /usr/lib64/libpython2.6.so.1.0
00007ffff7f8e000 236K rw--- /usr/lib64/libpython2.6.so.1.0
However, unmap callback in trace.log does not seem to have the
correct addr or length as arguments. The address and length do not
seem to correspond to anything in the mapping. There are some
additional debugging code in stap_uprobe_change_minus.:
stap_uprobe_munmap_found:312: -mmap pid 9635 addr 00007ffff7fd7000 length
154251 stf ffffffffa021e660 ffffffffa021e660 path
/usr/lib64/libpython2.6.so.1.0
stap_uprobe_change_minus:178: stap_uprobe_change_minus start
relocation=00007ffff7fd7000, length=0000000000025a8b
stap_uprobe_change_minus:216: (!0 && 9635 == 9635 && 00007ffff7cf8cc4 >=
00007ffff7fd7000 && 00007ffff7cf8cc4 < 00007ffff7ffca8b
(00007ffff7fd7000+0000000000025a8b)
stap_uprobe_change_minus:216: (!0 && 9635 == 9635 && 00007ffff7cf9394 >=
00007ffff7fd7000 && 00007ffff7cf9394 < 00007ffff7ffca8b
(00007ffff7fd7000+0000000000025a8b)
stap_uprobe_change_minus:260: stap_uprobe_change_minus end
stap_uprobe_munmap_found:312: -mmap pid 9635 addr 00007ffff7ffc000 length 4096
stf ffffffffa021e660 ffffffffa021e660 path /usr/lib64/libpython2.6.so.1.0
stap_uprobe_change_minus:178: stap_uprobe_change_minus start
relocation=00007ffff7ffc000, length=0000000000001000
stap_uprobe_change_minus:216: (!0 && 9635 == 9635 && 00007ffff7cf8cc4 >=
00007ffff7ffc000 && 00007ffff7cf8cc4 < 00007ffff7ffd000
(00007ffff7ffc000+0000000000001000)
stap_uprobe_change_minus:216: (!0 && 9635 == 9635 && 00007ffff7cf9394 >=
00007ffff7ffc000 && 00007ffff7cf9394 < 00007ffff7ffd000
(00007ffff7ffc000+0000000000001000)
stap_uprobe_change_minus:260: stap_uprobe_change_minus end
stap_uprobe_munmap_found:312: -mmap pid 9635 addr 00007ffff7ffc000 length 4096
stf ffffffffa021e660 ffffffffa021e660 path /usr/lib64/libpython2.6.so.1.0
stap_uprobe_change_minus:178: stap_uprobe_change_minus start
relocation=00007ffff7ffc000, length=0000000000001000
stap_uprobe_change_minus:216: (!0 && 9635 == 9635 && 00007ffff7cf8cc4 >=
00007ffff7ffc000 && 00007ffff7cf8cc4 < 00007ffff7ffd000
(00007ffff7ffc000+0000000000001000)
stap_uprobe_change_minus:216: (!0 && 9635 == 9635 && 00007ffff7cf9394 >=
00007ffff7ffc000 && 00007ffff7cf9394 < 00007ffff7ffd000
(00007ffff7ffc000+0000000000001000)
stap_uprobe_change_minus:260: stap_uprobe_change_minus end
Created attachment 4518 [details]
strace python ~/pyhello.py output
This trace shows the steps that python is taking to load an run the program.
The following is how the shared library is getting mapped in:
open("/usr/lib64/libpython2.6.so.1.0", O_RDONLY) = 3
read(3,
"\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\301\3\0\0\0\0\0"..., 832) =
832
fstat(3, {st_mode=S_IFREG|0555, st_size=1736312, ...}) = 0
mmap(NULL, 3889712, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) =
0x7ffff7c21000
mprotect(0x7ffff7d8f000, 2093056, PROT_NONE) = 0
mmap(0x7ffff7f8e000, 241664, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16d000) = 0x7ffff7f8e000
mmap(0x7ffff7fc9000, 55856, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ffff7fc9000
close(3) = 0
Identified the problem. The code generated by systemtap assumes there
are matching munmap for the mmaps operations. When the process exists
there are no munmaps for the regions with the probes. Thus, the
stap_uprobes[] fills with entries from processes that are no longer
around.
systemtap generated the following entry:
static struct stap_uprobe_tf stap_uprobe_finders[] = {
{ .finder={ .procname="/usr/bin/python",
.mmap_callback=&stap_uprobe_mmap_found,
.munmap_callback=&stap_uprobe_munmap_found,
},
.pathname="/usr/lib64/libpython2.6.so.1.0", },
};
There should be a call back when the process exist to clean up the stap_uprobes[].
(In reply to comment #7) > There should be a call back when the process exist to clean up the stap_uprobes[]. I'll work on adding this... |
Systemtap generated module has a finite number of slots to store entries for userspace probes. These slots are not reclaimined when a probed process exits. Given enough runs of an process that is probed the systemtap script will fail because the systemtap generated module has run out of slots. This will make it difficult to have long running scripts to monitor long term system performance. The generated module has the following data structure store information about userspace probes: #ifndef MAXUPROBES #define MAXUPROBES 572 #endif static struct stap_uprobe { union { struct uprobe up; struct uretprobe urp; }; int spec_index; unsigned long sdt_sem_address; } stap_uprobes [MAXUPROBES]; A simple example to demonstrate the problem was contructed using a very simple systemtap script and a bash script to run the instrumented python available at: http://people.redhat.com/wcohen/fudcon2009/ 1) install the instrumented python rpms 2) run the systemtap script with: stap -v /home/wcohen/research/profiling/pytrace2.stp 3) Start the pyloop.sh script Expected result is the systemtap script will continue to run for repeated runs of pyloop.sh, but the actual behavior of the systemtap script is: ERROR: Skipped too many probes, check MAXSKIPPED or try again with stap -t for more details. WARNING: Number of errors: 0, skipped probes: 102 Pass 5: run completed in 10usr/70sys/22792real ms.