[RFC PATCH] logging: add a LOG_TCG_WARN for temp leaks

[RFC PATCH] logging: add a LOG_TCG_WARN for temp leaks

[Alex Bennée]

Pretty much all calls to qemu_log are either wrapped in some other
enabling check or only enabled with debug defines. Add a specific flag
for TCG warnings and expand the documentation of the qemu_log
function.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Cc: Peter Maydell <peter.maydell@linaro.org>
---
 include/qemu/log-for-trace.h | 9 ++++++++-
 include/qemu/log.h           | 2 ++
 accel/tcg/translator.c       | 4 ++--
 util/log.c                   | 2 ++
 4 files changed, 14 insertions(+), 3 deletions(-)

diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
index 2f0a5b080ea..521d7936243 100644
--- a/include/qemu/log-for-trace.h
+++ b/include/qemu/log-for-trace.h
@@ -29,7 +29,14 @@ static inline bool qemu_loglevel_mask(int mask)
     return (qemu_loglevel & mask) != 0;
 }
 
-/* main logging function */
+/**
+ * qemu_log: main logging function
+ *
+ * Most users shouldn't be calling qemu_log unconditionally as it adds
+ * noise to logging output. Either use qemu_log_mask() or wrap
+ * successive log calls a qemu_loglevel_mask() check and
+ * qemu_log_lock/unlock(). The tracing infrastructure does similar wrapping.
+ */
 int GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
 
 #endif
diff --git a/include/qemu/log.h b/include/qemu/log.h
index f4724f73301..e1574ef7c14 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -64,6 +64,8 @@ static inline bool qemu_log_separate(void)
 #define CPU_LOG_PLUGIN     (1 << 18)
 /* LOG_STRACE is used for user-mode strace logging. */
 #define LOG_STRACE         (1 << 19)
+/* Additional TCG warnings */
+#define LOG_TCG_WARN       (1 << 20)
 
 /* Lock output for a series of related logs.  Since this is not needed
  * for a single qemu_log / qemu_log_mask / qemu_log_mask_and_addr, we
diff --git a/accel/tcg/translator.c b/accel/tcg/translator.c
index 603d17ff831..44396ccd7ad 100644
--- a/accel/tcg/translator.c
+++ b/accel/tcg/translator.c
@@ -26,8 +26,8 @@
 void translator_loop_temp_check(DisasContextBase *db)
 {
     if (tcg_check_temp_count()) {
-        qemu_log("warning: TCG temporary leaks before "
-                 TARGET_FMT_lx "\n", db->pc_next);
+        qemu_log_mask(LOG_TCG_WARN, "warning: TCG temporary leaks before "
+                      TARGET_FMT_lx "\n", db->pc_next);
     }
 }
 
diff --git a/util/log.c b/util/log.c
index bdb3d712e88..fad25d9317f 100644
--- a/util/log.c
+++ b/util/log.c
@@ -334,6 +334,8 @@ const QEMULogItem qemu_log_items[] = {
 #endif
     { LOG_STRACE, "strace",
       "log every user-mode syscall, its input, and its result" },
+    { LOG_TCG_WARN, "tcg",
+      "log TCG warnings useful to developers." },
     { 0, NULL, NULL },
 };
 
-- 
2.20.1

Re: [RFC PATCH] logging: add a LOG_TCG_WARN for temp leaks

[Peter Maydell]

On Thu, 11 Jun 2020 at 15:45, Alex Bennée <alex.bennee@linaro.org> wrote:
>
> Pretty much all calls to qemu_log are either wrapped in some other
> enabling check or only enabled with debug defines. Add a specific flag
> for TCG warnings and expand the documentation of the qemu_log
> function.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> Cc: Peter Maydell <peter.maydell@linaro.org>
> ---

> -/* main logging function */
> +/**
> + * qemu_log: main logging function
> + *
> + * Most users shouldn't be calling qemu_log unconditionally as it adds
> + * noise to logging output. Either use qemu_log_mask() or wrap
> + * successive log calls a qemu_loglevel_mask() check and
"inside a"

> + * qemu_log_lock/unlock(). The tracing infrastructure does similar wrapping.
> + */
>  int GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);

> +/* Additional TCG warnings */
> +#define LOG_TCG_WARN       (1 << 20)

I don't object to the new log group in principle, but it has exactly
one warning in it. I feel we'd be better to check for all the current
places that use qemu_log not inside a loglevel_mask condition (or
which use fprintf, if we still have those) and then see what the
most reasonable categorization is.

thanks
-- PMM

Re: [RFC PATCH] logging: add a LOG_TCG_WARN for temp leaks

[Alex Bennée]

Peter Maydell <peter.maydell@linaro.org> writes:

