tests/qemu: boot-analysis: Add support for logging libvirt events.

This commit is contained in:
Richard W.M. Jones
2016-04-06 10:43:00 +01:00
parent 0008d794cf
commit b332d91bc9
2 changed files with 227 additions and 10 deletions

View File

@@ -84,6 +84,7 @@ boot_analysis_CPPFLAGS = \
-I$(top_srcdir)/gnulib/lib -I$(top_builddir)/gnulib/lib \
-I$(top_srcdir)/src -I$(top_builddir)/src
boot_analysis_CFLAGS = \
-pthread \
$(WARN_CFLAGS) $(WERROR_CFLAGS) \
$(PCRE_CFLAGS)
boot_analysis_LDADD = \

View File

@@ -64,6 +64,7 @@
#include <inttypes.h>
#include <string.h>
#include <unistd.h>
#include <fcntl.h>
#include <getopt.h>
#include <limits.h>
#include <time.h>
@@ -71,7 +72,10 @@
#include <error.h>
#include <ctype.h>
#include <assert.h>
#include <sys/types.h>
#include <sys/wait.h>
#include <math.h>
#include <pthread.h>
#include "guestfs.h"
#include "guestfs-internal-frontend.h"
@@ -84,20 +88,32 @@
*/
#define WARNING_THRESHOLD 1.0
struct pass_data pass_data[NR_TEST_PASSES];
size_t nr_activities;
struct activity *activities;
static const char *append = NULL;
static int force_colour = 0;
static int memsize = 0;
static int smp = 1;
static int verbose = 0;
static int libvirt_pipe[2] = { -1, -1 };
static ssize_t libvirt_pass = -1;
/* Because there is a separate thread which collects libvirt log data,
* we must protect the pass_data struct with a mutex. This only
* applies during the data collection passes.
*/
static pthread_mutex_t pass_data_lock = PTHREAD_MUTEX_INITIALIZER;
struct pass_data pass_data[NR_TEST_PASSES];
size_t nr_activities;
struct activity *activities;
static void run_test (void);
static struct event *add_event (struct pass_data *, uint64_t source);
static guestfs_h *create_handle (void);
static void set_up_event_handlers (guestfs_h *g, size_t pass);
static void libvirt_log_hack (int argc, char **argv);
static void start_libvirt_thread (size_t pass);
static void stop_libvirt_thread (void);
static void add_drive (guestfs_h *g);
static void check_pass_data (void);
static void dump_pass_data (void);
@@ -152,6 +168,8 @@ main (int argc, char *argv[])
{ "color", 0, 0, 0 },
{ "colour", 0, 0, 0 },
{ "memsize", 1, 0, 'm' },
{ "libvirt-pipe-0", 1, 0, 0 }, /* see libvirt_log_hack */
{ "libvirt-pipe-1", 1, 0, 0 },
{ "smp", 1, 0, 0 },
{ "verbose", 0, 0, 'v' },
{ 0, 0, 0, 0 }
@@ -173,12 +191,22 @@ main (int argc, char *argv[])
force_colour = 1;
break;
}
else if (STREQ (long_options[option_index].name, "libvirt-pipe-0")) {
if (sscanf (optarg, "%d", &libvirt_pipe[0]) != 1)
error (EXIT_FAILURE, 0,
"could not parse libvirt-pipe-0 parameter: %s", optarg);
break;
}
else if (STREQ (long_options[option_index].name, "libvirt-pipe-1")) {
if (sscanf (optarg, "%d", &libvirt_pipe[1]) != 1)
error (EXIT_FAILURE, 0,
"could not parse libvirt-pipe-1 parameter: %s", optarg);
break;
}
else if (STREQ (long_options[option_index].name, "smp")) {
if (sscanf (optarg, "%d", &smp) != 1) {
fprintf (stderr, "%s: could not parse smp parameter: %s\n",
guestfs_int_program_name, optarg);
exit (EXIT_FAILURE);
}
if (sscanf (optarg, "%d", &smp) != 1)
error (EXIT_FAILURE, 0,
"could not parse smp parameter: %s", optarg);
break;
}
fprintf (stderr, "%s: unknown long option: %s (%d)\n",
@@ -205,6 +233,8 @@ main (int argc, char *argv[])
}
}
libvirt_log_hack (argc, argv);
if (STRNEQ (host_cpu, "x86_64"))
fprintf (stderr, "WARNING: host_cpu != x86_64: This program may not work or give bogus results.\n");
@@ -230,10 +260,12 @@ run_test (void)
for (i = 0; i < NR_TEST_PASSES; ++i) {
g = create_handle ();
set_up_event_handlers (g, i);
start_libvirt_thread (i);
add_drive (g);
if (guestfs_launch (g) == -1)
exit (EXIT_FAILURE);
guestfs_close (g);
stop_libvirt_thread ();
printf (" pass %zu: %zu events collected in %" PRIi64 " ns\n",
i+1, pass_data[i].nr_events, pass_data[i].elapsed_ns);
@@ -266,7 +298,7 @@ run_test (void)
}
static struct event *
add_event (struct pass_data *data, uint64_t source)
add_event_unlocked (struct pass_data *data, uint64_t source)
{
struct event *ret;
@@ -282,6 +314,17 @@ add_event (struct pass_data *data, uint64_t source)
return ret;
}
static struct event *
add_event (struct pass_data *data, uint64_t source)
{
struct event *ret;
pthread_mutex_lock (&pass_data_lock);
ret = add_event_unlocked (data, source);
pthread_mutex_unlock (&pass_data_lock);
return ret;
}
/* Common function to create the handle and set various defaults. */
static guestfs_h *
create_handle (void)
@@ -590,6 +633,179 @@ set_up_event_handlers (guestfs_h *g, size_t pass)
guestfs_set_trace (g, 1);
}
/* libvirt debugging sucks in a number of concrete ways:
*
* - you can't get a synchronous callback from a log message
* - you can't enable logging per handle (only globally
* by setting environment variables)
* - you can't debug the daemon easily
* - it's very complex
* - it's very complex but not in ways that are practical or useful
*
* To get log messages at all, we need to create a pipe connected to a
* second thread, and when libvirt prints something to the pipe we log
* that.
*
* However that's not sufficient. Because logging is only enabled
* when libvirt examines environment variables at the start of the
* program, we need to create the pipe and then fork+exec a new
* instance of the whole program with the pipe and environment
* variables set up.
*/
static int is_libvirt_backend (guestfs_h *g);
static void *libvirt_log_thread (void *datavp);
static void
libvirt_log_hack (int argc, char **argv)
{
guestfs_h *g;
g = guestfs_create ();
if (!is_libvirt_backend (g)) {
guestfs_close (g);
return;
}
guestfs_close (g);
/* Have we set up the pipes and environment and forked yet? If not,
* do that first.
*/
if (libvirt_pipe[0] == -1 || libvirt_pipe[1] == -1) {
char log_outputs[64];
char **new_argv;
char param1[64], param2[64];
size_t i;
pid_t pid;
int status;
/* Create the pipe. NB: do NOT use O_CLOEXEC since we want to pass
* this pipe into a child process.
*/
if (pipe (libvirt_pipe) == -1)
error (EXIT_FAILURE, 0, "pipe2");
/* Create the environment variables to enable logging in libvirt. */
setenv ("LIBVIRT_DEBUG", "1", 1);
snprintf (log_outputs, sizeof log_outputs,
"1:file:/dev/fd/%d", libvirt_pipe[1]);
setenv ("LIBVIRT_LOG_OUTPUTS", log_outputs, 1);
/* Run self again. */
new_argv = malloc ((argc+3) * sizeof (char *));
if (new_argv == NULL)
error (EXIT_FAILURE, errno, "malloc");
for (i = 0; i < (size_t) argc; ++i)
new_argv[i] = argv[i];
snprintf (param1, sizeof param1, "--libvirt-pipe-0=%d", libvirt_pipe[0]);
new_argv[argc] = param1;
snprintf (param2, sizeof param2, "--libvirt-pipe-1=%d", libvirt_pipe[1]);
new_argv[argc+1] = param2;
new_argv[argc+2] = NULL;
pid = fork ();
if (pid == -1)
error (EXIT_FAILURE, errno, "fork");
if (pid == 0) { /* Child process. */
execvp (argv[0], new_argv);
perror ("execvp");
_exit (EXIT_FAILURE);
}
if (waitpid (pid, &status, 0) == -1)
error (EXIT_FAILURE, errno, "waitpid");
if (WIFEXITED (status))
exit (WEXITSTATUS (status));
error (EXIT_FAILURE, 0, "unexpected exit status from process: %d", status);
}
/* If we reach this else clause, then we have forked. Now we must
* create a thread to read events from the pipe. This must be
* constantly reading from the pipe, otherwise we will deadlock.
* During the warm-up phase we end up throwing away messages.
*/
else {
pthread_t thread;
pthread_attr_t attr;
int r;
r = pthread_attr_init (&attr);
if (r != 0)
error (EXIT_FAILURE, r, "pthread_attr_init");
r = pthread_attr_setdetachstate (&attr, PTHREAD_CREATE_DETACHED);
if (r != 0)
error (EXIT_FAILURE, r, "pthread_attr_setdetachstate");
r = pthread_create (&thread, &attr, libvirt_log_thread, NULL);
if (r != 0)
error (EXIT_FAILURE, r, "pthread_create");
pthread_attr_destroy (&attr);
}
}
static void
start_libvirt_thread (size_t pass)
{
/* In the non-libvirt case, this variable is ignored. */
pthread_mutex_lock (&pass_data_lock);
libvirt_pass = pass;
pthread_mutex_unlock (&pass_data_lock);
}
static void
stop_libvirt_thread (void)
{
/* In the non-libvirt case, this variable is ignored. */
pthread_mutex_lock (&pass_data_lock);
libvirt_pass = -1;
pthread_mutex_unlock (&pass_data_lock);
}
/* The separate "libvirt thread". It loops reading debug messages
* printed by libvirt and adds them to the pass_data.
*/
static void *
libvirt_log_thread (void *arg)
{
struct event *event;
CLEANUP_FREE char *buf = NULL;
ssize_t r;
buf = malloc (BUFSIZ);
if (buf == NULL)
error (EXIT_FAILURE, errno, "malloc");
while ((r = read (libvirt_pipe[0], buf, BUFSIZ)) > 0) {
pthread_mutex_lock (&pass_data_lock);
if (libvirt_pass == -1) goto discard;
event =
add_event_unlocked (&pass_data[libvirt_pass], GUESTFS_EVENT_LIBRARY);
event->message = strndup (buf, r);
if (event->message == NULL)
error (EXIT_FAILURE, errno, "strndup");
discard:
pthread_mutex_unlock (&pass_data_lock);
}
if (r == -1)
error (EXIT_FAILURE, errno, "libvirt_log_thread: read");
/* It's possible for the pipe to be closed (r == 0) if thread
* cancellation is delayed after the main thread exits, so just
* ignore that case and exit.
*/
pthread_exit (NULL);
}
static int
is_libvirt_backend (guestfs_h *g)
{
CLEANUP_FREE char *backend = guestfs_get_backend (g);
return backend &&
(STREQ (backend, "libvirt") || STRPREFIX (backend, "libvirt:"));
}
/* Sanity check the collected events. */
static void
check_pass_data (void)