Update examples for probing with systemtap

This removes the old example for legacy probes and adds two
new scripts demonstrating many of the new probe point facilities.

The rpc-monitor.stp script will print out friendly details of all
RPC traffic between a libvirt client/server. This is incredibly
useful in seeing what RPC calls are being made, and also debugging
problems in the RPC protocol code

The events.stp script will print out lots of info about the poll
event loop, which is useful for debugging event handling problems

* examples/systemtap/events.stp, examples/systemtap/rpc-monitor.stp:
  New examples
* examples/systemtap/client.stp: Remove obsolete example

cfg.mk

@@ -726,7 +726,7 @@ exclude_file_name_regexp--sc_prohibit_readlink = ^src/util/util\.c$$
 exclude_file_name_regexp--sc_prohibit_setuid = ^src/util/util\.c$$
 
 exclude_file_name_regexp--sc_prohibit_sprintf = \
-  ^(docs/hacking\.html\.in)|(src/dtrace2systemtap\.pl)|(src/rpc/gensystemtap\.pl)$$
+  ^(docs/hacking\.html\.in)|(examples/systemtap/.*stp)|(src/dtrace2systemtap\.pl)|(src/rpc/gensystemtap\.pl)$$
 
 exclude_file_name_regexp--sc_prohibit_strncpy = \
   ^(src/util/util|tools/virsh)\.c$$

examples/systemtap/Makefile.am

 ## Copyright (C) 2005-2011 Red Hat, Inc.
 ## See COPYING.LIB for the License of this software
 
-EXTRA_DIST = client.stp
+EXTRA_DIST = \
+	events.stp \
+	rpc-monitor.stp

examples/systemtap/client.stp

-#!/usr/bin/stap
-
-probe libvirt.daemon.client.connect {
-      printf("Client fd=%d connected readonly=%d addr=%s\n", fd, readonly, addr);
-}
-probe libvirt.daemon.client.disconnect {
-      printf("Client fd=%d disconnected addr=%s\n", fd, addr);
-}
-
-probe libvirt.daemon.client.tls_allow {
-      printf("Client fd=%d tls allow %s\n", fd, x509dname);
-}
-probe libvirt.daemon.client.tls_deny {
-      printf("Client fd=%d tls deny %s\n", fd, x509dname);
-}
-probe libvirt.daemon.client.tls_fail {
-      printf("Client fd=%d tls fail\n", fd);
-}
-
-probe libvirt.daemon.client.auth_allow {
-      printf("Client fd=%d auth %s allow %s\n", fd, authname, identity);
-}
-probe libvirt.daemon.client.auth_deny {
-      printf("Client fd=%d auth %s deny %s\n", fd, authname, identity);
-}
-probe libvirt.daemon.client.auth_fail {
-      printf("Client fd=%d auth %s fail\n", fd, authname);
-}

examples/systemtap/events.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 operation of the libvirt event loop
+# in both client and server. Example output is:
+#
+#  0.000 begin
+#  2.359 18185 + handle 1 4 1
+#  2.360 18185 + handle 2 6 1
+#  2.360 18185 * handle 2 0
+#  2.360 14370 > handle 3 1
+#  2.360 14370 + handle 33 16 1
+#  2.361 14370 ~ 7 -1
+#  2.361 14370 > handle 33 1
+#  2.361 14370 * handle 33 1
+#  2.361 14370 * handle 33 1
+#  2.361 14370 * handle 33 3
+#  2.361 14370 ~ 7 -1
+#  2.361 14370 > handle 1 1
+#  2.361 14370 ~ 7 -1
+#  2.361 14370 > handle 33 2
+#  2.361 14370 * handle 33 1
+#  2.361 14370 ~ 7 -1
+#  2.361 18185 * handle 2 1
+#  2.362 18185 * handle 2 0
+#  2.362 14370 > handle 33 1
+#  2.362 14370 * handle 33 1
+#  2.362 14370 * handle 33 1
+#  2.362 14370 ~ 7 -1
+#  2.367 14370 * handle 33 3
+#  2.367 14370 > handle 1 1
+#  2.367 14370 ~ 7 -1
+#  2.367 14370 > handle 33 2
+#  2.367 14370 * handle 33 1
+#  2.367 14370 ~ 7 -1
+#  2.370 18185 - timeout 1
+#  2.370 14370 ! handle 33
+#  2.371 14370 - handle 33
+#  2.371 14370 ~ 6 -1
+#
+# Legend:
+#   +   Add
+#   -   Remove
+#   *   Update
+#   >   dispatch
+#   !   purge
+#   ~   Iterate
+#
+#
+
+# Show all updates to registered timeouts/handles
+global showUpdates = 1
+
+# Show when handles/timeouts are dispatched
+global showDispatch = 1
+
+# Show iterations of the event loop
+global showIter = 1
+
+global start
+
+# 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);
+}
+
+probe begin {
+  start = gettimeofday_ns() / (1000*1000)
+  print_ts("begin");
+}
+
+probe libvirt.event_poll.add_handle {
+  print_ts(sprintf("%d + handle %d %d %d", pid(), watch, fd, events));
+}
+probe libvirt.event_poll.remove_handle {
+  print_ts(sprintf("%d - handle %d", pid(), watch));
+}
+probe libvirt.event_poll.update_handle {
+  if (showUpdates)
+    print_ts(sprintf("%d * handle %d %d", pid(), watch, events));
+}
+probe libvirt.event_poll.purge_handle {
+  print_ts(sprintf("%d ! handle %d", pid(), watch));
+}
+probe libvirt.event_poll.dispatch_handle {
+  if (showDispatch)
+    print_ts(sprintf("%d > handle %d %d", pid(), watch, events));
+}
+
+probe libvirt.event_poll.add_timeout {
+  print_ts(sprintf("%d + timeout %d %d", pid(), timer, frequency));
+}
+probe libvirt.event_poll.remove_timeout {
+  print_ts(sprintf("%d - timeout %d", pid(), timer));
+}
+probe libvirt.event_poll.update_timeout {
+  if (showUpdates)
+    print_ts(sprintf("%d * timeout %d %d", pid(), timer, frequency));
+}
+probe libvirt.event_poll.purge_timeout {
+  print_ts(sprintf("%d ! timeout %d", pid(), timer));
+}
+
+probe libvirt.event_poll.dispatch_timeout {
+  if (showDispatch)
+    print_ts(sprintf("%d > timeout %d", pid(), timer));
+}
+
+probe libvirt.event_poll.run {
+  if (showIter)
+    print_ts(sprintf("%d ~ %d %d", pid(), nfds, timeout));
+}

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];
+   }
+}