This is the mail archive of the
systemtap@sourceware.org
mailing list for the systemtap project.
Re: updated uprobes patches
- From: Frank Eigler <fche at redhat dot com>
- To: Jim Keniston <jkenisto at us dot ibm dot com>
- Cc: systemtap <systemtap at sources dot redhat dot com>
- Date: Fri, 25 May 2007 22:15:58 -0400
- Subject: Re: updated uprobes patches
- References: <1180135729.6677.2.camel@ibm-ni9dztukfq8.beaverton.ibm.com>
Jim Keniston <jkenisto@us.ibm.com> writes:
> Here are updated uprobes patches to replace those I posted May 16.
OK. While this is too new for me to have tested it already, I just
plopped in a baby amount of translator support for uprobes.
Specifically, this little widget does what you think it does:
#! /usr/bin/env stap
probe process($1).statement($2).absolute.return,
process($1).statement($2).absolute
{
log (pp())
}
Where pid numbers are easily found and statement addresses may come
from e.g. "nm /usr/bin/foo" (or /usr/lib/debug/usr/bin/foo.debug).
There are no debuginfo-based to probe points, nor $target variables.
That's next.
Running this on a /bin/zsh instance on fedora rawhide's userspace,
hooking into the zchdir function call, I got the attached kernel
lockdep warnings [1]. I've also seen a juicier crash report from an
earlier run of the same script (but methinks against a shared library
area), also attached [2]. My test kernel was a hand-built 2.6.21 via
roland's git tree + the previous set of uprobes patches, running under
1*i686 qemu-kvm.
> Utrace is still not in the -mm kernel, so these patches are against
> the most recent utrace-enabled -mm kernel, 2.6.21-rc6-mm1. If you
> want to use a more recent kernel, you'll need to patch [...]
It's almost as if we should try to use a version control system.
- FChE
[1]
Linux version 2.6.21 (fche@vm-raw32) (gcc version 4.1.2 20070424 (Red Hat 4.1.2-11)) #3 SMP Thu May 3 03:50:22 EDT 2007
[...]
=======================================================
[ INFO: possible circular locking dependency detected ]
2.6.21 #3
-------------------------------------------------------
systemtap/0/2645 is trying to acquire lock:
(&slot->rwsem){----}, at: [<c045ef71>] uprobe_free_kimg_locked+0x45/0x72
but task is already holding lock:
(&uk->rwsem){----}, at: [<c045f444>] uprobe_free_kimg+0x2b/0x4e
which lock already depends on the new lock.
the existing dependency chain (in reverse order) is:
-> #3 (&uk->rwsem){----}:
[<c0442521>] __lock_acquire+0x9cd/0xb46
[<c0442a5b>] lock_acquire+0x56/0x6f
[<c043b487>] down_write+0x3f/0x59
[<c045fff2>] register_uprobe+0x411/0x659
[<c0460253>] register_uretprobe+0x19/0x22
[<f0ab6cfa>] systemtap_module_init+0xfd/0x25e [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<f0ab6e63>] probe_start+0x8/0x11 [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<f0ab6e8f>] _stp_handle_start+0x23/0x82 [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<f0ab7079>] _stp_ctl_write_cmd+0x18b/0x6e0 [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<c047eff3>] vfs_write+0xaf/0x163
[<c047f641>] sys_write+0x3d/0x61
[<c0404ee4>] syscall_call+0x7/0xb
[<ffffffff>] 0xffffffff
-> #2 (&uproc->utable_rwsem){----}:
[<c0442521>] __lock_acquire+0x9cd/0xb46
[<c0442a5b>] lock_acquire+0x56/0x6f
[<c043b55c>] down_read+0x3f/0x51
[<c045f707>] uprobe_report_quiesce+0xa0/0x107
[<c045be63>] report_quiescent+0x2e/0x12b
[<c045bf7f>] utrace_quiescent+0x1f/0x1e3
[<c045c881>] utrace_get_signal+0x460/0x475
[<c04317ca>] get_signal_to_deliver+0xef/0x328
[<c04044af>] do_notify_resume+0x94/0x716
[<c0404fad>] work_notifysig+0x13/0x1a
[<ffffffff>] 0xffffffff
-> #1 (&utask->mutex){--..}:
[<c0442521>] __lock_acquire+0x9cd/0xb46
[<c0442a5b>] lock_acquire+0x56/0x6f
[<c0610f1d>] __mutex_lock_slowpath+0xe5/0x24a
[<c06110a3>] mutex_lock+0x21/0x24
[<c04604e9>] uprobe_report_signal+0x28d/0x6da
[<c045b89e>] report_signal+0x64/0x129
[<c045c6c3>] utrace_get_signal+0x2a2/0x475
[<c04317ca>] get_signal_to_deliver+0xef/0x328
[<c04044af>] do_notify_resume+0x94/0x716
[<c0404fad>] work_notifysig+0x13/0x1a
[<ffffffff>] 0xffffffff
-> #0 (&slot->rwsem){----}:
[<c0442405>] __lock_acquire+0x8b1/0xb46
[<c0442a5b>] lock_acquire+0x56/0x6f
[<c043b487>] down_write+0x3f/0x59
[<c045ef71>] uprobe_free_kimg_locked+0x45/0x72
[<c045f44b>] uprobe_free_kimg+0x32/0x4e
[<c045f882>] unregister_uprobe+0x114/0x132
[<f0ab4f93>] systemtap_module_exit+0xeb/0x16c [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<f0ab501c>] probe_exit+0x8/0xa [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<f0ab5cd0>] _stp_cleanup_and_exit+0x68/0x7c [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<f0ab5d62>] _stp_work_queue+0x7e/0xbc [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<c0434e87>] run_workqueue+0x89/0x14e
[<c043589d>] worker_thread+0xf8/0x124
[<c043809b>] kthread+0xb3/0xdc
[<c0405b3f>] kernel_thread_helper+0x7/0x10
[<ffffffff>] 0xffffffff
other info that might help us debug this:
2 locks held by systemtap/0/2645:
#0: (&uproc->utable_rwsem){----}, at: [<c045f43d>] uprobe_free_kimg+0x24/0x4e
#1: (&uk->rwsem){----}, at: [<c045f444>] uprobe_free_kimg+0x2b/0x4e
stack backtrace:
[<c0405e96>] show_trace_log_lvl+0x1a/0x2f
[<c0406446>] show_trace+0x12/0x14
[<c04064ca>] dump_stack+0x16/0x18
[<c0440cbe>] print_circular_bug_tail+0x5f/0x68
[<c0442405>] __lock_acquire+0x8b1/0xb46
[<c0442a5b>] lock_acquire+0x56/0x6f
[<c043b487>] down_write+0x3f/0x59
[<c045ef71>] uprobe_free_kimg_locked+0x45/0x72
[<c045f44b>] uprobe_free_kimg+0x32/0x4e
[<c045f882>] unregister_uprobe+0x114/0x132
[<f0ab4f93>] systemtap_module_exit+0xeb/0x16c [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<f0ab501c>] probe_exit+0x8/0xa [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<f0ab5cd0>] _stp_cleanup_and_exit+0x68/0x7c [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<f0ab5d62>] _stp_work_queue+0x7e/0xbc [stap_d4aa65a7e7ff1e8145dc02ea41ffe3d3_608]
[<c0434e87>] run_workqueue+0x89/0x14e
[<c043589d>] worker_thread+0xf8/0x124
[<c043809b>] kthread+0xb3/0xdc
[<c0405b3f>] kernel_thread_helper+0x7/0x10
=======================
[2]
stap_76b95e849a6977cac529915de7ab8c57_402: systemtap: 0.5.14, base: f0af4000, memory: 23234+19038+1332+13600+4855
53 data+text+ctx+io+glob, probes: 1
BUG: unable to handle kernel paging request at virtual address 6b6b6b6b
printing eip:
c04efbda
*pde = 00000000
Oops: 0000 [#1]
SMP
Modules linked in: stap_76b95e849a6977cac529915de7ab8c57_402 xt_tcpudp iptable_nat nf_nat nf_conntrack_ipv4 nf_co
nntrack nfnetlink ip_tables x_tables hidp l2cap bluetooth nfs lockd nfs_acl sunrpc ipv6 dm_multipath parport_pc l
p parport floppy loop 8139cp 8139too i2c_piix4 mii i2c_core serio_raw pcspkr sr_mod cdrom sg dm_snapshot dm_zero
dm_mirror dm_mod ata_generic ata_piix libata sd_mod scsi_mod ext3 jbd mbcache ehci_hcd ohci_hcd uhci_hcd
CPU: 0
EIP: 0060:[<c04efbda>] Not tainted VLI
EFLAGS: 00010046 (2.6.21 #3)
EIP is at __list_add+0x2d/0x60
eax: 6b6b6b6b ebx: c6357e98 ecx: cce0a88c edx: 6b6b6b6b
esi: cce0a86c edi: 00000246 ebp: c6357e7c esp: c6357e64
ds: 007b es: 007b fs: 00d8 gs: 0000 ss: 0068
Process systemtap/0 (pid: 12113, ti=c6357000 task=ceda0030 task.ti=c6357000)
Stack: 00000000 00000002 00000001 c6357e98 c6357e98 cce0a86c c6357eb8 c0610f39
00000000 00000002 c06110a3 cc039964 ceda0030 c6357e98 c6357e98 11111111
cce0a86c c6357e98 cce0a86c f0afcbe0 00000296 c6357ec4 c06110a3 00000000
Call Trace:
[<c0405e96>] show_trace_log_lvl+0x1a/0x2f
[<c0405f46>] show_stack_log_lvl+0x9b/0xa3
[<c0406106>] show_registers+0x1b8/0x289
[<c04062f0>] die+0x119/0x22e
[<c0614061>] do_page_fault+0x3ee/0x4ba
[<c061288c>] error_code+0x7c/0x84
[<c0610f39>] __mutex_lock_slowpath+0x101/0x24a
[<c06110a3>] mutex_lock+0x21/0x24
[<c045f8e3>] unregister_uretprobe+0x43/0xa0
[<f0af5f85>] systemtap_module_exit+0xd9/0x170 [stap_76b95e849a6977cac529915de7ab8c57_402]
[<f0af6024>] probe_exit+0x8/0xa [stap_76b95e849a6977cac529915de7ab8c57_402]
[<f0af6cd8>] _stp_cleanup_and_exit+0x68/0x7c [stap_76b95e849a6977cac529915de7ab8c57_402]
[<f0af6d6a>] _stp_work_queue+0x7e/0xbc [stap_76b95e849a6977cac529915de7ab8c57_402]
[<c0434e87>] run_workqueue+0x89/0x14e
[<c043589d>] worker_thread+0xf8/0x124
[<c043809b>] kthread+0xb3/0xdc
[<c0405b3f>] kernel_thread_helper+0x7/0x10
=======================
Code: e5 56 53 89 c3 83 ec 10 8b 41 04 39 d0 74 1c 89 4c 24 0c 89 54 24 04 89 44 24 08 c7 04 24 f5 52 6b c0 e8 03
83 f3 ff 0f 0b eb fe <8b> 32 39 ce 74 1c 89 54 24 0c 89 74 24 08 89 4c 24 04 c7 04 24
EIP: [<c04efbda>] __list_add+0x2d/0x60 SS:ESP 0068:c6357e64
Slab corruption: size-512 start=cce0a86c, len=512
Redzone: 0x5a2cf071/0x5a2cf071.
Last user: [<c045f5cf>](uprobe_free_process+0xe5/0xec)
000: 6b 6b 6b 6b 6a 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b
Single bit error detected. Probably bad RAM.
Run memtest86+ or a similar memory test tool.
Prev obj: start=cce0a660, len=512
Redzone: 0x5a2cf071/0x5a2cf071.
Last user: [<c05aaa03>](skb_release_data+0x7c/0x80)
000: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b
010: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b
Next obj: start=cce0aa78, len=512
Redzone: 0x170fc2a5/0x170fc2a5.
Last user: [<f0af548d>](_stp_kmalloc+0x10/0x2a [stap_76b95e849a6977cac529915de7ab8c57_402])
000: 00 60 81 f0 78 15 f2 ce c3 60 81 f0 8b 15 f2 ce
010: fe 60 81 f0 9d 15 f2 ce 8d 61 81 f0 b2 15 f2 ce