Re: [PATCH v1 3/5] Add use of RCU for qemu_logfile.

[Alex Bennée]

Robert Foley <address@hidden> writes:

> This now allows changing the logfile while logging is active,
> and also solves the issue of a seg fault while changing the logfile.
>
> Any read access to the qemu_logfile handle will use
> the rcu_read_lock()/unlock() around the use of the handle.
> To fetch the handle we will use atomic_rcu_read().
> We also in many cases do a check for validity of the
> logfile handle before using it to deal with the case where the
> file is closed and set to NULL.
>
> The cases where we write to the qemu_logfile will use atomic_rcu_set().
> Writers will also use call_rcu() with a newly added qemu_logfile_free
> function for freeing/closing when readers have finished.
>
> Signed-off-by: Robert Foley <address@hidden>
> ---
> v1
>     - Changes for review comments.
>     - Minor changes to definition of QemuLogFile.
>     - Changed qemu_log_separate() to fix unbalanced and
>       remove qemu_log_enabled() check.
>     - changed qemu_log_lock() to include else.
>     - make qemu_logfile_free static.
>     - use g_assert(logfile) in qemu_logfile_free.
>     - Relocated unlock out of if/else in qemu_log_close(), and
>       in qemu_set_log().
> ---
>  include/qemu/log.h | 42 ++++++++++++++++++++++----
>  util/log.c         | 73 +++++++++++++++++++++++++++++++++-------------
>  include/exec/log.h | 33 ++++++++++++++++++---
>  tcg/tcg.c          | 12 ++++++--
>  4 files changed, 128 insertions(+), 32 deletions(-)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index a7c5b01571..528e1f9dd7 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -3,9 +3,16 @@
>
>  /* A small part of this API is split into its own header */
>  #include "qemu/log-for-trace.h"
> +#include "qemu/rcu.h"
> +
> +typedef struct QemuLogFile {
> +    struct rcu_head rcu;
> +    FILE *fd;
> +} QemuLogFile;
>
>  /* Private global variable, don't use */
> -extern FILE *qemu_logfile;
> +extern QemuLogFile *qemu_logfile;
> +
>
>  /*
>   * The new API:
> @@ -25,7 +32,16 @@ static inline bool qemu_log_enabled(void)
>   */
>  static inline bool qemu_log_separate(void)
>  {
> -    return qemu_logfile != NULL && qemu_logfile != stderr;
> +    QemuLogFile *logfile;
> +    bool res = false;
> +
> +    rcu_read_lock();
> +    logfile = atomic_rcu_read(&qemu_logfile);
> +    if (logfile && logfile->fd != stderr) {
> +        res = true;
> +    }
> +    rcu_read_unlock();
> +    return res;
>  }
>
>  #define CPU_LOG_TB_OUT_ASM (1 << 0)
> @@ -55,14 +71,23 @@ static inline bool qemu_log_separate(void)
>
>  static inline FILE *qemu_log_lock(void)
>  {
> -    qemu_flockfile(qemu_logfile);
> -    return logfile->fd;
> +    QemuLogFile *logfile;
> +    rcu_read_lock();
> +    logfile = atomic_rcu_read(&qemu_logfile);
> +    if (logfile) {
> +        qemu_flockfile(logfile->fd);
> +        return logfile->fd;
> +    } else {
> +        rcu_read_unlock();
> +        return NULL;
> +    }
>  }
>
>  static inline void qemu_log_unlock(FILE *fd)
>  {
>      if (fd) {
>          qemu_funlockfile(fd);
> +        rcu_read_unlock();
>      }
>  }
>
> @@ -73,9 +98,14 @@ static inline void qemu_log_unlock(FILE *fd)
>  static inline void GCC_FMT_ATTR(1, 0)
>  qemu_log_vprintf(const char *fmt, va_list va)
>  {
> -    if (qemu_logfile) {
> -        vfprintf(qemu_logfile, fmt, va);
> +    QemuLogFile *logfile;
> +
> +    rcu_read_lock();
> +    logfile = atomic_rcu_read(&qemu_logfile);
> +    if (logfile) {
> +        vfprintf(logfile->fd, fmt, va);
>      }
> +    rcu_read_unlock();
>  }
>
>  /* log only if a bit is set on the current loglevel mask:
> diff --git a/util/log.c b/util/log.c
> index c25643dc99..802b8de42e 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -28,7 +28,7 @@
>
>  static char *logfilename;
>  static QemuMutex qemu_logfile_mutex;
> -FILE *qemu_logfile;
> +QemuLogFile *qemu_logfile;
>  int qemu_loglevel;
>  static int log_append = 0;
>  static GArray *debug_regions;
> @@ -37,10 +37,14 @@ static GArray *debug_regions;
>  int qemu_log(const char *fmt, ...)
>  {
>      int ret = 0;
> -    if (qemu_logfile) {
> +    QemuLogFile *logfile;
> +
> +    rcu_read_lock();
> +    logfile = atomic_rcu_read(&qemu_logfile);
> +    if (logfile) {
>          va_list ap;
>          va_start(ap, fmt);
> -        ret = vfprintf(qemu_logfile, fmt, ap);
> +        ret = vfprintf(logfile->fd, fmt, ap);
>          va_end(ap);
>
>          /* Don't pass back error results.  */
> @@ -48,6 +52,7 @@ int qemu_log(const char *fmt, ...)
>              ret = 0;
>          }
>      }
> +    rcu_read_unlock();
>      return ret;
>  }
>
> @@ -56,11 +61,23 @@ static void __attribute__((__constructor__)) 
> qemu_logfile_init(void)
>      qemu_mutex_init(&qemu_logfile_mutex);
>  }
>
> +static void qemu_logfile_free(QemuLogFile *logfile)
> +{
> +    g_assert(logfile);
> +
> +    if (logfile->fd != stderr) {
> +        fclose(logfile->fd);
> +    }
> +    g_free(logfile);
> +}
> +
>  static bool log_uses_own_buffers;
>
>  /* enable or disable low levels log */
>  void qemu_set_log(int log_flags)
>  {
> +    QemuLogFile *logfile;
> +
>      qemu_loglevel = log_flags;
>  #ifdef CONFIG_TRACE_LOG
>      qemu_loglevel |= LOG_TRACE;
> @@ -70,44 +87,50 @@ void qemu_set_log(int log_flags)
>      qemu_mutex_lock(&qemu_logfile_mutex);
>      if (!qemu_logfile &&
>          (is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
> +        logfile = g_new0(QemuLogFile, 1);
>          if (logfilename) {
> -            qemu_logfile = fopen(logfilename, log_append ? "a" : "w");
> -            if (!qemu_logfile) {
> +            logfile->fd = fopen(logfilename, log_append ? "a" : "w");
> +            if (!logfile->fd) {
> +                g_free(logfile);
>                  perror(logfilename);
>                  _exit(1);
>              }
>              /* In case we are a daemon redirect stderr to logfile */
>              if (is_daemonized()) {
> -                dup2(fileno(qemu_logfile), STDERR_FILENO);
> -                fclose(qemu_logfile);
> +                dup2(fileno(logfile->fd), STDERR_FILENO);
> +                fclose(logfile->fd);
>                  /* This will skip closing logfile in qemu_log_close() */
> -                qemu_logfile = stderr;
> +                logfile->fd = stderr;
>              }
>          } else {
>              /* Default to stderr if no log file specified */
>              assert(!is_daemonized());
> -            qemu_logfile = stderr;
> +            logfile->fd = stderr;
>          }
>          /* must avoid mmap() usage of glibc by setting a buffer "by hand" */
>          if (log_uses_own_buffers) {
>              static char logfile_buf[4096];
>
> -            setvbuf(qemu_logfile, logfile_buf, _IOLBF, sizeof(logfile_buf));
> +            setvbuf(logfile->fd, logfile_buf, _IOLBF, sizeof(logfile_buf));
>          } else {
>  #if defined(_WIN32)
>              /* Win32 doesn't support line-buffering, so use unbuffered 
> output. */
> -            setvbuf(qemu_logfile, NULL, _IONBF, 0);
> +            setvbuf(logfile->fd, NULL, _IONBF, 0);
>  #else
> -            setvbuf(qemu_logfile, NULL, _IOLBF, 0);
> +            setvbuf(logfile->fd, NULL, _IOLBF, 0);
>  #endif
>              log_append = 1;
>          }
> +        atomic_rcu_set(&qemu_logfile, logfile);
>      }
> -    qemu_mutex_unlock(&qemu_logfile_mutex);
> +    logfile = qemu_logfile;

Isn't this read outside of the protection of both rcu_read_lock() and
the mutex? Could that race?

> +
>      if (qemu_logfile &&
>          (is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
> -        qemu_log_close();
> +        atomic_rcu_set(&qemu_logfile, NULL);
> +        call_rcu(logfile, qemu_logfile_free, rcu);

I wonder if we can re-arrange the logic here so it's lets confusing? For
example the NULL qemu_loglevel can be detected at the start and we
should be able just to squash the current log and reset and go. I'm not
sure about the damonize/stdout check.

>      }
> +    qemu_mutex_unlock(&qemu_logfile_mutex);
>  }
>
>  void qemu_log_needs_buffers(void)
> @@ -123,6 +146,7 @@ void qemu_log_needs_buffers(void)
>  void qemu_set_log_filename(const char *filename, Error **errp)
>  {
>      char *pidstr;
> +
>      g_free(logfilename);

nit: stray newline
>
>      pidstr = strstr(filename, "%");
> @@ -235,19 +259,28 @@ out:
>  /* fflush() the log file */
>  void qemu_log_flush(void)
>  {
> -    fflush(qemu_logfile);
> +    QemuLogFile *logfile;
> +
> +    rcu_read_lock();
> +    logfile = atomic_rcu_read(&qemu_logfile);
> +    if (logfile) {
> +        fflush(logfile->fd);
> +    }
> +    rcu_read_unlock();
>  }
>
>  /* Close the log file */
>  void qemu_log_close(void)
>  {
> +    QemuLogFile *logfile;
> +
>      g_assert(qemu_logfile_mutex.initialized);
>      qemu_mutex_lock(&qemu_logfile_mutex);
> -    if (qemu_logfile) {
> -        if (qemu_logfile != stderr) {
> -            fclose(qemu_logfile);
> -        }
> -        qemu_logfile = NULL;
> +    logfile = qemu_logfile;
> +
> +    if (logfile) {
> +        atomic_rcu_set(&qemu_logfile, NULL);
> +        call_rcu(logfile, qemu_logfile_free, rcu);
>      }
>      qemu_mutex_unlock(&qemu_logfile_mutex);
>  }
> diff --git a/include/exec/log.h b/include/exec/log.h
> index e2cfd436e6..9bd1e4aa20 100644
> --- a/include/exec/log.h
> +++ b/include/exec/log.h
> @@ -15,8 +15,15 @@
>   */
>  static inline void log_cpu_state(CPUState *cpu, int flags)
>  {
> +    QemuLogFile *logfile;
> +
>      if (qemu_log_enabled()) {
> -        cpu_dump_state(cpu, qemu_logfile, flags);
> +        rcu_read_lock();
> +        logfile = atomic_rcu_read(&qemu_logfile);
> +        if (logfile) {
> +            cpu_dump_state(cpu, logfile->fd, flags);
> +        }
> +        rcu_read_unlock();
>      }
>  }
>
> @@ -40,19 +47,37 @@ static inline void log_cpu_state_mask(int mask, CPUState 
> *cpu, int flags)
>  static inline void log_target_disas(CPUState *cpu, target_ulong start,
>                                      target_ulong len)
>  {
> -    target_disas(qemu_logfile, cpu, start, len);
> +    QemuLogFile *logfile;
> +    rcu_read_lock();
> +    logfile = atomic_rcu_read(&qemu_logfile);
> +    if (logfile) {
> +        target_disas(logfile->fd, cpu, start, len);
> +    }
> +    rcu_read_unlock();
>  }
>
>  static inline void log_disas(void *code, unsigned long size)
>  {
> -    disas(qemu_logfile, code, size);
> +    QemuLogFile *logfile;
> +    rcu_read_lock();
> +    logfile = atomic_rcu_read(&qemu_logfile);
> +    if (logfile) {
> +        disas(logfile->fd, code, size);
> +    }
> +    rcu_read_unlock();
>  }
>
>  #if defined(CONFIG_USER_ONLY)
>  /* page_dump() output to the log file: */
>  static inline void log_page_dump(void)
>  {
> -    page_dump(qemu_logfile);
> +    QemuLogFile *logfile;
> +    rcu_read_lock();
> +    logfile = atomic_rcu_read(&qemu_logfile);
> +    if (logfile) {
> +        page_dump(logfile->fd);
> +    }
> +    rcu_read_unlock();
>  }
>  #endif
>  #endif
> diff --git a/tcg/tcg.c b/tcg/tcg.c
> index 0511266d85..4f616ba38b 100644
> --- a/tcg/tcg.c
> +++ b/tcg/tcg.c
> @@ -2114,9 +2114,17 @@ static void tcg_dump_ops(TCGContext *s, bool 
> have_prefs)
>          }
>
>          if (have_prefs || op->life) {
> -            for (; col < 40; ++col) {
> -                putc(' ', qemu_logfile);
> +
> +            QemuLogFile *logfile;
> +
> +            rcu_read_lock();
> +            logfile = atomic_rcu_read(&qemu_logfile);
> +            if (logfile) {
> +                for (; col < 40; ++col) {
> +                    putc(' ', logfile->fd);
> +                }
>              }
> +            rcu_read_unlock();
>          }
>
>          if (op->life) {


--
Alex Bennée