libvirt/examples/systemtap/rpc-monitor.stp

#!/usr/bin/stap
#
# Copyright (C) 2011 Red Hat, Inc.
#
# This library is free software; you can redistribute it and/or
# modify it under the terms of the GNU Lesser General Public
# License as published by the Free Software Foundation; either
# version 2.1 of the License, or (at your option) any later version.
#
# This library is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
# Lesser General Public License for more details.
#
# You should have received a copy of the GNU Lesser General Public
# License along with this library; if not, write to the Free Software
# Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307  USA
#
# Author: Daniel P. Berrange <berrange@redhat.com>
#
# This script will monitor all RPC messages going in/out of libvirtd and
# any connected clients. Example output:
#
#  0.000 begin
#  2.632 C + 0x7f1ea57dc010   local=127.0.0.1;0 remote=127.0.0.1;0
#  2.632 C > 0x7f1ea57dc010   msg=remote.1.auth_list(call, ok, 0) len=28
#  2.632 + S 0x1c1f710        local=127.0.0.1;0 remote=127.0.0.1;0
#  2.632 > S 0x1c1f710        msg=remote.1.auth_list(call, ok, 0) len=28
#  2.633 < S 0x1c1f710        msg=remote.1.auth_list(reply, ok, 0) len=36
#  2.633 C < 0x7f1ea57dc010   msg=remote.1.auth_list(reply, ok, 0) len=36
#  2.633 C > 0x7f1ea57dc010   msg=remote.1.open(call, ok, 1) len=40
#  2.633 > S 0x1c1f710        msg=remote.1.open(call, ok, 1) len=40
#  2.639 < S 0x1c1f710        msg=remote.1.open(reply, ok, 1) len=28
#  2.639 C < 0x7f1ea57dc010   msg=remote.1.open(reply, ok, 1) len=28
#  2.639 C > 0x7f1ea57dc010   msg=remote.1.get_uri(call, ok, 2) len=28
#  2.639 > S 0x1c1f710        msg=remote.1.get_uri(call, ok, 2) len=28
#  2.639 < S 0x1c1f710        msg=remote.1.get_uri(reply, ok, 2) len=48
#  2.640 C < 0x7f1ea57dc010   msg=remote.1.get_uri(reply, ok, 2) len=48
#  2.640 C > 0x7f1ea57dc010   msg=remote.1.domain_lookup_by_id(call, ok, 3) len=32
#  2.640 > S 0x1c1f710        msg=remote.1.domain_lookup_by_id(call, ok, 3) len=32
#  2.640 < S 0x1c1f710        msg=remote.1.domain_lookup_by_id(reply, error, 3) len=180
#  2.641 C < 0x7f1ea57dc010   msg=remote.1.domain_lookup_by_id(reply, error, 3) len=180
#  2.641 C > 0x7f1ea57dc010   msg=remote.1.close(call, ok, 4) len=28
#  2.641 > S 0x1c1f710        msg=remote.1.close(call, ok, 4) len=28
#  2.641 < S 0x1c1f710        msg=remote.1.close(reply, ok, 4) len=28
#  2.641 C < 0x7f1ea57dc010   msg=remote.1.close(reply, ok, 4) len=28
#  2.641 C - 0x7f1ea57dc010   local= remote=
#  2.641 - S 0x1c1f710        local=127.0.0.1;0 remote=127.0.0.1;0


global start

# If this is set to '1', then all the raw RPC values are postfixed
# to the string translation
global verbose=0

# Print a string, with a timestamp relative to the start of the script
function print_ts(msg)
{
  now = gettimeofday_ns() / (1000*1000)
  delta = (now - start)

  printf("%3d.%03d %s\n", (delta / 1000), (delta % 1000), msg);
}


# Just so we know the script is now running
probe begin {
  start = gettimeofday_ns() / (1000*1000)
  print_ts("begin")
}


# Format an RPC message
function msginfo(prefix, client, len, prog, version, proc, type, status, serial)
{
  progstr = libvirt_rpc_program_name(prog, verbose);
  procstr = libvirt_rpc_procedure_name(prog, version, proc, verbose);
  typestr = libvirt_rpc_type_name(type, verbose);
  statusstr = libvirt_rpc_status_name(status, verbose);


  print_ts(sprintf("%s %-16p msg=%s.%d.%s(%s, %s, %d) len=%d",
                   prefix, client, progstr, version, procstr,
                   typestr, statusstr, serial, len));
}

# Catch all tx/rx of RPC messages by clients & libvirtd
probe libvirt.rpc.server_client_msg_rx {
   if (len)
     msginfo("> S", client, len, prog, vers, proc, type, status, serial)
}
probe libvirt.rpc.server_client_msg_tx_queue {
   if (len)
     msginfo("< S", client, len, prog, vers, proc, type, status, serial)
}
probe libvirt.rpc.client_msg_rx {
   if (len)
     msginfo("C <", client, len, prog, vers, proc, type, status, serial)
}
probe libvirt.rpc.client_msg_tx_queue {
   if (len)
     msginfo("C >", client, len, prog, vers, proc, type, status, serial)
}


# Used to track connection info
global localAddrs
global remoteAddrs;
global clientSocks
global serverSocks


# Watch for all sockets opened/closed
probe libvirt.rpc.socket_new {
   localAddrs[pid(), sock] = localAddr;
   remoteAddrs[pid(), sock] = remoteAddr;
}

probe libvirt.rpc.socket_free {
   if (refs == 1) {
      delete localAddrs[pid(), sock];
      delete remoteAddrs[pid(), sock];
  }
}


# Print whenever a client opens / closes a connection
probe libvirt.rpc.client_new {
   clientSocks[pid(), client] = sock;
   print_ts(sprintf("C + %-16p local=%s remote=%s", client, localAddrs[pid(), sock], remoteAddrs[pid(), sock]));
}

probe libvirt.rpc.client_free {
   if (refs == 1) {
     print_ts(sprintf("C - %-16p local=%s remote=%s", client,
              localAddrs[pid(), clientSocks[pid(), client]],
	      remoteAddrs[pid(), clientSocks[pid(), client]]));
     delete clientSocks[pid(), client];
   }
}


# print whenever the server receives a client connection open/close
probe libvirt.rpc.server_client_new {
   serverSocks[pid(), client] = sock;
   print_ts(sprintf("+ S %-16p local=%s remote=%s", client, localAddrs[pid(), sock], remoteAddrs[pid(), sock]));
}

probe libvirt.rpc.server_client_free {
   if (refs == 1) {
     print_ts(sprintf("- S %-16p local=%s remote=%s", client,
              localAddrs[pid(), serverSocks[pid(), client]],
              remoteAddrs[pid(), serverSocks[pid(), client]]));
     delete serverSocks[pid(), client];
   }
}


probe libvirt.rpc.socket_send_fd {
      print_ts(sprintf("=   %-16p send fd=%d", sock, fd));
}


probe libvirt.rpc.socket_recv_fd {
      print_ts(sprintf("=   %-16p recv fd=%d", sock, fd));
}