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