This is the mail archive of the systemtap@sourceware.org mailing list for the systemtap project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

Re: updated uprobes patches


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


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]