[libvirt] [RFC PATCH 0/2] Add some systemtap probes to RPC code

[Daniel P. Berrange]

Trying to investigate & debug the keepalive series I decided we
needed a better way to trace the RPC protocol than the regular
debug messages. Ideally we'd have a wireshark dissector but that
seems like it will be an awful lot of work todo. So instead I
have added a few systemtap probes to the RPC call which fire
everytime an RPC message is queued for dispatch, or a completed
RPC message is read off the wire

Now I can see all communications using a script like this

# cat > watch.stp <<EOF
function msginfo(prefix, prog, version, proc, type, status, serial)
{
  if (type == 0)
    typestr = "call"
  else if (type == 1)
    typestr = "reply"
  else if (type == 2)
    typestr = "message"
  else if (type == 3)
    typestr = "stream"
  else
    typestr = "unknown"

  if (status == 0)
    statusstr = "ok"
  else if (status == 1)
    statusstr = "error"
  else if (status == 2)
    statusstr = "continue"
  else
    statusstr = "unknown"

  printf("%s program: %-10d version: %d procedure: %-4d type: %u:%-9s status: %u:%-9s serial: %-4d\n",
         prefix, prog, version, proc, type, typestr, status, statusstr, serial);
}

probe libvirt.rpc.server_msg_rx {
   msginfo(">S", prog, vers, proc, type, status, serial)
}
probe libvirt.rpc.server_msg_tx {
   msginfo("<S", prog, vers, proc, type, status, serial)
}
probe libvirt.rpc.client_msg_rx {
   msginfo("<C", prog, vers, proc, type, status, serial)
}
probe libvirt.rpc.client_msg_tx {
   msginfo(">C", prog, vers, proc, type, status, serial)
}
EOF

# stap  watch.stp 
>C program: 536903814  version: 1 procedure: 66   type: 0:call      status: 0:ok        serial: 0   
>S program: 536903814  version: 1 procedure: 66   type: 0:call      status: 0:ok        serial: 0   
<S program: 536903814  version: 1 procedure: 66   type: 1:reply     status: 0:ok        serial: 0   
<C program: 536903814  version: 1 procedure: 66   type: 1:reply     status: 0:ok        serial: 0   
>C program: 536903814  version: 1 procedure: 1    type: 0:call      status: 0:ok        serial: 1   
>S program: 536903814  version: 1 procedure: 1    type: 0:call      status: 0:ok        serial: 1   
<S program: 536903814  version: 1 procedure: 1    type: 1:reply     status: 0:ok        serial: 1   
<C program: 536903814  version: 1 procedure: 1    type: 1:reply     status: 0:ok        serial: 1   
>C program: 536903814  version: 1 procedure: 110  type: 0:call      status: 0:ok        serial: 2   
>S program: 536903814  version: 1 procedure: 110  type: 0:call      status: 0:ok        serial: 2   
<S program: 536903814  version: 1 procedure: 110  type: 1:reply     status: 0:ok        serial: 2   
<C program: 536903814  version: 1 procedure: 110  type: 1:reply     status: 0:ok        serial: 2   
>C program: 536903814  version: 1 procedure: 23   type: 0:call      status: 0:ok        serial: 3   
>S program: 536903814  version: 1 procedure: 23   type: 0:call      status: 0:ok        serial: 3   
<S program: 536903814  version: 1 procedure: 23   type: 1:reply     status: 0:ok        serial: 3   
<C program: 536903814  version: 1 procedure: 23   type: 1:reply     status: 0:ok        serial: 3   
>C program: 536903814  version: 1 procedure: 19   type: 0:call      status: 0:ok        serial: 4   
>S program: 536903814  version: 1 procedure: 19   type: 0:call      status: 0:ok        serial: 4   
<S program: 536903814  version: 1 procedure: 19   type: 1:reply     status: 0:ok        serial: 4   
<C program: 536903814  version: 1 procedure: 19   type: 1:reply     status: 0:ok        serial: 4   
>C program: 536903814  version: 1 procedure: 16   type: 0:call      status: 0:ok        serial: 5   
>S program: 536903814  version: 1 procedure: 16   type: 0:call      status: 0:ok        serial: 5   
<S program: 536903814  version: 1 procedure: 16   type: 1:reply     status: 0:ok        serial: 5   
<C program: 536903814  version: 1 procedure: 16   type: 1:reply     status: 0:ok        serial: 5   
>C program: 536903814  version: 1 procedure: 151  type: 0:call      status: 0:ok        serial: 6   
>S program: 536903814  version: 1 procedure: 151  type: 0:call      status: 0:ok        serial: 6   
<S program: 536903814  version: 1 procedure: 151  type: 1:reply     status: 0:ok        serial: 6   
<C program: 536903814  version: 1 procedure: 151  type: 1:reply     status: 0:ok        serial: 6   
>C program: 536903814  version: 1 procedure: 15   type: 0:call      status: 0:ok        serial: 7   
>S program: 536903814  version: 1 procedure: 15   type: 0:call      status: 0:ok        serial: 7   
<S program: 536903814  version: 1 procedure: 15   type: 1:reply     status: 0:ok        serial: 7   
<C program: 536903814  version: 1 procedure: 15   type: 1:reply     status: 0:ok        serial: 7   
>C program: 536903814  version: 1 procedure: 183  type: 0:call      status: 0:ok        serial: 8   
>S program: 536903814  version: 1 procedure: 183  type: 0:call      status: 0:ok        serial: 8   
<S program: 536903814  version: 1 procedure: 183  type: 1:reply     status: 0:ok        serial: 8   
<C program: 536903814  version: 1 procedure: 183  type: 1:reply     status: 0:ok        serial: 8   
>C program: 536903814  version: 1 procedure: 122  type: 0:call      status: 0:ok        serial: 9   
>S program: 536903814  version: 1 procedure: 122  type: 0:call      status: 0:ok        serial: 9   
<S program: 536903814  version: 1 procedure: 122  type: 1:reply     status: 0:ok        serial: 9   
<C program: 536903814  version: 1 procedure: 122  type: 1:reply     status: 0:ok        serial: 9   
>C program: 536903814  version: 1 procedure: 121  type: 0:call      status: 0:ok        serial: 10  
>S program: 536903814  version: 1 procedure: 121  type: 0:call      status: 0:ok        serial: 10  
<S program: 536903814  version: 1 procedure: 121  type: 1:reply     status: 0:ok        serial: 10  
<C program: 536903814  version: 1 procedure: 121  type: 1:reply     status: 0:ok        serial: 10  
>C program: 536903814  version: 1 procedure: 2    type: 0:call      status: 0:ok        serial: 11  
>S program: 536903814  version: 1 procedure: 2    type: 0:call      status: 0:ok        serial: 11  
<S program: 536903814  version: 1 procedure: 2    type: 1:reply     status: 0:ok        serial: 11  
<C program: 536903814  version: 1 procedure: 2    type: 1:reply     status: 0:ok        serial: 11  

Is the trace information resulting from 'virsh dominfo $VM'

An RPC call shoudl result in 4 messages, tx by client, rx
by server, tx by server and rx by client. An async event
will only result in 2 messages, tx by server, rx by client
and so on.

A further enhancement I want to make is to make the rpc
generator script, spit out a systemtap function for
converting procedure numbers into function/event names,
as well as adding helper functions for converting program
type and status numbers into friendly strings