On Tue, 12 Nov 2019 at 12:36, Alex Bennée <alex.ben...@linaro.org> wrote:
>
>
> > }
> > + 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?
This assignment is under the mutex. This change moved the mutex
unlock towards the end of the function, just a few lines below the
call_rcu().
> > +
> > 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);
> > }
> >
Absolutely, the logic that was here originally can be improved. We
found it confusing also.
We could move things around a bit and change it to something like this
to help clarify.
bool need_to_open_file = false;
/*
* In all cases we only log if qemu_loglevel is set.
* And:
* If not daemonized we will always log either to stderr
* or to a file (if there is a logfilename).
* If we are daemonized,
* we will only log if there is a logfilename.
*/
if (qemu_loglevel && (!is_daemonized() || logfilename) {
need_to_open_file = true;
}
g_assert(qemu_logfile_mutex.initialized);
qemu_mutex_lock(&qemu_logfile_mutex);
if(qemu_logfile && !need_to_open_file) {
/* Close file. */
QemuLogFile *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);
__snip__ existing patch logic for opening the qemu_logfile will
be inserted here.
}
qemu_mutex_unlock(&qemu_logfile_mutex);
> > {
> > char *pidstr;
> > +
> > g_free(logfilename);
>
> nit: stray newline
Will remove the newline.
Thanks,
Rob
On Tue, 12 Nov 2019 at 12:36, Alex Bennée <alex.ben...@linaro.org> wrote:
>
>
> Robert Foley <robert.fo...@linaro.org> 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 <robert.fo...@linaro.org>
> > ---
> > 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
