Re: Watching the libvirt RPC protocol using SystemTAP

["Daniel P. Berrange" <berrange at redhat dot com>]

On Wed, Nov 30, 2011 at 02:55:42PM +0100, Mark Wielaard wrote:
> Hi Daniel (CC systemtap list, go read Daniel's blog post),
> 
> Thanks for your nice writeup of "Watching the libvirt RPC protocol using
> SystemTAP":
> http://berrange.com/posts/2011/11/30/watching-the-libvirt-rpc-protocol-using-systemtap/
> 
> Apologies for focusing on the one aspect you said didn't work well
> enough for you, but we are here to make things even more awesome. So
> could you give some examples of where things fail to work for you with
> respect to "My real immediate wishlist is for systemtap to get better at
> providing userspace stack traces, since it fails to provide a useful
> trace far too often, as compared to GDB."

We had previously discussed the problem here:

  http://cygwin.com/ml/systemtap/2011-q1/msg00144.html

where you suggested invoking using

  $ stap -d /usr/sbin/libvirtd --ldd  ...scriptname...

For some reason I didn't reply to your suggestion back there, but I've not
found that to make any significant difference to the stack traces, at least
with the version of systemtap I had at the time (1.3 / Fedora 13).

Trying again on Fedora 15, with systemtap 1.6, with just a short demo
script

probe libvirt.rpc.client_msg_rx {
  printf("client=%p len=%d program=%d version=%d procedure=%d type=%d status=%d serial=%d\n",
         client, len, prog, vers, proc, type, status, serial);
  print_ubacktrace();
}

results in warnings and just a single hex symbol for backtrace

# stap demo1.stp
WARNING: Couldn't register module '/usr/lib64/libvirt.so.0.9.7' for pid 6228 (-12)
WARNING: Try increasing -DTASK_FINDER_VMA_ENTRY_ITEMS
WARNING: Couldn't register module '/usr/lib64/libvirt.so.0.9.7' for pid 26878 (-12)
WARNING: Couldn't register module '/usr/lib64/libvirt.so.0.9.7' for pid 28535 (-12)
client=0x7f2aae3bd010 len=36 program=536903814 version=1 procedure=66 type=1 status=0 serial=0
 0x3c57f0b3dd
client=0x7f2aae3bd010 len=28 program=536903814 version=1 procedure=1 type=1 status=0 serial=1
 0x3c57f0b3dd
client=0x7f2aae3bd010 len=48 program=536903814 version=1 procedure=110 type=1 status=0 serial=2
 0x3c57f0b3dd


Adding  -d /usr/sbin/libvirtd --ldd to the invocation results in
hundreds more warnings

WARNING: Couldn't register module '/lib64/libkeyutils-1.2.so' for pid 1135 (-12)
WARNING: Couldn't register module '/lib64/libcrypto.so.1.0.0e' for pid 1135 (-12)
WARNING: Couldn't register module '/lib64/libgcc_s-4.6.1-20110908.so.1' for pid 2264 (-12)
WARNING: Couldn't register module '/lib64/ld-2.14.so' for pid 931 (-12)
WARNING: Couldn't register module '/lib64/libc-2.14.so' for pid 931 (-12)
WARNING: Couldn't register module '/lib64/libpthread-2.14.so' for pid 931 (-12)
WARNING: Couldn't register module '/lib64/librt-2.14.so' for pid 931 (-12)
WARNING: Couldn't register module '/lib64/libcap-ng.so.0.0.0' for pid 931 (-12)
WARNING: Couldn't register module '/lib64/libdl-2.14.so' for pid 1996 (-12)
WARNING: Couldn't register module '/lib64/libc-2.14.so' for pid 1996 (-12)
WARNING: Couldn't register module '/lib64/librt-2.14.so' for pid 1996 (-12)
WARNING: Couldn't register module '/lib64/libpthread-2.14.so' for pid 1996 (-12)
...snip...

I've never been able to get anything close the stack traces that GDB
produces:

(gdb) bt
#0  call (conn=0x6778b0, priv=0x677f00, flags=0, proc_nr=66, 
    args_filter=0x3a82f13a00 <__GI_xdr_void>, args=0x0, 
    ret_filter=0x3c57f07ab0 <xdr_remote_auth_list_ret>, ret=0x7fffffffdec0 "")
    at remote/remote_driver.c:4208
#1  0x0000003c57efee80 in remoteAuthenticate (authtype=0x0, auth=0x3c582b08a0, priv=0x677f00, 
    conn=0x6778b0) at remote/remote_driver.c:2423
#2  doRemoteOpen (conn=0x6778b0, priv=0x677f00, auth=0x3c582b08a0, flags=0)
    at remote/remote_driver.c:667
#3  0x0000003c57f0341b in remoteOpen (conn=0x6778b0, auth=0x3c582b08a0, flags=<optimized out>)
    at remote/remote_driver.c:846
#4  0x0000003c57ec2133 in do_open (name=0x0, auth=0x3c582b08a0, flags=0) at libvirt.c:1196
#5  0x0000003c57ec4616 in virConnectOpenAuth (name=0x0, auth=0x3c582b08a0, flags=0) at libvirt.c:1422
#6  0x000000000040ceb1 in vshReconnect (ctl=0x7fffffffe400) at virsh.c:594
#7  0x000000000040d0c0 in vshCommandRun (ctl=0x7fffffffe400, cmd=0x656e80) at virsh.c:15270
#8  0x000000000040a02f in main (argc=<optimized out>, argv=0x7fffffffe5a8) at virsh.c:16706


NB, I'm not expecting systtemtap to show me any details of variables
in the trace of course. I'd just settle for all 8 lines of the track
with function names

eg if print_ubacktrace were able to give something like this:

#0  call
#1  0x0000003c57efee80 remoteAuthenticate
#2  doRemoteOpen
#3  0x0000003c57f0341b in remoteOpen
#4  0x0000003c57ec2133 in do_open
#5  0x0000003c57ec4616 in virConnectOpenAuth
#6  0x000000000040ceb1 in vshReconnect
#7  0x000000000040d0c0 in vshCommandRun
#8  0x000000000040a02f in main

then I'd be very happy.


Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|