Watching the libvirt RPC protocol using SystemTAP

Watching the libvirt RPC protocol using SystemTAP

[Mark Wielaard]

Hi Daniel (CC systemtap list, go read Daniel's blog post),

[I actually got the systemtap mailinglist address wrong... sorry for the
double 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."

Thanks,

Mark

Re: Watching the libvirt RPC protocol using SystemTAP

[Daniel P. Berrange]

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

Re: Watching the libvirt RPC protocol using SystemTAP

[Mark Wielaard]

Hi Daniel,

On Wed, 2011-11-30 at 14:27 +0000, Daniel P. Berrange wrote:
> 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

Thanks for the short demo. (-12) is ENOMEM and this is
http://sourceware.org/bugzilla/show_bug.cgi?id=11671
"Allocate __stp_tf_vma_entry dynamically"

I hadn't given it very high priority because I thought it only occurred
in weird artificial situations. Clearly it does happen in practice, even
with a fairly simple setup. I'll give it higher priority.

BTW. The hard coded default for TASK_FINDER_VMA_ENTRY_ITEMS currently
is, the arbitrary number, 1536. You could try to do as the warning
message says and invoke stap with -DTASK_FINDER_VMA_ENTRY_ITEMS=7680 or
something even bigger to see if that helps.

Thanks,

Mark

Re: Watching the libvirt RPC protocol using SystemTAP

[Daniel P. Berrange]

On Wed, Nov 30, 2011 at 03:50:02PM +0100, Mark Wielaard wrote:
> Hi Daniel,
> 
> On Wed, 2011-11-30 at 14:27 +0000, Daniel P. Berrange wrote:
> > 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
> 
> Thanks for the short demo. (-12) is ENOMEM and this is
> http://sourceware.org/bugzilla/show_bug.cgi?id=11671
> "Allocate __stp_tf_vma_entry dynamically"
> 
> I hadn't given it very high priority because I thought it only occurred
> in weird artificial situations. Clearly it does happen in practice, even
> with a fairly simple setup. I'll give it higher priority.
> 
> BTW. The hard coded default for TASK_FINDER_VMA_ENTRY_ITEMS currently
> is, the arbitrary number, 1536. You could try to do as the warning
> message says and invoke stap with -DTASK_FINDER_VMA_ENTRY_ITEMS=7680 or
> something even bigger to see if that helps.

Ahhhh, I thought TASK_FINDER_VMA_ENTRY_ITEMS= was refering to a kernel
compile option. Didn't realize it was a stap option.

I can indeed get useful stack traces if I set that, which is great !

# stap -DTASK_FINDER_VMA_ENTRY_ITEMS=7680  demo1.stp
WARNING: Missing unwind data for module, rerun with 'stap -d /usr/bin/virsh'
client=0x7f775cf62010 len=36 program=536903814 version=1 procedure=66 type=1 status=0 serial=0
 0x3c57f0b3dd : virNetClientIOHandleInput+0x87d/0x890 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0b9a0 : virNetClientIOEventLoop+0x5b0/0x630 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0cb23 : virNetClientSend+0x2b3/0x590 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0d47c : virNetClientProgramCall+0x26c/0x8a0 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ef091e : callWithFD+0xce/0x120 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ef099c : call+0x2c/0x40 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57efee80 : doRemoteOpen+0x890/0x20f0 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0341b : remoteOpen+0x9b/0x290 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ec2133 : do_open+0x1f3/0x1100 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ec4616 : virConnectOpenAuth+0x76/0xb0 [/usr/lib64/libvirt.so.0.9.7]
 0x40ceb1 [/usr/bin/virsh+0xceb1/0x40000]
client=0x7f775cf62010 len=28 program=536903814 version=1 procedure=1 type=1 status=0 serial=1
 0x3c57f0b3dd : virNetClientIOHandleInput+0x87d/0x890 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0b9a0 : virNetClientIOEventLoop+0x5b0/0x630 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0cb23 : virNetClientSend+0x2b3/0x590 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0d47c : virNetClientProgramCall+0x26c/0x8a0 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ef091e : callWithFD+0xce/0x120 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ef099c : call+0x2c/0x40 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57eff57a : doRemoteOpen+0xf8a/0x20f0 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0341b : remoteOpen+0x9b/0x290 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ec2133 : do_open+0x1f3/0x1100 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ec4616 : virConnectOpenAuth+0x76/0xb0 [/usr/lib64/libvirt.so.0.9.7]
 0x40ceb1 [/usr/bin/virsh+0xceb1/0x40000]
client=0x7f775cf62010 len=48 program=536903814 version=1 procedure=110 type=1 status=0 serial=2
 0x3c57f0b3dd : virNetClientIOHandleInput+0x87d/0x890 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0b9a0 : virNetClientIOEventLoop+0x5b0/0x630 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0cb23 : virNetClientSend+0x2b3/0x590 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0d47c : virNetClientProgramCall+0x26c/0x8a0 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ef091e : callWithFD+0xce/0x120 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ef099c : call+0x2c/0x40 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f00092 : doRemoteOpen+0x1aa2/0x20f0 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57f0341b : remoteOpen+0x9b/0x290 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ec2133 : do_open+0x1f3/0x1100 [/usr/lib64/libvirt.so.0.9.7]
 0x3c57ec4616 : virConnectOpenAuth+0x76/0xb0 [/usr/lib64/libvirt.so.0.9.7]
 0x40ceb1 [/usr/bin/virsh+0xceb1/0x40000]


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