> On Thu, 11 Jun 2020 at 15:45, Alex Bennée <alex.bennee@linaro.org> wrote:
>>
>> Pretty much all calls to qemu_log are either wrapped in some other
>> enabling check or only enabled with debug defines. Add a specific flag
>> for TCG warnings and expand the documentation of the qemu_log
>> function.
>>
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> Cc: Peter Maydell <peter.maydell@linaro.org>
>> ---
>
>> -/* main logging function */
>> +/**
>> + * qemu_log: main logging function
>> + *
>> + * Most users shouldn't be calling qemu_log unconditionally as it adds
>> + * noise to logging output. Either use qemu_log_mask() or wrap
>> + * successive log calls a qemu_loglevel_mask() check and
> "inside a"
>
>> + * qemu_log_lock/unlock(). The tracing infrastructure does similar wrapping.
>> + */
>>  int GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
>
>> +/* Additional TCG warnings */
>> +#define LOG_TCG_WARN       (1 << 20)
>
> I don't object to the new log group in principle, but it has exactly
> one warning in it. I feel we'd be better to check for all the current
> places that use qemu_log not inside a loglevel_mask condition (or
> which use fprintf, if we still have those) and then see what the
> most reasonable categorization is.

I did a grep of qemu_log and fprintf cases in accel/tcg and tcg and this
was the only one that wasn't:

  - either wrapped by qemu_loglevel_mask()
  - part of an abort/exit() path (which should arguably be converted to error_report/abort)

In the wider code most of the the qemu_logs() I found where in D()
functions in the various device emulations.

-- 
Alex Bennée

Re: [RFC PATCH] logging: add a LOG_TCG_WARN for temp leaks

[Philippe Mathieu-Daudé]

On 6/11/20 4:45 PM, Alex Bennée wrote:
> Pretty much all calls to qemu_log are either wrapped in some other
> enabling check or only enabled with debug defines. Add a specific flag
> for TCG warnings and expand the documentation of the qemu_log
> function.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> Cc: Peter Maydell <peter.maydell@linaro.org>
> ---
>  include/qemu/log-for-trace.h | 9 ++++++++-
>  include/qemu/log.h           | 2 ++
>  accel/tcg/translator.c       | 4 ++--
>  util/log.c                   | 2 ++
>  4 files changed, 14 insertions(+), 3 deletions(-)
> 
> diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
> index 2f0a5b080ea..521d7936243 100644
> --- a/include/qemu/log-for-trace.h
> +++ b/include/qemu/log-for-trace.h
> @@ -29,7 +29,14 @@ static inline bool qemu_loglevel_mask(int mask)
>      return (qemu_loglevel & mask) != 0;
>  }
>  
> -/* main logging function */
> +/**
> + * qemu_log: main logging function
> + *
> + * Most users shouldn't be calling qemu_log unconditionally as it adds
> + * noise to logging output. Either use qemu_log_mask() or wrap
> + * successive log calls a qemu_loglevel_mask() check and
> + * qemu_log_lock/unlock(). The tracing infrastructure does similar wrapping.
> + */
>  int GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
>  
>  #endif
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index f4724f73301..e1574ef7c14 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -64,6 +64,8 @@ static inline bool qemu_log_separate(void)
>  #define CPU_LOG_PLUGIN     (1 << 18)
>  /* LOG_STRACE is used for user-mode strace logging. */
>  #define LOG_STRACE         (1 << 19)
> +/* Additional TCG warnings */
> +#define LOG_TCG_WARN       (1 << 20)
>  
>  /* Lock output for a series of related logs.  Since this is not needed
>   * for a single qemu_log / qemu_log_mask / qemu_log_mask_and_addr, we
> diff --git a/accel/tcg/translator.c b/accel/tcg/translator.c
> index 603d17ff831..44396ccd7ad 100644
> --- a/accel/tcg/translator.c
> +++ b/accel/tcg/translator.c
> @@ -26,8 +26,8 @@
>  void translator_loop_temp_check(DisasContextBase *db)
>  {
>      if (tcg_check_temp_count()) {
> -        qemu_log("warning: TCG temporary leaks before "
> -                 TARGET_FMT_lx "\n", db->pc_next);
> +        qemu_log_mask(LOG_TCG_WARN, "warning: TCG temporary leaks before "
> +                      TARGET_FMT_lx "\n", db->pc_next);

Why not replace by warn_report_once()?

>      }
>  }
>  
> diff --git a/util/log.c b/util/log.c
> index bdb3d712e88..fad25d9317f 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -334,6 +334,8 @@ const QEMULogItem qemu_log_items[] = {
>  #endif
>      { LOG_STRACE, "strace",
>        "log every user-mode syscall, its input, and its result" },
> +    { LOG_TCG_WARN, "tcg",
> +      "log TCG warnings useful to developers." },
>      { 0, NULL, NULL },
>  };
>  
>