From f009e084782ac692ce1a519b5255e9abf4a79632 Mon Sep 17 00:00:00 2001 From: "Richard W.M. Jones" Date: Wed, 6 Apr 2016 10:43:00 +0100 Subject: [PATCH] tests/qemu: boot-analysis: Add support for logging libvirt events. (cherry picked from commit b332d91bc9685e8992ede2c8a10655f26fd0395e) --- tests/qemu/Makefile.am | 1 + tests/qemu/boot-analysis.c | 236 +++++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 227 insertions(+), 10 deletions(-) diff --git a/tests/qemu/Makefile.am b/tests/qemu/Makefile.am index cc5cb6a..fdf643f 100644 --- a/tests/qemu/Makefile.am +++ b/tests/qemu/Makefile.am @@ -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 = \ diff --git a/tests/qemu/boot-analysis.c b/tests/qemu/boot-analysis.c index 37d8b3c..2a43976 100644 --- a/tests/qemu/boot-analysis.c +++ b/tests/qemu/boot-analysis.c @@ -64,6 +64,7 @@ #include #include #include +#include #include #include #include @@ -71,7 +72,10 @@ #include #include #include +#include +#include #include +#include #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) -- 1.8.3.1