Re: updated uprobes patches

[Jim Keniston <jkenisto at us dot ibm dot com>]

On Fri, 2007-05-25 at 22:15 -0400, Frank Eigler wrote:
> 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()) 
>   }
> 

Yay for stap!  When you say it "does what you think it does," I'm
assuming that you're getting actual trace output (as opposed to just the
translator generating correct code).

Thanks for the info on the lockdep warnings.  These warnings should be
gone with the May uprobes bits.  See below.

> 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.

It looks like you're using bits from April.  I've reworked (and
simplified) locking, and so some of the rwsems and mutexes mentioned in
the lockdep report no longer exist.  My May 16 uprobes post was the
first to include this simplified locking.  I've run uprobes tests
against the May 25 uprobes on a lockdep-enabled kernel.  The lockdep
instrumentation didn't complain.

> 
> > 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.

Sorry, you'll have to be less subtle here if you want me to catch your
drift.

> 
> - 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){----}:

uk->rwsem no longer exists.

>        [<c0442521>] __lock_acquire+0x9cd/0xb46
>        [<c0442a5b>] lock_acquire+0x56/0x6f
...
> 
> -> #2 (&uproc->utable_rwsem){----}:

uproc->utable_rwsem no longer exists.

>        [<c0442521>] __lock_acquire+0x9cd/0xb46
>        [<c0442a5b>] lock_acquire+0x56/0x6f
...
> -> #1 (&utask->mutex){--..}:

utask->mutex no longer exists.

>        [<c0442521>] __lock_acquire+0x9cd/0xb46
>        [<c0442a5b>] lock_acquire+0x56/0x6f
...
> 
> -> #0 (&slot->rwsem){----}:
slot->rwsem is still there.

>        [<c0442405>] __lock_acquire+0x8b1/0xb46
>        [<c0442a5b>] lock_acquire+0x56/0x6f
...
> 
> 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:
...

Yup, this was exactly the problem that made me rethink the locking.

>  [<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]
> 

[core dump snipped]

Jim