Re: [PATCH v2 5/6] Add use of RCU for qemu_logfile.

[Robert Foley]

On Mon, 18 Nov 2019 at 11:41, Alex Bennée <address@hidden> wrote:
>
>
> >>
> > OK, got it.
> > We will need to make one other change to target/tilegx/translate.c
> > since it conditionally unlocks depending on what qemu_log_lock()
> > returns.
>
> Hmm I'd be tempted to drop the locking all together and drop the final
> log("\n") statement. The reason being the translator can longjmp out of
> the loop if it attempts to translate an instruction in an inaccessible
> page.
>
Good point.  Makes sense to remove the locking and final log("\n").
Will make this change.

Thanks,
-Rob

On Mon, 18 Nov 2019 at 11:41, Alex Bennée <address@hidden> wrote:
>
>
> Robert Foley <address@hidden> writes:
>
> > On Mon, 18 Nov 2019 at 08:23, Alex Bennée <address@hidden> wrote:
> >>
> >>
> >> Robert Foley <address@hidden> writes:
> >>
> >> > On Mon, 18 Nov 2019 at 07:22, Alex Bennée <address@hidden> wrote:
> >> >>
> >> >>
> >> >> > +    if (logfile) {
> >> >> > +        qemu_flockfile(logfile->fd);
> >> >> > +        return logfile->fd;
> >> >> > +    } else {
> >> >> > +        rcu_read_unlock();
> >> >>
> >> >> As qemu_log_lock() and unlock should be paired we can drop the unlock
> >> >> here and do an unconditional unlock bellow even if a null fd is passed.
> >> >>
> >> >> Otherwise:
> >> >>
> >> >> Reviewed-by: Alex Bennée <address@hidden>
> >> >>
> >> > Sounds reasonable.  It sounds like we should change it to be something
> >> > like this.
> >> >
> >> > static inline FILE *qemu_log_lock(void)
> >> > {
> >> >     QemuLogFile *logfile;
> >> >     rcu_read_lock();
> >> >     logfile = atomic_rcu_read(&qemu_logfile);
> >> >     if (logfile) {
> >> >         qemu_flockfile(logfile->fd);
> >> >         return logfile->fd;
> >> >     }
> >> >     rcu_read_unlock();
> >> >     return NULL;
> >> > }
> >> > I will make the changes.
> >>
> >> No I mean as you have to call qemu_log_unlock() you can to the unlock
> >> there. You have to hold the lock over the usage of the resource:
> >>
> > OK, got it.
> > We will need to make one other change to target/tilegx/translate.c
> > since it conditionally unlocks depending on what qemu_log_lock()
> > returns.
>
> Hmm I'd be tempted to drop the locking all together and drop the final
> log("\n") statement. The reason being the translator can longjmp out of
> the loop if it attempts to translate an instruction in an inaccessible
> page.
>
> >
> > It seems like the right thing to do since it makes all uses of
> > qemu_log_lock() homogeneous in that they will always unconditionally
> > call qemu_log_unlock().
> >
> > I will make the changes.
> >
> > Thanks,
> > -Rob
> >
> > On Mon, 18 Nov 2019 at 08:23, Alex Bennée <address@hidden> wrote:
> >>
> >>
> >> Robert Foley <address@hidden> writes:
> >>
> >> > On Mon, 18 Nov 2019 at 07:22, Alex Bennée <address@hidden> wrote:
> >> >>
> >> >>
> >> >> > +    if (logfile) {
> >> >> > +        qemu_flockfile(logfile->fd);
> >> >> > +        return logfile->fd;
> >> >> > +    } else {
> >> >> > +        rcu_read_unlock();
> >> >>
> >> >> As qemu_log_lock() and unlock should be paired we can drop the unlock
> >> >> here and do an unconditional unlock bellow even if a null fd is passed.
> >> >>
> >> >> Otherwise:
> >> >>
> >> >> Reviewed-by: Alex Bennée <address@hidden>
> >> >>
> >> > Sounds reasonable.  It sounds like we should change it to be something
> >> > like this.
> >> >
> >> > static inline FILE *qemu_log_lock(void)
> >> > {
> >> >     QemuLogFile *logfile;
> >> >     rcu_read_lock();
> >> >     logfile = atomic_rcu_read(&qemu_logfile);
> >> >     if (logfile) {
> >> >         qemu_flockfile(logfile->fd);
> >> >         return logfile->fd;
> >> >     }
> >> >     rcu_read_unlock();
> >> >     return NULL;
> >> > }
> >> > I will make the changes.
> >>
> >> No I mean as you have to call qemu_log_unlock() you can to the unlock
> >> there. You have to hold the lock over the usage of the resource:
> >>
> >>   static inline FILE *qemu_log_lock(void)
> >>   {
> >>       QemuLogFile *logfile;
> >>       rcu_read_lock();
> >>       logfile = atomic_rcu_read(&qemu_logfile);
> >>       if (logfile) {
> >>           qemu_flockfile(logfile->fd);
> >>           return logfile->fd;
> >>       } else {
> >>           return NULL;
> >>       }
> >>   }
> >>
> >>   static inline void qemu_log_unlock(FILE *fd)
> >>   {
> >>       if (fd) {
> >>           qemu_funlockfile(fd);
> >>       }
> >>       rcu_read_unlock();
> >>   }
> >>
> >>
> >> >
> >> > Thanks,
> >> > -Rob
> >> > On Mon, 18 Nov 2019 at 07:22, Alex Bennée <address@hidden> wrote:
> >> >>
> >> >>
> >> >> 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>
> >> >> > ---
> >> >> > v2
> >> >> >     - No specific changes, just merging in cleanup changes in 
> >> >> > qemu_set_log().
> >> >> > ---
> >> >> > 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         | 72 
> >> >> > ++++++++++++++++++++++++++++++++--------------
> >> >> >  include/exec/log.h | 33 ++++++++++++++++++---
> >> >> >  tcg/tcg.c          | 12 ++++++--
> >> >> >  4 files changed, 126 insertions(+), 33 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();
> >> >>
> >> >> As qemu_log_lock() and unlock should be paired we can drop the unlock
> >> >> here and do an unconditional unlock bellow even if a null fd is passed.
> >> >>
> >> >> Otherwise:
> >> >>
> >> >> Reviewed-by: Alex Bennée <address@hidden>
> >> >>
> >> >> > +        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 91ebb5c924..9f9b6b74b7 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,12 +61,24 @@ 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)
> >> >> >  {
> >> >> >      bool need_to_open_file = false;
> >> >> > +    QemuLogFile *logfile;
> >> >> > +
> >> >> >      qemu_loglevel = log_flags;
> >> >> >  #ifdef CONFIG_TRACE_LOG
> >> >> >      qemu_loglevel |= LOG_TRACE;
> >> >> > @@ -80,43 +97,47 @@ void qemu_set_log(int log_flags)
> >> >> >      g_assert(qemu_logfile_mutex.initialized);
> >> >> >      qemu_mutex_lock(&qemu_logfile_mutex);
> >> >> >      if (qemu_logfile && !need_to_open_file) {
> >> >> > -        qemu_mutex_unlock(&qemu_logfile_mutex);
> >> >> > -        qemu_log_close();
> >> >> > +        logfile = qemu_logfile;
> >> >> > +        atomic_rcu_set(&qemu_logfile, NULL);
> >> >> > +        call_rcu(logfile, qemu_logfile_free, rcu);
> >> >> >      } else if (!qemu_logfile && need_to_open_file) {
> >> >> > +        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;
> >> >> >          }
> >> >> > -        qemu_mutex_unlock(&qemu_logfile_mutex);
> >> >> > +        atomic_rcu_set(&qemu_logfile, logfile);
> >> >> >      }
> >> >> > +    qemu_mutex_unlock(&qemu_logfile_mutex);
> >> >> >  }
> >> >> >
> >> >> >  void qemu_log_needs_buffers(void)
> >> >> > @@ -245,19 +266,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
> >>
> >>
> >> --
> >> Alex Bennée
>
>
> --
> Alex Bennée