From: "Daniel P. Berrange" <berrange(a)redhat.com&gt; This change adds some systemtap/dtrace probes to the QEMU monitor client code. In particular it allows watching of all operations for a VM * examples/systemtap/qemu-monitor.stp: Watch all monitor commands * src/Makefile.am: Passing libdir/bindir/sbindir to dtrace2systemtap.pl * src/dtrace2systemtap.pl: Accept libdir/bindir/sbindir as args and look for '# binary:' comment to mark probes against libvirtd vs libvirt.so * src/qemu/qemu_monitor.c, src/qemu/qemu_monitor_json.c, src/qemu/qemu_monitor_text.c: Add probes for key functions --- examples/systemtap/qemu-monitor.stp | 81 +++++++++++++++++++++++++++++++++++ src/Makefile.am | 2 +- src/dtrace2systemtap.pl | 15 ++++++- src/probes.d | 20 +++++++++ src/qemu/qemu_monitor.c | 31 ++++++++++++- src/qemu/qemu_monitor_json.c | 4 ++ src/qemu/qemu_monitor_text.c | 3 + 7 files changed, 150 insertions(+), 6 deletions(-) create mode 100644 examples/systemtap/qemu-monitor.stp diff --git a/examples/systemtap/qemu-monitor.stp b/examples/systemtap/qemu-monitor.stp new file mode 100644 index 0000000..647eacc --- /dev/null +++ b/examples/systemtap/qemu-monitor.stp @@ -0,0 +1,81 @@ +#!/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(a)redhat.com&gt; +# +# This script will monitor all messages sent/received between libvirt +# and the QEMU monitor +# +# stap qemu-monitor.stp +# 0.000 begin +# 3.848 ! 0x7f2dc00017b0 {"timestamp": {"seconds": 1319466931, "microseconds": 187755}, "event": "SHUTDOWN"} +# 5.773 > 0x7f2dc0007960 {"execute":"qmp_capabilities","id":"libvirt-1"} +# 5.774 < 0x7f2dc0007960 {"return": {}, "id": "libvirt-1"} +# 5.774 > 0x7f2dc0007960 {"execute":"query-commands","id":"libvirt-2"} +# 5.777 < 0x7f2dc0007960 {"return": [{"name": "quit"}, {"name": ....snip.... +# 5.777 > 0x7f2dc0007960 {"execute":"query-chardev","id":"libvirt-3"} +# 5.778 < 0x7f2dc0007960 {"return": [{"filename": ....snip.... +# 5.779 > 0x7f2dc0007960 {"execute":"query-cpus","id":"libvirt-4"} +# 5.780 < 0x7f2dc0007960 {"return": [{"current": true, "CPU": 0, "pc": 1048560, "halted": false, "thread_id": 13299}], "id": "libvirt-4"} +# 5.780 > 0x7f2dc0007960 {"execute":"set_password","arguments":{"protocol":"vnc","password":"123456","connected":"keep"},"id":"libvirt-5"} +# 5.782 < 0x7f2dc0007960 {"return": {}, "id": "libvirt-5"} +# 5.782 > 0x7f2dc0007960 {"execute":"expire_password","arguments":{"protocol":"vnc","time":"never"},"id":"libvirt-6"} +# 5.783 < 0x7f2dc0007960 {"return": {}, "id": "libvirt-6"} +# 5.783 > 0x7f2dc0007960 {"execute":"balloon","arguments":{"value":224395264},"id":"libvirt-7"} +# 5.785 < 0x7f2dc0007960 {"return": {}, "id": "libvirt-7"} +# 5.785 > 0x7f2dc0007960 {"execute":"cont","id":"libvirt-8"} +# 5.789 ! 0x7f2dc0007960 {"timestamp": {"seconds": 1319466933, "microseconds": 129980}, "event": "RESUME"} +# 5.789 < 0x7f2dc0007960 {"return": {}, "id": "libvirt-8"} +# 7.537 ! 0x7f2dc0007960 {"timestamp": {"seconds": 1319466934, "microseconds": 881214}, "event": "SHUTDOWN"} +# + + +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); +} + + +# Just so we know the script is now running +probe begin { + start = gettimeofday_ns() / (1000*1000) + print_ts("begin") +} + +probe libvirt.qemu.monitor_send_msg { + if (fd != -1) { + print_ts(sprintf("> %p %s (fd=%d)", mon, substr(msg, 0, strlen(msg)-2), fd)); + } else { + print_ts(sprintf("> %p %s", mon, substr(msg, 0, strlen(msg)-2))); + } +} + +probe libvirt.qemu.monitor_recv_reply { + print_ts(sprintf("< %p %s", mon, reply)); +} + +probe libvirt.qemu.monitor_recv_event { + print_ts(sprintf("! %p %s", mon, event)); +} + diff --git a/src/Makefile.am b/src/Makefile.am index 2555f81..81ec730 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -1288,7 +1288,7 @@ 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 $< > $@ + $(AM_V_GEN)perl -w $(srcdir)/dtrace2systemtap.pl $(bindir) $(sbindir) $(libdir) $< > $@ CLEANFILES += probes.h probes.o libvirt_functions.stp libvirt_probes.stp endif diff --git a/src/dtrace2systemtap.pl b/src/dtrace2systemtap.pl index fab066b..b577eac 100755 --- a/src/dtrace2systemtap.pl +++ b/src/dtrace2systemtap.pl @@ -31,6 +31,10 @@ my $file; my @files; my %files; +my $bindir = shift @ARGV; +my $sbindir = shift @ARGV; +my $libdir = shift @ARGV; + my $probe; my $args; @@ -47,6 +51,8 @@ while (<>) { $files{$file} = { prefix => undef, probes => [] }; } elsif (m,^\s*\#\s*prefix:\s*(\S+)\s*$,) { $files{$file}->{prefix} = $1; + } elsif (m,^\s*\#\s*binary:\s*(\S+)\s*$,) { + $files{$file}->{binary} = $1; } else { if (m,\s*probe\s+([a-zA-Z0-9_]+)\((.*?)(\);)?$,) { $probe = $1; @@ -66,7 +72,7 @@ while (<>) { die "unexpected data $_ on line $."; } } else { - die "unexpected data $_ on line $."; + #die "unexpected data $_ on line $."; } } } @@ -84,7 +90,12 @@ foreach my $file (@files) { my $pname = $name; $pname =~ s/${prefix}_/libvirt.$prefix./; - print "probe $pname = process(\"libvirt.so\").mark(\"$name\") {\n"; + my $binary = "$libdir/libvirt.so"; + if (exists $files{$file}->{binary}) { + $binary = $sbindir . "/" . $files{$file}->{binary}; + } + + print "probe $pname = process(\"$binary\").mark(\"$name\") {\n"; my @args = split /,/, $args; for (my $i = 0 ; $i <= $#args ; $i++) { diff --git a/src/probes.d b/src/probes.d index 6d95c84..7f66ac0 100644 --- a/src/probes.d +++ b/src/probes.d @@ -69,4 +69,24 @@ provider libvirt { probe rpc_tls_session_handshake_pass(void *sess); probe rpc_tls_session_handshake_fail(void *sess); + + # file: src/qemu/qemu_monitor.c + # prefix: qemu + # binary: libvirtd + # Monitor lifecycle + probe qemu_monitor_new(void *mon, int refs, int fd); + probe qemu_monitor_ref(void *mon, int refs); + probe qemu_monitor_unref(void *mon, int refs); + probe qemu_monitor_close(void *monm, int refs); + + # High level monitor message processing + probe qemu_monitor_send_msg(void *mon, const char *msg, int fd); + probe qemu_monitor_recv_reply(void *mon, const char *reply); + probe qemu_monitor_recv_event(void *mon, const char *event); + + # Low level monitor I/O processing + probe qemu_monitor_io_process(void *mon, const char *buf, unsigned int len); + probe qemu_monitor_io_read(void *mon, const char *buf, unsigned int len, int ret, int errno); + probe qemu_monitor_io_write(void *mon, const char *buf, unsigned int len, int ret, int errno); + probe qemu_monitor_io_send_fd(void *mon, int fd, int ret, int errno); }; diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c index 182e63d..75429fa 100644 --- a/src/qemu/qemu_monitor.c +++ b/src/qemu/qemu_monitor.c @@ -183,6 +183,8 @@ static void qemuMonitorFree(qemuMonitorPtr mon) int qemuMonitorRef(qemuMonitorPtr mon) { mon->refs++; + PROBE(QEMU_MONITOR_UNREF, + "mon=%p refs=%d", mon, mon->refs); return mon->refs; } @@ -190,6 +192,8 @@ int qemuMonitorUnref(qemuMonitorPtr mon) { mon->refs--; + PROBE(QEMU_MONITOR_UNREF, + "mon=%p refs=%d", mon, mon->refs); if (mon->refs == 0) { qemuMonitorUnlock(mon); qemuMonitorFree(mon); @@ -305,6 +309,9 @@ qemuMonitorIOProcess(qemuMonitorPtr mon) # endif #endif + PROBE(QEMU_MONITOR_IO_PROCESS, + "mon=%p buf=%s len=%zu", mon, mon->buffer, mon->bufferOffset); + if (mon->json) len = qemuMonitorJSONIOProcess(mon, mon->buffer, mon->bufferOffset, @@ -403,6 +410,18 @@ qemuMonitorIOWrite(qemuMonitorPtr mon) mon->msg->txLength - mon->msg->txOffset, mon->msg->txFD); + PROBE(QEMU_MONITOR_IO_WRITE, + "mon=%p buf=%s len=%d ret=%d errno=%d", + mon, + mon->msg->txBuffer + mon->msg->txOffset, + mon->msg->txLength - mon->msg->txOffset, + done, errno); + + if (mon->msg->txFD != -1) + PROBE(QEMU_MONITOR_IO_SEND_FD, + "mon=%p fd=%d ret=%d errno=%d", + mon, mon->msg->txFD, done, errno); + if (done < 0) { if (errno == EAGAIN) return 0; @@ -696,7 +715,9 @@ qemuMonitorOpen(virDomainObjPtr vm, } qemuMonitorRef(mon); - VIR_DEBUG("New mon %p fd =%d watch=%d", mon, mon->fd, mon->watch); + PROBE(QEMU_MONITOR_NEW, + "mon=%p refs=%d fd=%d", + mon, mon->refs, mon->fd); qemuMonitorUnlock(mon); return mon; @@ -719,9 +740,9 @@ void qemuMonitorClose(qemuMonitorPtr mon) if (!mon) return; - VIR_DEBUG("mon=%p", mon); - qemuMonitorLock(mon); + PROBE(QEMU_MONITOR_CLOSE, + "mon=%p refs=%d", mon, mon->refs); if (mon->fd >= 0) { if (mon->watch) @@ -762,6 +783,10 @@ int qemuMonitorSend(qemuMonitorPtr mon, mon->msg = msg; qemuMonitorUpdateWatch(mon); + PROBE(QEMU_MONITOR_SEND_MSG, + "mon=%p msg=%s fd=%d", + mon, mon->msg->txBuffer, mon->msg->txFD); + while (!mon->msg->finished) { if (virCondWait(&mon->notify, &mon->lock) < 0) { qemuReportError(VIR_ERR_INTERNAL_ERROR, "%s", diff --git a/src/qemu/qemu_monitor_json.c b/src/qemu/qemu_monitor_json.c index cd8f1e5..2c4aee5 100644 --- a/src/qemu/qemu_monitor_json.c +++ b/src/qemu/qemu_monitor_json.c @@ -126,9 +126,13 @@ qemuMonitorJSONIOProcessLine(qemuMonitorPtr mon, if (virJSONValueObjectHasKey(obj, "QMP") == 1) { ret = 0; } else if (virJSONValueObjectHasKey(obj, "event") == 1) { + PROBE(QEMU_MONITOR_RECV_EVENT, + "mon=%p event=%s", mon, line); ret = qemuMonitorJSONIOProcessEvent(mon, obj); } else if (virJSONValueObjectHasKey(obj, "error") == 1 || virJSONValueObjectHasKey(obj, "return") == 1) { + PROBE(QEMU_MONITOR_RECV_REPLY, + "mon=%p reply=%s", mon, line); if (msg) { msg->rxObject = obj; msg->finished = 1; diff --git a/src/qemu/qemu_monitor_text.c b/src/qemu/qemu_monitor_text.c index 4774df9..c652321 100644 --- a/src/qemu/qemu_monitor_text.c +++ b/src/qemu/qemu_monitor_text.c @@ -198,6 +198,9 @@ int qemuMonitorTextIOProcess(qemuMonitorPtr mon ATTRIBUTE_UNUSED, VIR_DEBUG("Finished 0 byte reply"); #endif } + PROBE(QEMU_MONITOR_RECV_REPLY, + "mon=%p reply=%s", + mon, msg->rxBuffer); msg->finished = 1; used += end - (data + used); used += strlen(BASIC_PROMPT); -- 1.7.6.4