From ddf3bd32ce1246d466f4ffc12ee3a8e41db1d0e9 Mon Sep 17 00:00:00 2001 From: "Daniel P. Berrange" Date: Fri, 30 Sep 2011 14:40:23 +0100 Subject: [PATCH] Rewrite all the DTrace/SystemTAP probing The libvirtd daemon had a few crude system tap probes. Some of these were broken during the RPC rewrite. The new modular RPC code is structured in a way that allows much more effective tracing. Instead of trying to hook up the original probes, define a new set of probes for the RPC and event code. The master probes file is now src/probes.d. This contains probes for virNetServerClientPtr, virNetClientPtr, virSocketPtr virNetTLSContextPtr and virNetTLSSessionPtr modules. Also add probes for the poll event loop. The src/dtrace2systemtap.pl script can convert the probes.d file into a libvirt_probes.stp file to make use from systemtap much simpler. The src/rpc/gensystemtap.pl script can generate a set of systemtap functions for translating RPC enum values into printable strings. This works for all RPC header enums (program, type, status, procedure) and also the authentication enum The PROBE macro will automatically generate a VIR_DEBUG statement, so any place with a PROBE can remove any existing manual DEBUG statements. * daemon/libvirtd.stp, daemon/probes.d: Remove obsolete probing * daemon/libvirtd.h: Remove probe macros * daemon/Makefile.am: Remove all probe buildings/install * daemon/remote.c: Update authentication probes * src/dtrace2systemtap.pl, src/rpc/gensystemtap.pl: Scripts to generate STP files * src/internal.h: Add probe macros * src/probes.d: Master list of probes * src/rpc/virnetclient.c, src/rpc/virnetserverclient.c, src/rpc/virnetsocket.c, src/rpc/virnettlscontext.c, src/util/event_poll.c: Insert probe points, removing any DEBUG statements that duplicate the info --- cfg.mk | 3 +- daemon/Makefile.am | 26 +---- daemon/libvirtd.h | 47 --------- daemon/libvirtd.stp | 65 ------------ daemon/probes.d | 12 --- daemon/remote.c | 60 ++++++----- src/.gitignore | 4 + src/Makefile.am | 41 +++++++- src/dtrace2systemtap.pl | 104 +++++++++++++++++++ src/internal.h | 72 +++++++++++++ src/probes.d | 72 +++++++++++++ src/rpc/gensystemtap.pl | 195 +++++++++++++++++++++++++++++++++++ src/rpc/virnetclient.c | 28 +++-- src/rpc/virnetserverclient.c | 23 ++++- src/rpc/virnetsocket.c | 13 ++- src/rpc/virnettlscontext.c | 47 ++++++--- src/util/event_poll.c | 47 +++++++-- 17 files changed, 647 insertions(+), 212 deletions(-) delete mode 100644 daemon/libvirtd.stp delete mode 100644 daemon/probes.d create mode 100755 src/dtrace2systemtap.pl create mode 100644 src/probes.d create mode 100755 src/rpc/gensystemtap.pl diff --git a/cfg.mk b/cfg.mk index 9f4aa3edef..fd0ac63721 100644 --- a/cfg.mk +++ b/cfg.mk @@ -725,7 +725,8 @@ 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$$ +exclude_file_name_regexp--sc_prohibit_sprintf = \ + ^(docs/hacking\.html\.in)|(src/dtrace2systemtap\.pl)|(src/rpc/gensystemtap\.pl)$$ exclude_file_name_regexp--sc_prohibit_strncpy = \ ^(src/util/util|tools/virsh)\.c$$ diff --git a/daemon/Makefile.am b/daemon/Makefile.am index ce15cbbea0..e7821b2f83 100644 --- a/daemon/Makefile.am +++ b/daemon/Makefile.am @@ -48,7 +48,6 @@ EXTRA_DIST = \ THREADS.txt \ libvirtd.pod.in \ libvirtd.8.in \ - libvirtd.stp \ $(DAEMON_SOURCES) BUILT_SOURCES = @@ -110,6 +109,10 @@ libvirtd_LDADD = \ $(SASL_LIBS) \ $(POLKIT_LIBS) +if WITH_DTRACE +libvirtd_LDADD += ../src/probes.o +endif + libvirtd_LDADD += \ ../src/libvirt-qemu.la @@ -167,24 +170,6 @@ policyfile = libvirtd.policy-1 endif endif -if WITH_DTRACE -libvirtd_LDADD += probes.o -nodist_libvirtd_SOURCES = probes.h - -BUILT_SOURCES += probes.h - -tapsetdir = $(datadir)/systemtap/tapset -tapset_DATA = libvirtd.stp - -probes.h: probes.d - $(AM_V_GEN)$(DTRACE) -o $@ -h -s $< - -probes.o: probes.d - $(AM_V_GEN)$(DTRACE) -o $@ -G -s $< - -CLEANFILES += probes.h probes.o -endif - install-data-local: install-init install-data-sasl install-data-polkit \ install-logrotate mkdir -p $(DESTDIR)$(localstatedir)/log/libvirt @@ -299,9 +284,6 @@ install-data-local: install-data-sasl uninstall-local:: uninstall-data-sasl endif # WITH_LIBVIRTD -# This is needed for 'make dist' too, so can't wrap in WITH_LIBVIRTD. -EXTRA_DIST += probes.d libvirtd.stp - POD2MAN = pod2man -c "Virtualization Support" \ -r "$(PACKAGE)-$(VERSION)" -s 8 diff --git a/daemon/libvirtd.h b/daemon/libvirtd.h index 6d6460ea3e..ecb7374ffc 100644 --- a/daemon/libvirtd.h +++ b/daemon/libvirtd.h @@ -39,53 +39,6 @@ # endif # include "virnetserverprogram.h" -# if WITH_DTRACE -# ifndef LIBVIRTD_PROBES_H -# define LIBVIRTD_PROBES_H -# include "probes.h" -# endif /* LIBVIRTD_PROBES_H */ - -/* Systemtap 1.2 headers have a bug where they cannot handle a - * variable declared with array type. Work around this by casting all - * arguments. This is some gross use of the preprocessor because - * PROBE is a var-arg macro, but it is better than the alternative of - * making all callers to PROBE have to be aware of the issues. And - * hopefully, if we ever add a call to PROBE with other than 2 or 3 - * end arguments, you can figure out the pattern to extend this hack. - */ -# define VIR_COUNT_ARGS(...) VIR_ARG5(__VA_ARGS__, 4, 3, 2, 1) -# define VIR_ARG5(_1, _2, _3, _4, _5, ...) _5 -# define VIR_ADD_CAST_EXPAND(a, b, ...) VIR_ADD_CAST_PASTE(a, b, __VA_ARGS__) -# define VIR_ADD_CAST_PASTE(a, b, ...) a##b(__VA_ARGS__) - -/* The double cast is necessary to silence gcc warnings; any pointer - * can safely go to intptr_t and back to void *, which collapses - * arrays into pointers; while any integer can be widened to intptr_t - * then cast to void *. */ -# define VIR_ADD_CAST(a) ((void *)(intptr_t)(a)) -# define VIR_ADD_CAST2(a, b) \ - VIR_ADD_CAST(a), VIR_ADD_CAST(b) -# define VIR_ADD_CAST3(a, b, c) \ - VIR_ADD_CAST(a), VIR_ADD_CAST(b), VIR_ADD_CAST(c) - -# define VIR_ADD_CASTS(...) \ - VIR_ADD_CAST_EXPAND(VIR_ADD_CAST, VIR_COUNT_ARGS(__VA_ARGS__), \ - __VA_ARGS__) - -# define PROBE_EXPAND(NAME, ARGS) NAME(ARGS) -# define PROBE(NAME, FMT, ...) \ - VIR_DEBUG_INT("trace." __FILE__ , __func__, __LINE__, \ - #NAME ": " FMT, __VA_ARGS__); \ - if (LIBVIRTD_ ## NAME ## _ENABLED()) { \ - PROBE_EXPAND(LIBVIRTD_ ## NAME, \ - VIR_ADD_CASTS(__VA_ARGS__)); \ - } -# else -# define PROBE(NAME, FMT, ...) \ - VIR_DEBUG_INT("trace." __FILE__, __func__, __LINE__, \ - #NAME ": " FMT, __VA_ARGS__); -# endif - typedef struct daemonClientStream daemonClientStream; typedef daemonClientStream *daemonClientStreamPtr; typedef struct daemonClientPrivate daemonClientPrivate; diff --git a/daemon/libvirtd.stp b/daemon/libvirtd.stp deleted file mode 100644 index 7406eebb7e..0000000000 --- a/daemon/libvirtd.stp +++ /dev/null @@ -1,65 +0,0 @@ -probe libvirt.daemon.client.connect = process("libvirtd").mark("client_connect") -{ - fd = $arg1; - readonly = $arg2; - localAddr = user_string($arg3); - remoteAddr = user_string($arg4); -} - -probe libvirt.daemon.client.disconnect = process("libvirtd").mark("client_disconnect") -{ - fd = $arg1; -} - - -probe libvirt.daemon.client.tls_allow = process("libvirtd").mark("client_tls_allow") -{ - fd = $arg1; - x509dname = user_string($arg2); -} - -probe libvirt.daemon.client.tls_deny = process("libvirtd").mark("client_tls_deny") -{ - fd = $arg1; - x509dname = user_string($arg2); -} - -probe libvirt.daemon.client.tls_fail = process("libvirtd").mark("client_tls_fail") -{ - fd = $arg1; -} - - -function authtype_to_string(authtype) { - if (authtype == 0) - return "none" - if (authtype == 1) - return "sasl" - if (authtype == 2) - return "polkit" - return "unknown" -} - - -probe libvirt.daemon.client.auth_allow = process("libvirtd").mark("client_auth_allow") -{ - fd = $arg1; - authtype = $arg2; - authname = authtype_to_string($arg2); - identity = user_string($arg3); -} - -probe libvirt.daemon.client.auth_deny = process("libvirtd").mark("client_auth_deny") -{ - fd = $arg1; - authtype = $arg2; - authname = authtype_to_string($arg2); - identity = user_string($arg3); -} - -probe libvirt.daemon.client.auth_fail = process("libvirtd").mark("client_auth_fail") -{ - fd = $arg1; - authtype = $arg2; - authname = authtype_to_string($arg2); -} diff --git a/daemon/probes.d b/daemon/probes.d deleted file mode 100644 index d1050c0741..0000000000 --- a/daemon/probes.d +++ /dev/null @@ -1,12 +0,0 @@ -provider libvirtd { - probe client_connect(int fd, int readonly, const char *localAddr, const char *remoteAddr); - probe client_disconnect(int fd); - - probe client_auth_allow(int fd, int authtype, const char *identity); - probe client_auth_deny(int fd, int authtype, const char *identity); - probe client_auth_fail(int fd, int authtype); - - probe client_tls_allow(int fd, const char *x509dname); - probe client_tls_deny(int fd, const char *x509dname); - probe client_tls_fail(int fd); -}; diff --git a/daemon/remote.c b/daemon/remote.c index 245d41caef..550bed4c27 100644 --- a/daemon/remote.c +++ b/daemon/remote.c @@ -1933,8 +1933,9 @@ authfail: virNetError(VIR_ERR_AUTH_FAILED, "%s", _("authentication failed")); virNetMessageSaveError(rerr); - PROBE(CLIENT_AUTH_FAIL, "fd=%d, auth=%d", - virNetServerClientGetFD(client), REMOTE_AUTH_SASL); + PROBE(RPC_SERVER_CLIENT_AUTH_FAIL, + "client=%p auth=%d", + client, REMOTE_AUTH_SASL); virNetSASLSessionFree(sasl); virMutexUnlock(&priv->lock); return -1; @@ -1976,8 +1977,9 @@ remoteSASLFinish(virNetServerClientPtr client) VIR_DEBUG("Authentication successful %d", virNetServerClientGetFD(client)); identity = virNetSASLSessionGetIdentity(priv->sasl); - PROBE(CLIENT_AUTH_ALLOW, "fd=%d, auth=%d, username=%s", - virNetServerClientGetFD(client), REMOTE_AUTH_SASL, identity); + PROBE(RPC_SERVER_CLIENT_AUTH_ALLOW, + "client=%p auth=%d identity=%s", + client, REMOTE_AUTH_SASL, identity); virNetSASLSessionFree(priv->sasl); priv->sasl = NULL; @@ -2064,14 +2066,16 @@ remoteDispatchAuthSaslStart(virNetServerPtr server ATTRIBUTE_UNUSED, return 0; authfail: - PROBE(CLIENT_AUTH_FAIL, "fd=%d, auth=%d", - virNetServerClientGetFD(client), REMOTE_AUTH_SASL); + PROBE(RPC_SERVER_CLIENT_AUTH_FAIL, + "client=%p auth=%d", + client, REMOTE_AUTH_SASL); goto error; authdeny: identity = virNetSASLSessionGetIdentity(priv->sasl); - PROBE(CLIENT_AUTH_DENY, "fd=%d, auth=%d, username=%s", - virNetServerClientGetFD(client), REMOTE_AUTH_SASL, identity); + PROBE(RPC_SERVER_CLIENT_AUTH_DENY, + "client=%p auth=%d identity=%s", + client, REMOTE_AUTH_SASL, identity); goto error; error: @@ -2160,14 +2164,16 @@ remoteDispatchAuthSaslStep(virNetServerPtr server ATTRIBUTE_UNUSED, return 0; authfail: - PROBE(CLIENT_AUTH_FAIL, "fd=%d, auth=%d", - virNetServerClientGetFD(client), REMOTE_AUTH_SASL); + PROBE(RPC_SERVER_CLIENT_AUTH_FAIL, + "client=%p auth=%d", + client, REMOTE_AUTH_SASL); goto error; authdeny: identity = virNetSASLSessionGetIdentity(priv->sasl); - PROBE(CLIENT_AUTH_DENY, "fd=%d, auth=%d, username=%s", - virNetServerClientGetFD(client), REMOTE_AUTH_SASL, identity); + PROBE(RPC_SERVER_CLIENT_AUTH_DENY, + "client=%p auth=%d identity=%s", + client, REMOTE_AUTH_SASL, identity); goto error; error: @@ -2295,8 +2301,9 @@ remoteDispatchAuthPolkit(virNetServerPtr server ATTRIBUTE_UNUSED, VIR_FREE(tmp); goto authdeny; } - PROBE(CLIENT_AUTH_ALLOW, "fd=%d, auth=%d, username=%s", - virNetServerClientGetFD(client), REMOTE_AUTH_POLKIT, ident); + PROBE(RPC_SERVER_CLIENT_AUTH_ALLOW, + "client=%p auth=%d identity=%s", + client, REMOTE_AUTH_POLKIT, ident); VIR_INFO("Policy allowed action %s from pid %d, uid %d", action, callerPid, callerUid); ret->complete = 1; @@ -2315,13 +2322,15 @@ error: return -1; authfail: - PROBE(CLIENT_AUTH_FAIL, "fd=%d, auth=%d", - virNetServerClientGetFD(client), REMOTE_AUTH_POLKIT); + PROBE(RPC_SERVER_CLIENT_AUTH_FAIL, + "client=%p auth=%d", + client, REMOTE_AUTH_POLKIT); goto error; authdeny: - PROBE(CLIENT_AUTH_DENY, "fd=%d, auth=%d, username=%s", - virNetServerClientGetFD(client), REMOTE_AUTH_POLKIT, (char *)ident); + PROBE(RPC_SERVER_CLIENT_AUTH_DENY, + "client=%p auth=%d identity=%s", + client, REMOTE_AUTH_POLKIT, (char *)ident); goto error; } #elif HAVE_POLKIT0 @@ -2429,8 +2438,9 @@ remoteDispatchAuthPolkit(virNetServerPtr server, polkit_result_to_string_representation(pkresult)); goto authdeny; } - PROBE(CLIENT_AUTH_ALLOW, "fd=%d, auth=%d, username=%s", - virNetServerClientGetFD(client), REMOTE_AUTH_POLKIT, ident); + PROBE(RPC_SERVER_CLIENT_AUTH_ALLOW, + "client=%p auth=%d identity=%s", + client, REMOTE_AUTH_POLKIT, ident); VIR_INFO("Policy allowed action %s from pid %d, uid %d, result %s", action, callerPid, callerUid, polkit_result_to_string_representation(pkresult)); @@ -2449,13 +2459,15 @@ error: return -1; authfail: - PROBE(CLIENT_AUTH_FAIL, "fd=%d, auth=%d", - virNetServerClientGetFD(client), REMOTE_AUTH_POLKIT); + PROBE(RPC_SERVER_CLIENT_AUTH_FAIL, + "client=%p auth=%d", + client, REMOTE_AUTH_POLKIT); goto error; authdeny: - PROBE(CLIENT_AUTH_DENY, "fd=%d, auth=%d, username=%s", - virNetServerClientGetFD(client), REMOTE_AUTH_POLKIT, ident); + PROBE(RPC_SERVER_CLIENT_AUTH_DENY, + "client=%p auth=%d identity=%s", + client, REMOTE_AUTH_POLKIT, ident); goto error; } diff --git a/src/.gitignore b/src/.gitignore index a619643aac..64e6aec69b 100644 --- a/src/.gitignore +++ b/src/.gitignore @@ -16,3 +16,7 @@ libvirt_qemu.def *.s remote_protocol-structs-t virt-aa-helper +libvirt_functions.stp +libvirt_probes.stp +probes.o +probes.h diff --git a/src/Makefile.am b/src/Makefile.am index 7f2f5e527e..f937b97456 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -25,6 +25,9 @@ AM_LDFLAGS = $(COVERAGE_LDFLAGS) EXTRA_DIST = $(conf_DATA) util/keymaps.csv BUILT_SOURCES = +CLEANFILES = +DISTCLEANFILES = +MAINTAINERCLEANFILES = if WITH_NETWORK UUID=$(shell uuidgen 2>/dev/null) @@ -1249,6 +1252,35 @@ libvirt_la_CFLAGS = -DIN_LIBVIRT $(AM_CFLAGS) # picked out for us. libvirt_la_DEPENDENCIES = $(libvirt_la_BUILT_LIBADD) $(LIBVIRT_SYMBOL_FILE) +if WITH_DTRACE +libvirt_la_LIBADD += probes.o +nodist_libvirt_la_SOURCES = probes.h + +BUILT_SOURCES += probes.h libvirt_probes.stp libvirt_functions.stp + +tapsetdir = $(datadir)/systemtap/tapset +tapset_DATA = libvirt_probes.stp libvirt_functions.stp + +probes.h: probes.d + $(AM_V_GEN)$(DTRACE) -o $@ -h -s $< + +probes.o: probes.d + $(AM_V_GEN)$(DTRACE) -o $@ -G -s $< + +RPC_PROBE_FILES = $(srcdir)/rpc/virnetprotocol.x $(srcdir)/remote/remote_protocol.x $(srcdir)/remote/qemu_protocol.x + +libvirt_functions.stp: $(RPC_PROBE_FILES) $(srcdir)/rpc/gensystemtap.pl + $(AM_V_GEN)perl -w $(srcdir)/rpc/gensystemtap.pl $(RPC_PROBE_FILES) > $@ + +libvirt_probes.stp: probes.d $(srcdir)/dtrace2systemtap.pl + $(AM_V_GEN)perl -w $(srcdir)/dtrace2systemtap.pl $< > $@ + +CLEANFILES += probes.h probes.o libvirt_functions.stp libvirt_probes.stp +endif + +EXTRA_DIST += probes.d + + # Create an automake "convenience library" version of libvirt_la, # just for testing, since the test harness requires access to internal # bits and pieces that we don't want to make publicly accessible. @@ -1432,6 +1464,9 @@ libvirt_lxc_LDADD = $(CAPNG_LIBS) $(YAJL_LIBS) \ $(LIBXML_LIBS) $(NUMACTL_LIBS) $(LIB_PTHREAD) \ $(LIBNL_LIBS) $(AUDIT_LIBS) $(DEVMAPPER_LIBS) \ ../gnulib/lib/libgnu.la +if WITH_DTRACE +libvirt_lxc_LDADD += probes.o +endif libvirt_lxc_CFLAGS = \ $(LIBPARTED_CFLAGS) \ $(NUMACTL_CFLAGS) \ @@ -1545,6 +1580,6 @@ if WITH_NETWORK endif rmdir "$(DESTDIR)$(localstatedir)/lib/libvirt" ||: -CLEANFILES = *.gcov .libs/*.gcda .libs/*.gcno *.gcno *.gcda *.i *.s -DISTCLEANFILES = $(GENERATED_SYM_FILES) -MAINTAINERCLEANFILES = $(REMOTE_DRIVER_GENERATED) $(VIR_NET_RPC_GENERATED) $(ESX_DRIVER_GENERATED) +CLEANFILES += *.gcov .libs/*.gcda .libs/*.gcno *.gcno *.gcda *.i *.s +DISTCLEANFILES += $(GENERATED_SYM_FILES) +MAINTAINERCLEANFILES += $(REMOTE_DRIVER_GENERATED) $(VIR_NET_RPC_GENERATED) $(ESX_DRIVER_GENERATED) diff --git a/src/dtrace2systemtap.pl b/src/dtrace2systemtap.pl new file mode 100755 index 0000000000..fab066bfb0 --- /dev/null +++ b/src/dtrace2systemtap.pl @@ -0,0 +1,104 @@ +#!/usr/bin/perl +# +# 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 +# +# Generate a set of systemtap probe definitions corresponding to +# DTrace probe markers in libvirt.so +# +# perl dtrace2systemtap.pl probes.d > libvirt_probes.stp +# + +use strict; +use warnings; + +my $file; +my @files; +my %files; + +my $probe; +my $args; + +# Read the DTraceprobes definition +while (<>) { + next if m,^\s*$,; + + next if /^\s*provider\s+\w+\s*{\s*$/; + next if /^\s*};\s*$/; + + if (m,^\s*\#\s*file:\s*(\S+)\s*$,) { + $file = $1; + push @files, $file; + $files{$file} = { prefix => undef, probes => [] }; + } elsif (m,^\s*\#\s*prefix:\s*(\S+)\s*$,) { + $files{$file}->{prefix} = $1; + } else { + if (m,\s*probe\s+([a-zA-Z0-9_]+)\((.*?)(\);)?$,) { + $probe = $1; + $args = $2; + if ($3) { + push @{$files{$file}->{probes}}, [$probe, $args]; + $probe = $args = undef; + } + } elsif ($probe) { + if (m,^(.*?)(\);)?$,) { + $args .= $1; + if ($2) { + push @{$files{$file}->{probes}}, [$probe, $args]; + $probe = $args = undef; + } + } else { + die "unexpected data $_ on line $."; + } + } else { + die "unexpected data $_ on line $."; + } + } +} + +# Write out the SystemTap probes +foreach my $file (@files) { + my $prefix = $files{$file}->{prefix}; + my @probes = @{$files{$file}->{probes}}; + + print "# $file\n\n"; + foreach my $probe (@probes) { + my $name = $probe->[0]; + my $args = $probe->[1]; + + my $pname = $name; + $pname =~ s/${prefix}_/libvirt.$prefix./; + + print "probe $pname = process(\"libvirt.so\").mark(\"$name\") {\n"; + + my @args = split /,/, $args; + for (my $i = 0 ; $i <= $#args ; $i++) { + my $arg = $args[$i]; + my $isstr = $arg =~ /char\s+\*/; + $arg =~ s/^.*\s\*?(\S+)$/$1/; + + if ($isstr) { + print " $arg = user_string(\$arg", $i + 1, ");\n"; + } else { + print " $arg = \$arg", $i + 1, ";\n"; + } + } + print "}\n\n"; + } + print "\n"; +} diff --git a/src/internal.h b/src/internal.h index 1997031a98..4184f148f7 100644 --- a/src/internal.h +++ b/src/internal.h @@ -242,4 +242,76 @@ /* divide value by size, rounding up */ # define VIR_DIV_UP(value, size) (((value) + (size) - 1) / (size)) + +# if WITH_DTRACE +# ifndef LIBVIRT_PROBES_H +# define LIBVIRT_PROBES_H +# include "probes.h" +# endif /* LIBVIRT_PROBES_H */ + +/* Systemtap 1.2 headers have a bug where they cannot handle a + * variable declared with array type. Work around this by casting all + * arguments. This is some gross use of the preprocessor because + * PROBE is a var-arg macro, but it is better than the alternative of + * making all callers to PROBE have to be aware of the issues. And + * hopefully, if we ever add a call to PROBE with other than 9 + * end arguments, you can figure out the pattern to extend this hack. + */ +# define VIR_COUNT_ARGS(...) VIR_ARG11(__VA_ARGS__, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1) +# define VIR_ARG11(_1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, ...) _11 +# define VIR_ADD_CAST_EXPAND(a, b, ...) VIR_ADD_CAST_PASTE(a, b, __VA_ARGS__) +# define VIR_ADD_CAST_PASTE(a, b, ...) a##b(__VA_ARGS__) + +/* The double cast is necessary to silence gcc warnings; any pointer + * can safely go to intptr_t and back to void *, which collapses + * arrays into pointers; while any integer can be widened to intptr_t + * then cast to void *. */ +# define VIR_ADD_CAST(a) ((void *)(intptr_t)(a)) +# define VIR_ADD_CAST1(a) \ + VIR_ADD_CAST(a) +# define VIR_ADD_CAST2(a, b) \ + VIR_ADD_CAST(a), VIR_ADD_CAST(b) +# define VIR_ADD_CAST3(a, b, c) \ + VIR_ADD_CAST(a), VIR_ADD_CAST(b), VIR_ADD_CAST(c) +# define VIR_ADD_CAST4(a, b, c, d) \ + VIR_ADD_CAST(a), VIR_ADD_CAST(b), VIR_ADD_CAST(c), \ + VIR_ADD_CAST(d) +# define VIR_ADD_CAST5(a, b, c, d, e) \ + VIR_ADD_CAST(a), VIR_ADD_CAST(b), VIR_ADD_CAST(c), \ + VIR_ADD_CAST(d), VIR_ADD_CAST(e) +# define VIR_ADD_CAST6(a, b, c, d, e, f) \ + VIR_ADD_CAST(a), VIR_ADD_CAST(b), VIR_ADD_CAST(c), \ + VIR_ADD_CAST(d), VIR_ADD_CAST(e), VIR_ADD_CAST(f) +# define VIR_ADD_CAST7(a, b, c, d, e, f, g) \ + VIR_ADD_CAST(a), VIR_ADD_CAST(b), VIR_ADD_CAST(c), \ + VIR_ADD_CAST(d), VIR_ADD_CAST(e), VIR_ADD_CAST(f), \ + VIR_ADD_CAST(g) +# define VIR_ADD_CAST8(a, b, c, d, e, f, g, h) \ + VIR_ADD_CAST(a), VIR_ADD_CAST(b), VIR_ADD_CAST(c), \ + VIR_ADD_CAST(d), VIR_ADD_CAST(e), VIR_ADD_CAST(f), \ + VIR_ADD_CAST(g), VIR_ADD_CAST(h) +# define VIR_ADD_CAST9(a, b, c, d, e, f, g, h, i) \ + VIR_ADD_CAST(a), VIR_ADD_CAST(b), VIR_ADD_CAST(c), \ + VIR_ADD_CAST(d), VIR_ADD_CAST(e), VIR_ADD_CAST(f), \ + VIR_ADD_CAST(g), VIR_ADD_CAST(h), VIR_ADD_CAST(i) + +# define VIR_ADD_CASTS(...) \ + VIR_ADD_CAST_EXPAND(VIR_ADD_CAST, VIR_COUNT_ARGS(__VA_ARGS__), \ + __VA_ARGS__) + +# define PROBE_EXPAND(NAME, ARGS) NAME(ARGS) +# define PROBE(NAME, FMT, ...) \ + VIR_DEBUG_INT("trace." __FILE__ , __func__, __LINE__, \ + #NAME ": " FMT, __VA_ARGS__); \ + if (LIBVIRT_ ## NAME ## _ENABLED()) { \ + PROBE_EXPAND(LIBVIRT_ ## NAME, \ + VIR_ADD_CASTS(__VA_ARGS__)); \ + } +# else +# define PROBE(NAME, FMT, ...) \ + VIR_DEBUG_INT("trace." __FILE__, __func__, __LINE__, \ + #NAME ": " FMT, __VA_ARGS__); +# endif + + #endif /* __VIR_INTERNAL_H__ */ diff --git a/src/probes.d b/src/probes.d new file mode 100644 index 0000000000..6d95c846be --- /dev/null +++ b/src/probes.d @@ -0,0 +1,72 @@ +provider libvirt { + # file: src/util/event_poll.c + # prefix: event_poll + probe event_poll_add_handle(int watch, int fd, int events, void *cb, void *opaque, void *ff); + probe event_poll_update_handle(int watch, int events); + probe event_poll_remove_handle(int watch); + probe event_poll_dispatch_handle(int watch, int events); + probe event_poll_purge_handle(int watch); + + probe event_poll_add_timeout(int timer, int frequency, void *cb, void *opaque, void *ff); + probe event_poll_update_timeout(int timer, int frequency); + probe event_poll_remove_timeout(int timer); + probe event_poll_dispatch_timeout(int timer); + probe event_poll_purge_timeout(int timer); + + probe event_poll_run(int nfds, int timeout); + + + # file: src/rpc/virnetsocket.c + # prefix: rpc + probe rpc_socket_new(void *sock, int refs, int fd, int errfd, int pid, const char *localAddr, const char *remoteAddr); + probe rpc_socket_ref(void *sock, int refs); + probe rpc_socket_free(void *sock, int refs); + + + # file: src/rpc/virnetserverclient.c + # prefix: rpc + probe rpc_server_client_new(void *client, int refs, void *sock); + probe rpc_server_client_ref(void *client, int refs); + probe rpc_server_client_free(void *client, int refs); + + probe rpc_server_client_msg_tx_queue(void *client, int len, int prog, int vers, int proc, int type, int status, int serial); + probe rpc_server_client_msg_rx(void *client, int len, int prog, int vers, int proc, int type, int status, int serial); + + + # file: src/rpc/virnetclient.c + # prefix: rpc + probe rpc_client_new(void *client, int refs, void *sock); + probe rpc_client_ref(void *client, int refs); + probe rpc_client_free(void *client, int refs); + + probe rpc_client_msg_tx_queue(void *client, int len, int prog, int vers, int proc, int type, int status, int serial); + probe rpc_client_msg_rx(void *client, int len, int prog, int vers, int proc, int type, int status, int serial); + + + # file: daemon/libvirtd.c + # prefix: rpc + probe rpc_server_client_auth_allow(void *client, int authtype, const char *identity); + probe rpc_server_client_auth_deny(void *client, int authtype, const char *identity); + probe rpc_server_client_auth_fail(void *client, int authtype); + + + # file: src/rpc/virnettlscontext.c + # prefix: rpc + probe rpc_tls_context_new(void *ctxt, int refs, const char *cacert, const char *cacrl, + const char *cert, const char *key, int sanityCheckCert, int requireValidCert, int isServer); + probe rpc_tls_context_ref(void *ctxt, int refs); + probe rpc_tls_context_free(void *ctxt, int refs); + + probe rpc_tls_context_session_allow(void *ctxt, void *sess, const char *dname); + probe rpc_tls_context_session_deny(void *ctxt, void *sess, const char *dname); + probe rpc_tls_context_session_fail(void *ctxt, void *sess); + + + probe rpc_tls_session_new(void *sess, void *ctxt, int refs, const char *hostname, int isServer); + probe rpc_tls_session_ref(void *sess, int refs); + probe rpc_tls_session_free(void *sess, int refs); + + probe rpc_tls_session_handshake_pass(void *sess); + probe rpc_tls_session_handshake_fail(void *sess); + +}; diff --git a/src/rpc/gensystemtap.pl b/src/rpc/gensystemtap.pl new file mode 100755 index 0000000000..1cf9c0fb10 --- /dev/null +++ b/src/rpc/gensystemtap.pl @@ -0,0 +1,195 @@ +#!/usr/bin/perl +# +# 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 +# +# Generate a set of systemtap functions for translating various +# RPC enum values into strings +# +# perl gensystemtap.pl */*.x > libvirt_functions.stp +# + +use strict; + +my %funcs; + +my %type; +my %status; +my %auth; + +my $instatus = 0; +my $intype = 0; +my $inauth = 0; +while (<>) { + if (/enum\s+virNetMessageType/) { + $intype = 1; + } elsif (/enum\s+virNetMessageStatus/) { + $instatus = 1; + } elsif (/enum remote_auth_type/) { + $inauth = 1; + } elsif (/}/) { + $instatus = $intype = $inauth = 0; + } elsif ($instatus) { + if (/^\s+VIR_NET_(\w+)\s*=\s*(\d+),?$/) { + $status{$2} = lc $1; + } + } elsif ($intype) { + if (/^\s+VIR_NET_(\w+)\s*=\s*(\d+),?$/) { + $type{$2} = lc $1; + } + } elsif ($inauth) { + if (/^\s+REMOTE_AUTH_(\w+)\s*=\s*(\d+),?$/) { + $auth{$2} = lc $1; + } + } else { + if (/(\w+)_PROGRAM\s*=\s*0x([a-fA-F0-9]+)\s*;/) { + $funcs{lc $1} = { id => hex($2), version => undef, progs => [] }; + } elsif (/(\w+)_PROTOCOL_VERSION\s*=\s*(\d+)\s*;/) { + $funcs{lc $1}->{version} = $2; + } elsif (/(\w+)_PROC_(.*?)\s+=\s+(\d+)/) { + $funcs{lc $1}->{progs}->[$3] = lc $2; + } + } +} + +print <{id}, ") {\n"; + print " programstr = \"", $prog, "\"\n"; +} +print <{id}, " && version == ", $funcs{$prog}->{version}, ") {\n"; + + my $pfirst = 1; + for (my $id = 1 ; $id <= $#{$funcs{$prog}->{progs}} ; $id++) { + my $cond = $pfirst ? "if" : "} else if"; + $pfirst = 0; + print " $cond (proc == $id) {\n"; + print " procstr = \"", $funcs{$prog}->{progs}->[$id], "\";\n"; + } + print " } else {\n"; + print " procstr = \"unknown\";\n"; + print " verbose = 1;\n"; + print " }\n"; +} +print <refs); + PROBE(RPC_CLIENT_NEW, + "client=%p refs=%d sock=%p", + client, client->refs, client->sock); + return client; no_memory: @@ -228,7 +231,9 @@ void virNetClientRef(virNetClientPtr client) { virNetClientLock(client); client->refs++; - VIR_DEBUG("client=%p refs=%d", client, client->refs); + PROBE(RPC_CLIENT_REF, + "client=%p refs=%d", + client, client->refs); virNetClientUnlock(client); } @@ -261,7 +266,9 @@ void virNetClientFree(virNetClientPtr client) return; virNetClientLock(client); - VIR_DEBUG("client=%p refs=%d", client, client->refs); + PROBE(RPC_CLIENT_FREE, + "client=%p refs=%d", + client, client->refs); client->refs--; if (client->refs > 0) { virNetClientUnlock(client); @@ -680,10 +687,11 @@ virNetClientCallDispatch(virNetClientPtr client) if (virNetMessageDecodeHeader(&client->msg) < 0) return -1; - VIR_DEBUG("Incoming message prog %d vers %d proc %d type %d status %d serial %d", - client->msg.header.prog, client->msg.header.vers, - client->msg.header.proc, client->msg.header.type, - client->msg.header.status, client->msg.header.serial); + PROBE(RPC_CLIENT_MSG_RX, + "client=%p len=%zu prog=%u vers=%u proc=%u type=%u status=%u serial=%u", + client, client->msg.bufferLength, + client->msg.header.prog, client->msg.header.vers, client->msg.header.proc, + client->msg.header.type, client->msg.header.status, client->msg.header.serial); switch (client->msg.header.type) { case VIR_NET_REPLY: /* Normal RPC replies */ @@ -1197,6 +1205,12 @@ int virNetClientSend(virNetClientPtr client, virNetClientCallPtr call; int ret = -1; + PROBE(RPC_CLIENT_MSG_TX_QUEUE, + "client=%p len=%zu prog=%u vers=%u proc=%u type=%u status=%u serial=%u", + client, msg->bufferLength, + msg->header.prog, msg->header.vers, msg->header.proc, + msg->header.type, msg->header.status, msg->header.serial); + if (expectReply && (msg->bufferLength != 0) && (msg->header.status == VIR_NET_CONTINUE)) { diff --git a/src/rpc/virnetserverclient.c b/src/rpc/virnetserverclient.c index 412814def9..05077d65bb 100644 --- a/src/rpc/virnetserverclient.c +++ b/src/rpc/virnetserverclient.c @@ -328,7 +328,9 @@ virNetServerClientPtr virNetServerClientNew(virNetSocketPtr sock, client->rx->bufferLength = VIR_NET_MESSAGE_LEN_MAX; client->nrequests = 1; - VIR_DEBUG("client=%p refs=%d", client, client->refs); + PROBE(RPC_SERVER_CLIENT_NEW, + "client=%p refs=%d sock=%p", + client, client->refs, client->sock); return client; @@ -343,7 +345,9 @@ void virNetServerClientRef(virNetServerClientPtr client) { virNetServerClientLock(client); client->refs++; - VIR_DEBUG("client=%p refs=%d", client, client->refs); + PROBE(RPC_SERVER_CLIENT_REF, + "client=%p refs=%d", + client, client->refs); virNetServerClientUnlock(client); } @@ -535,7 +539,9 @@ void virNetServerClientFree(virNetServerClientPtr client) return; virNetServerClientLock(client); - VIR_DEBUG("client=%p refs=%d", client, client->refs); + PROBE(RPC_SERVER_CLIENT_FREE, + "client=%p refs=%d", + client, client->refs); client->refs--; if (client->refs > 0) { @@ -772,6 +778,12 @@ readmore: return; } + PROBE(RPC_SERVER_CLIENT_MSG_RX, + "client=%p len=%zu prog=%u vers=%u proc=%u type=%u status=%u serial=%u", + client, msg->bufferLength, + msg->header.prog, msg->header.vers, msg->header.proc, + msg->header.type, msg->header.status, msg->header.serial); + /* Maybe send off for queue against a filter */ filter = client->filters; while (filter) { @@ -979,6 +991,11 @@ int virNetServerClientSendMessage(virNetServerClientPtr client, virNetServerClientLock(client); if (client->sock && !client->wantClose) { + PROBE(RPC_SERVER_CLIENT_MSG_TX_QUEUE, + "client=%p len=%zu prog=%u vers=%u proc=%u type=%u status=%u serial=%u", + client, msg->bufferLength, + msg->header.prog, msg->header.vers, msg->header.proc, + msg->header.type, msg->header.status, msg->header.serial); virNetMessageQueuePush(&client->tx, msg); virNetServerClientUpdateEvent(client); diff --git a/src/rpc/virnetsocket.c b/src/rpc/virnetsocket.c index 93e062a1ff..e4289b10f3 100644 --- a/src/rpc/virnetsocket.c +++ b/src/rpc/virnetsocket.c @@ -170,8 +170,10 @@ static virNetSocketPtr virNetSocketNew(virSocketAddrPtr localAddr, sock->client = isClient; - VIR_DEBUG("sock=%p localAddrStr=%s remoteAddrStr=%s", - sock, NULLSTR(sock->localAddrStr), NULLSTR(sock->remoteAddrStr)); + PROBE(RPC_SOCKET_NEW, + "sock=%p refs=%d fd=%d errfd=%d pid=%d localAddr=%s, remoteAddr=%s", + sock, sock->refs, fd, errfd, + pid, NULLSTR(sock->localAddrStr), NULLSTR(sock->remoteAddrStr)); return sock; @@ -659,6 +661,9 @@ void virNetSocketRef(virNetSocketPtr sock) { virMutexLock(&sock->lock); sock->refs++; + PROBE(RPC_SOCKET_REF, + "sock=%p refs=%d", + sock, sock->refs); virMutexUnlock(&sock->lock); } @@ -669,6 +674,10 @@ void virNetSocketFree(virNetSocketPtr sock) return; virMutexLock(&sock->lock); + PROBE(RPC_SOCKET_FREE, + "sock=%p refs=%d", + sock, sock->refs); + sock->refs--; if (sock->refs > 0) { virMutexUnlock(&sock->lock); diff --git a/src/rpc/virnettlscontext.c b/src/rpc/virnettlscontext.c index f3cc7696e4..74a61e0783 100644 --- a/src/rpc/virnettlscontext.c +++ b/src/rpc/virnettlscontext.c @@ -650,9 +650,6 @@ static virNetTLSContextPtr virNetTLSContextNew(const char *cacert, char *gnutlsdebug; int err; - VIR_DEBUG("cacert=%s cacrl=%s cert=%s key=%s sanityCheckCert=%d requireValid=%d isServer=%d", - cacert, NULLSTR(cacrl), cert, key, sanityCheckCert, requireValidCert, isServer); - if (VIR_ALLOC(ctxt) < 0) { virReportOOMError(); return NULL; @@ -721,6 +718,10 @@ static virNetTLSContextPtr virNetTLSContextNew(const char *cacert, ctxt->x509dnWhitelist = x509dnWhitelist; ctxt->isServer = isServer; + PROBE(RPC_TLS_CONTEXT_NEW, + "ctxt=%p refs=%d cacert=%s cacrl=%s cert=%s key=%s sanityCheckCert=%d requireValidCert=%d isServer=%d", + ctxt, ctxt->refs, cacert, NULLSTR(cacrl), cert, key, sanityCheckCert, requireValidCert, isServer); + return ctxt; error: @@ -933,6 +934,9 @@ void virNetTLSContextRef(virNetTLSContextPtr ctxt) { virMutexLock(&ctxt->lock); ctxt->refs++; + PROBE(RPC_TLS_CONTEXT_REF, + "ctxt=%p refs=%d", + ctxt, ctxt->refs); virMutexUnlock(&ctxt->lock); } @@ -1056,24 +1060,24 @@ static int virNetTLSContextValidCertificate(virNetTLSContextPtr ctxt, gnutls_x509_crt_deinit(cert); } -#if 0 - PROBE(CLIENT_TLS_ALLOW, "fd=%d, name=%s", - virNetServerClientGetFD(client), name); -#endif + PROBE(RPC_TLS_CONTEXT_SESSION_ALLOW, + "ctxt=%p sess=%p dname=%s", + ctxt, sess, dname); + return 0; authdeny: -#if 0 - PROBE(CLIENT_TLS_DENY, "fd=%d, name=%s", - virNetServerClientGetFD(client), name); -#endif + PROBE(RPC_TLS_CONTEXT_SESSION_DENY, + "ctxt=%p sess=%p dname=%s", + ctxt, sess, dname); + return -1; authfail: -#if 0 - PROBE(CLIENT_TLS_FAIL, "fd=%d", - virNetServerClientGetFD(client)); -#endif + PROBE(RPC_TLS_CONTEXT_SESSION_FAIL, + "ctxt=%p sess=%p", + ctxt, sess); + return -1; } @@ -1111,6 +1115,9 @@ void virNetTLSContextFree(virNetTLSContextPtr ctxt) return; virMutexLock(&ctxt->lock); + PROBE(RPC_TLS_CONTEXT_FREE, + "ctxt=%p refs=%d", + ctxt, ctxt->refs); ctxt->refs--; if (ctxt->refs > 0) { virMutexUnlock(&ctxt->lock); @@ -1225,6 +1232,10 @@ virNetTLSSessionPtr virNetTLSSessionNew(virNetTLSContextPtr ctxt, sess->isServer = ctxt->isServer; + PROBE(RPC_TLS_SESSION_NEW, + "sess=%p refs=%d ctxt=%p hostname=%s isServer=%d", + sess, sess->refs, ctxt, hostname, sess->isServer); + return sess; error: @@ -1237,6 +1248,9 @@ void virNetTLSSessionRef(virNetTLSSessionPtr sess) { virMutexLock(&sess->lock); sess->refs++; + PROBE(RPC_TLS_SESSION_REF, + "sess=%p refs=%d", + sess, sess->refs); virMutexUnlock(&sess->lock); } @@ -1388,6 +1402,9 @@ void virNetTLSSessionFree(virNetTLSSessionPtr sess) return; virMutexLock(&sess->lock); + PROBE(RPC_TLS_SESSION_FREE, + "sess=%p refs=%d", + sess, sess->refs); sess->refs--; if (sess->refs > 0) { virMutexUnlock(&sess->lock); diff --git a/src/util/event_poll.c b/src/util/event_poll.c index e8679b8e59..0b75471a37 100644 --- a/src/util/event_poll.c +++ b/src/util/event_poll.c @@ -109,7 +109,6 @@ int virEventPollAddHandle(int fd, int events, void *opaque, virFreeCallback ff) { int watch; - EVENT_DEBUG("Add handle fd=%d events=%d cb=%p opaque=%p", fd, events, cb, opaque); virMutexLock(&eventLoop.lock); if (eventLoop.handlesCount == eventLoop.handlesAlloc) { EVENT_DEBUG("Used %zu handle slots, adding at least %d more", @@ -135,6 +134,10 @@ int virEventPollAddHandle(int fd, int events, eventLoop.handlesCount++; virEventPollInterruptLocked(); + + PROBE(EVENT_POLL_ADD_HANDLE, + "watch=%d fd=%d events=%d cb=%p opaque=%p ff=%p", + watch, fd, events, cb, opaque, ff); virMutexUnlock(&eventLoop.lock); return watch; @@ -142,7 +145,9 @@ int virEventPollAddHandle(int fd, int events, void virEventPollUpdateHandle(int watch, int events) { int i; - EVENT_DEBUG("Update handle w=%d e=%d", watch, events); + PROBE(EVENT_POLL_UPDATE_HANDLE, + "watch=%d events=%d", + watch, events); if (watch <= 0) { VIR_WARN("Ignoring invalid update watch %d", watch); @@ -169,7 +174,9 @@ void virEventPollUpdateHandle(int watch, int events) { */ int virEventPollRemoveHandle(int watch) { int i; - EVENT_DEBUG("Remove handle w=%d", watch); + PROBE(EVENT_POLL_REMOVE_HANDLE, + "watch=%d", + watch); if (watch <= 0) { VIR_WARN("Ignoring invalid remove watch %d", watch); @@ -206,7 +213,7 @@ int virEventPollAddTimeout(int frequency, { unsigned long long now; int ret; - EVENT_DEBUG("Adding timer %d with %d ms freq", nextTimer, frequency); + if (virTimeMs(&now) < 0) { return -1; } @@ -234,6 +241,10 @@ int virEventPollAddTimeout(int frequency, eventLoop.timeoutsCount++; ret = nextTimer-1; virEventPollInterruptLocked(); + + PROBE(EVENT_POLL_ADD_TIMEOUT, + "timer=%d frequency=%d cb=%p opaque=%p ff=%p", + ret, frequency, cb, opaque, ff); virMutexUnlock(&eventLoop.lock); return ret; } @@ -242,7 +253,9 @@ void virEventPollUpdateTimeout(int timer, int frequency) { unsigned long long now; int i; - EVENT_DEBUG("Updating timer %d timeout with %d ms freq", timer, frequency); + PROBE(EVENT_POLL_UPDATE_TIMEOUT, + "timer=%d frequency=%d", + timer, frequency); if (timer <= 0) { VIR_WARN("Ignoring invalid update timer %d", timer); @@ -274,7 +287,9 @@ void virEventPollUpdateTimeout(int timer, int frequency) */ int virEventPollRemoveTimeout(int timer) { int i; - EVENT_DEBUG("Remove timer %d", timer); + PROBE(EVENT_POLL_REMOVE_TIMEOUT, + "timer=%d", + timer); if (timer <= 0) { VIR_WARN("Ignoring invalid remove timer %d", timer); @@ -417,6 +432,9 @@ static int virEventPollDispatchTimeouts(void) eventLoop.timeouts[i].expiresAt = now + eventLoop.timeouts[i].frequency; + PROBE(EVENT_POLL_DISPATCH_TIMEOUT, + "timer=%d", + timer); virMutexUnlock(&eventLoop.lock); (cb)(timer, opaque); virMutexLock(&eventLoop.lock); @@ -464,8 +482,9 @@ static int virEventPollDispatchHandles(int nfds, struct pollfd *fds) { int watch = eventLoop.handles[i].watch; void *opaque = eventLoop.handles[i].opaque; int hEvents = virEventPollFromNativeEvents(fds[n].revents); - EVENT_DEBUG("Dispatch n=%d f=%d w=%d e=%d %p", i, - fds[n].fd, watch, fds[n].revents, opaque); + PROBE(EVENT_POLL_DISPATCH_HANDLE, + "watch=%d events=%d", + watch, hEvents); virMutexUnlock(&eventLoop.lock); (cb)(watch, fds[n].fd, hEvents, opaque); virMutexLock(&eventLoop.lock); @@ -494,8 +513,9 @@ static void virEventPollCleanupTimeouts(void) { continue; } - EVENT_DEBUG("Purging timeout %d with id %d", i, - eventLoop.timeouts[i].timer); + PROBE(EVENT_POLL_PURGE_TIMEOUT, + "timer=%d", + eventLoop.timeouts[i].timer); if (eventLoop.timeouts[i].ff) { virFreeCallback ff = eventLoop.timeouts[i].ff; void *opaque = eventLoop.timeouts[i].opaque; @@ -541,6 +561,9 @@ static void virEventPollCleanupHandles(void) { continue; } + PROBE(EVENT_POLL_PURGE_HANDLE, + "watch=%d", + eventLoop.handles[i].watch); if (eventLoop.handles[i].ff) { virFreeCallback ff = eventLoop.handles[i].ff; void *opaque = eventLoop.handles[i].opaque; @@ -590,7 +613,9 @@ int virEventPollRunOnce(void) { virMutexUnlock(&eventLoop.lock); retry: - EVENT_DEBUG("Poll on %d handles %p timeout %d", nfds, fds, timeout); + PROBE(EVENT_POLL_RUN, + "nhandles=%d imeout=%d", + nfds, timeout); ret = poll(fds, nfds, timeout); if (ret < 0) { EVENT_DEBUG("Poll got error event %d", errno);