[Qemu-devel] [PATCH v5 0/9] qemu-log, -dfilter and other logging tweaks

[Qemu-devel] [PATCH v5 0/9] qemu-log, -dfilter and other logging tweaks

[Alex Bennée]

Hi,

With the approaching soft-freeze I realised I'd better get the next
iteration of these patches out. I've dropped the perf.map and logging
system invocation patches to be revisited at a later date.

A bunch of commits have gained Reviewed-by tags from v4 and are mostly
unchanged. However there are some have seen a bit of churn:

The tcg patch is a lot simpler than previously thanks to clean-ups in
the tcg code. This means the controversial storing of size in the
TranslationBlock is gone and the patch is a simple pushing down of the
TB structure for debugging purposes.

The -dfilter patch has seen a little clean-up following IRC
discussion. The range operator is now .. which means - acts as the
more intuitive mathematical operation like its + counterpart.

The dfilter-ise exec, out_asm patch also includes op and opt_op output
thanks again to the re-factoring moving this out of per-target code.
This in turn means the target-arm patch now only deals with in-asm.

Discussion on previous patches about exec output are now out of date
as -d nochain has already been merged. I've slightly tweaked the help
text to reflect that.

The question of which tree is going to take these patches remains open
as qemu-log is currently un-maintained. As these are mostly focused at
TCG work perhaps via the TCG code tree? Richard/Peter any objections?

Alex Bennée (7):
  tcg: pass down TranslationBlock to tcg_code_gen
  qemu-log: correct help text for -d cpu
  qemu-log: support simple pid substitution in logfile
  qemu-log: new option -dfilter to limit output
  qemu-log: dfilter-ise exec, out_asm, op and opt_op
  target-arm: dfilter support for in_asm
  cputlb: modernise the debug support

Peter Maydell (2):
  qemu-log: Avoid function call for disabled qemu_log_mask logging
  qemu-log: Improve the "exec" TB execution logging

 cpu-exec.c                 |  21 +++++----
 cputlb.c                   |  54 +++++++++++++--------
 include/exec/exec-all.h    |   5 ++
 include/qemu/log.h         |  28 ++++++++++-
 qemu-log.c                 | 115 +++++++++++++++++++++++++++++++++++++++------
 qemu-options.hx            |  18 +++++++
 target-arm/translate-a64.c |   3 +-
 target-arm/translate.c     |   3 +-
 tcg/tcg.c                  |  12 +++--
 tcg/tcg.h                  |   2 +-
 translate-all.c            |  13 +++--
 vl.c                       |   3 ++
 12 files changed, 218 insertions(+), 59 deletions(-)

-- 
2.7.0

[Qemu-devel] [PATCH v5 1/9] tcg: pass down TranslationBlock to tcg_code_gen

[Alex Bennée]

My later debugging patches need access to the origin PC which is held in
the TranslationBlock structure. Pass down the whole structure as it also
holds the information about the code start point.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

---
v1
 - checkpatch fixes
v5
 - much simplified due to changes since last posting
---
 tcg/tcg.c       |  6 +++---
 tcg/tcg.h       |  2 +-
 translate-all.c | 10 ++++------
 3 files changed, 8 insertions(+), 10 deletions(-)

diff --git a/tcg/tcg.c b/tcg/tcg.c
index 3ce02dc..0101cc1 100644
--- a/tcg/tcg.c
+++ b/tcg/tcg.c
@@ -2316,7 +2316,7 @@ void tcg_dump_op_count(FILE *f, fprintf_function cpu_fprintf)
 #endif
 
 
-int tcg_gen_code(TCGContext *s, tcg_insn_unit *gen_code_buf)
+int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
 {
     int i, oi, oi_next, num_insns;
 
@@ -2375,8 +2375,8 @@ int tcg_gen_code(TCGContext *s, tcg_insn_unit *gen_code_buf)
 
     tcg_reg_alloc_start(s);
 
-    s->code_buf = gen_code_buf;
-    s->code_ptr = gen_code_buf;
+    s->code_buf = tb->tc_ptr;
+    s->code_ptr = tb->tc_ptr;
 
     tcg_out_tb_init(s);
 
diff --git a/tcg/tcg.h b/tcg/tcg.h
index a696922..9a18ee4 100644
--- a/tcg/tcg.h
+++ b/tcg/tcg.h
@@ -626,7 +626,7 @@ void tcg_context_init(TCGContext *s);
 void tcg_prologue_init(TCGContext *s);
 void tcg_func_start(TCGContext *s);
 
-int tcg_gen_code(TCGContext *s, tcg_insn_unit *gen_code_buf);
+int tcg_gen_code(TCGContext *s, TranslationBlock *tb);
 
 void tcg_set_frame(TCGContext *s, int reg, intptr_t start, intptr_t size);
 
diff --git a/translate-all.c b/translate-all.c
index ab61fac..dce00d5 100644
--- a/translate-all.c
+++ b/translate-all.c
@@ -1055,7 +1055,6 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
     TranslationBlock *tb;
     tb_page_addr_t phys_pc, phys_page2;
     target_ulong virt_page2;
-    tcg_insn_unit *gen_code_buf;
     int gen_code_size, search_size;
 #ifdef CONFIG_PROFILER
     int64_t ti;
@@ -1078,8 +1077,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
         tcg_ctx.tb_ctx.tb_invalidated_flag = 1;
     }
 
-    gen_code_buf = tcg_ctx.code_gen_ptr;
-    tb->tc_ptr = gen_code_buf;
+    tb->tc_ptr = tcg_ctx.code_gen_ptr;
     tb->cs_base = cs_base;
     tb->flags = flags;
     tb->cflags = cflags;
@@ -1119,11 +1117,11 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
        the tcg optimization currently hidden inside tcg_gen_code.  All
        that should be required is to flush the TBs, allocate a new TB,
        re-initialize it per above, and re-do the actual code generation.  */
-    gen_code_size = tcg_gen_code(&tcg_ctx, gen_code_buf);
+    gen_code_size = tcg_gen_code(&tcg_ctx, tb);
     if (unlikely(gen_code_size < 0)) {
         goto buffer_overflow;
     }
-    search_size = encode_search(tb, (void *)gen_code_buf + gen_code_size);
+    search_size = encode_search(tb, (void *)tb->tc_ptr + gen_code_size);
     if (unlikely(search_size < 0)) {
         goto buffer_overflow;
     }
@@ -1145,7 +1143,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
 #endif
 
     tcg_ctx.code_gen_ptr = (void *)
-        ROUND_UP((uintptr_t)gen_code_buf + gen_code_size + search_size,
+        ROUND_UP((uintptr_t)tb->tc_ptr + gen_code_size + search_size,
                  CODE_GEN_ALIGN);
 
     /* check next page if needed */
-- 
2.7.0

Re: [Qemu-devel] [PATCH v5 1/9] tcg: pass down TranslationBlock to tcg_code_gen

[Richard Henderson]

On 02/05/2016 01:56 AM, Alex Bennée wrote:
> diff --git a/translate-all.c b/translate-all.c
> index ab61fac..dce00d5 100644
> --- a/translate-all.c
> +++ b/translate-all.c
> @@ -1055,7 +1055,6 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>       TranslationBlock *tb;
>       tb_page_addr_t phys_pc, phys_page2;
>       target_ulong virt_page2;
> -    tcg_insn_unit *gen_code_buf;
>       int gen_code_size, search_size;
>   #ifdef CONFIG_PROFILER
>       int64_t ti;
> @@ -1078,8 +1077,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>           tcg_ctx.tb_ctx.tb_invalidated_flag = 1;
>       }
>
> -    gen_code_buf = tcg_ctx.code_gen_ptr;
> -    tb->tc_ptr = gen_code_buf;
> +    tb->tc_ptr = tcg_ctx.code_gen_ptr;

Why get rid of the gen_code_buf variable?  You're forcing the compiler to keep 
reloading the value from memory.

Certainly that's not relevant to passing down TB to tcg_gen_code, and is a 
separate change that ought to be separately defended.


r~

>       tb->cs_base = cs_base;
>       tb->flags = flags;
>       tb->cflags = cflags;
> @@ -1119,11 +1117,11 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>          the tcg optimization currently hidden inside tcg_gen_code.  All
>          that should be required is to flush the TBs, allocate a new TB,
>          re-initialize it per above, and re-do the actual code generation.  */
> -    gen_code_size = tcg_gen_code(&tcg_ctx, gen_code_buf);
> +    gen_code_size = tcg_gen_code(&tcg_ctx, tb);
>       if (unlikely(gen_code_size < 0)) {
>           goto buffer_overflow;
>       }
> -    search_size = encode_search(tb, (void *)gen_code_buf + gen_code_size);
> +    search_size = encode_search(tb, (void *)tb->tc_ptr + gen_code_size);
>       if (unlikely(search_size < 0)) {
>           goto buffer_overflow;
>       }
> @@ -1145,7 +1143,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>   #endif
>
>       tcg_ctx.code_gen_ptr = (void *)
> -        ROUND_UP((uintptr_t)gen_code_buf + gen_code_size + search_size,
> +        ROUND_UP((uintptr_t)tb->tc_ptr + gen_code_size + search_size,
>                    CODE_GEN_ALIGN);
>
>       /* check next page if needed */
>

Re: [Qemu-devel] [PATCH v5 1/9] tcg: pass down TranslationBlock to tcg_code_gen

[Alex Bennée]

Richard Henderson <rth@twiddle.net> writes:

> On 02/05/2016 01:56 AM, Alex Bennée wrote:
>> diff --git a/translate-all.c b/translate-all.c
>> index ab61fac..dce00d5 100644
>> --- a/translate-all.c
>> +++ b/translate-all.c
>> @@ -1055,7 +1055,6 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>>       TranslationBlock *tb;
>>       tb_page_addr_t phys_pc, phys_page2;
>>       target_ulong virt_page2;
>> -    tcg_insn_unit *gen_code_buf;
>>       int gen_code_size, search_size;
>>   #ifdef CONFIG_PROFILER
>>       int64_t ti;
>> @@ -1078,8 +1077,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>>           tcg_ctx.tb_ctx.tb_invalidated_flag = 1;
>>       }
>>
>> -    gen_code_buf = tcg_ctx.code_gen_ptr;
>> -    tb->tc_ptr = gen_code_buf;
>> +    tb->tc_ptr = tcg_ctx.code_gen_ptr;
>
> Why get rid of the gen_code_buf variable?  You're forcing the compiler to keep
> reloading the value from memory.
>
> Certainly that's not relevant to passing down TB to tcg_gen_code, and is a
> separate change that ought to be separately defended.

Fixed. Thanks.

>
>
> r~
>
>>       tb->cs_base = cs_base;
>>       tb->flags = flags;
>>       tb->cflags = cflags;
>> @@ -1119,11 +1117,11 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>>          the tcg optimization currently hidden inside tcg_gen_code.  All
>>          that should be required is to flush the TBs, allocate a new TB,
>>          re-initialize it per above, and re-do the actual code generation.  */
>> -    gen_code_size = tcg_gen_code(&tcg_ctx, gen_code_buf);
>> +    gen_code_size = tcg_gen_code(&tcg_ctx, tb);
>>       if (unlikely(gen_code_size < 0)) {
>>           goto buffer_overflow;
>>       }
>> -    search_size = encode_search(tb, (void *)gen_code_buf + gen_code_size);
>> +    search_size = encode_search(tb, (void *)tb->tc_ptr + gen_code_size);
>>       if (unlikely(search_size < 0)) {
>>           goto buffer_overflow;
>>       }
>> @@ -1145,7 +1143,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>>   #endif
>>
>>       tcg_ctx.code_gen_ptr = (void *)
>> -        ROUND_UP((uintptr_t)gen_code_buf + gen_code_size + search_size,
>> +        ROUND_UP((uintptr_t)tb->tc_ptr + gen_code_size + search_size,
>>                    CODE_GEN_ALIGN);
>>
>>       /* check next page if needed */
>>


--
Alex Bennée

[Qemu-devel] [PATCH v5 2/9] qemu-log: correct help text for -d cpu

[Alex Bennée]

This doesn't just dump CPU state on translation but on every block
entrance.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Andreas Färber <afaerber@suse.de>

---
v4
  - add r-b tag
v5
  - slightly tweak the wording now nochain exists
---
 qemu-log.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/qemu-log.c b/qemu-log.c
index 901b930..5d11fe7 100644
--- a/qemu-log.c
+++ b/qemu-log.c
@@ -105,7 +105,7 @@ const QEMULogItem qemu_log_items[] = {
     { CPU_LOG_EXEC, "exec",
       "show trace before each executed TB (lots of logs)" },
     { CPU_LOG_TB_CPU, "cpu",
-      "show CPU state before block translation" },
+      "show CPU registers before entering a TB (lots of logs)" },
     { CPU_LOG_MMU, "mmu",
       "log MMU-related activities" },
     { CPU_LOG_PCALL, "pcall",
-- 
2.7.0

Re: [Qemu-devel] [PATCH v5 2/9] qemu-log: correct help text for -d cpu

[Richard Henderson]

On 02/05/2016 01:56 AM, Alex Bennée wrote:
> This doesn't just dump CPU state on translation but on every block
> entrance.
>
> Signed-off-by: Alex Bennée<alex.bennee@linaro.org>
> Reviewed-by: Andreas Färber<afaerber@suse.de>

Reviewed-by: Richard Henderson <rth@twiddle.net>


r~

[Qemu-devel] [PATCH v5 3/9] qemu-log: Avoid function call for disabled qemu_log_mask logging

[Alex Bennée]

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

Make qemu_log_mask() a macro which only calls the function to
do the actual work if the logging is enabled. This avoids making
a function call in possible fast paths where logging is disabled.

Signed-off-by: Peter Maydell <peter.maydell@linaro.org>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Andreas Färber <afaerber@suse.de>

---
v4
  - fix s-o-b tags, add r-b tag
---
 include/qemu/log.h | 13 ++++++++++---
 qemu-log.c         | 11 -----------
 2 files changed, 10 insertions(+), 14 deletions(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index d837d90..776ceaf 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -73,10 +73,17 @@ qemu_log_vprintf(const char *fmt, va_list va)
     }
 }
 
-/* log only if a bit is set on the current loglevel mask
+/* log only if a bit is set on the current loglevel mask:
+ * @mask: bit to check in the mask
+ * @fmt: printf-style format string
+ * @args: optional arguments for format string
  */
-void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
-
+#define qemu_log_mask(MASK, FMT, ...)                   \
+    do {                                                \
+        if (unlikely(qemu_loglevel_mask(MASK))) {       \
+            qemu_log(FMT, ## __VA_ARGS__);              \
+        }                                               \
+    } while (0)
 
 /* Special cases: */
 
diff --git a/qemu-log.c b/qemu-log.c
index 5d11fe7..8c59063 100644
--- a/qemu-log.c
+++ b/qemu-log.c
@@ -36,17 +36,6 @@ void qemu_log(const char *fmt, ...)
     va_end(ap);
 }
 
-void qemu_log_mask(int mask, const char *fmt, ...)
-{
-    va_list ap;
-
-    va_start(ap, fmt);
-    if ((qemu_loglevel & mask) && qemu_logfile) {
-        vfprintf(qemu_logfile, fmt, ap);
-    }
-    va_end(ap);
-}
-
 /* enable or disable low levels log */
 void do_qemu_set_log(int log_flags, bool use_own_buffers)
 {
-- 
2.7.0

[Qemu-devel] [PATCH v5 4/9] qemu-log: Improve the "exec" TB execution logging

[Alex Bennée]

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

Improve the TB execution logging so that it is easier to identify
what is happening from trace logs:
 * move the "Trace" logging of executed TBs into cpu_tb_exec()
   so that it is emitted if and only if we actually execute a TB,
   and for consistency for the CPU state logging
 * log when we link two TBs together via tb_add_jump()
 * log when cpu_tb_exec() returns early from a chain of TBs

The new style logging looks like this:

Trace 0x7fb7cc822ca0 [ffffffc0000dce00]
Linking TBs 0x7fb7cc822ca0 [ffffffc0000dce00] index 0 -> 0x7fb7cc823110 [ffffffc0000dce10]
Trace 0x7fb7cc823110 [ffffffc0000dce10]
Trace 0x7fb7cc823420 [ffffffc000302688]
Trace 0x7fb7cc8234a0 [ffffffc000302698]
Trace 0x7fb7cc823520 [ffffffc0003026a4]
Trace 0x7fb7cc823560 [ffffffc0000dce44]
Linking TBs 0x7fb7cc823560 [ffffffc0000dce44] index 1 -> 0x7fb7cc8235d0 [ffffffc0000dce70]
Trace 0x7fb7cc8235d0 [ffffffc0000dce70]
Abandoned execution of TB chain before 0x7fb7cc8235d0 [ffffffc0000dce70]
Trace 0x7fb7cc8235d0 [ffffffc0000dce70]
Trace 0x7fb7cc822fd0 [ffffffc0000dd52c]

Signed-off-by: Peter Maydell <peter.maydell@linaro.org>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
[AJB: reword patch title]
Reviewed-by: Aurelien Jarno <aurelien@aurel32.net>
---
 cpu-exec.c              | 20 +++++++++++---------
 include/exec/exec-all.h |  3 +++
 2 files changed, 14 insertions(+), 9 deletions(-)

diff --git a/cpu-exec.c b/cpu-exec.c
index c459364..8151e6f 100644
--- a/cpu-exec.c
+++ b/cpu-exec.c
@@ -132,10 +132,14 @@ static void init_delay_params(SyncClocks *sc, const CPUState *cpu)
 #endif /* CONFIG USER ONLY */
 
 /* Execute a TB, and fix up the CPU state afterwards if necessary */
-static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, uint8_t *tb_ptr)
+static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb)
 {
     CPUArchState *env = cpu->env_ptr;
     uintptr_t next_tb;
+    uint8_t *tb_ptr = itb->tc_ptr;
+
+    qemu_log_mask(CPU_LOG_EXEC, "Trace %p [" TARGET_FMT_lx "] %s\n",
+                  itb->tc_ptr, itb->pc, lookup_symbol(itb->pc));
 
 #if defined(DEBUG_DISAS)
     if (qemu_loglevel_mask(CPU_LOG_TB_CPU)) {
@@ -166,6 +170,10 @@ static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, uint8_t *tb_ptr)
          */
         CPUClass *cc = CPU_GET_CLASS(cpu);
         TranslationBlock *tb = (TranslationBlock *)(next_tb & ~TB_EXIT_MASK);
+        qemu_log_mask(CPU_LOG_EXEC,
+                      "Abandoned execution of TB chain before %p ["
+                      TARGET_FMT_lx "] %s\n",
+                      itb->tc_ptr, itb->pc, lookup_symbol(itb->pc));
         if (cc->synchronize_from_tb) {
             cc->synchronize_from_tb(cpu, tb);
         } else {
@@ -201,7 +209,7 @@ static void cpu_exec_nocache(CPUState *cpu, int max_cycles,
     cpu->current_tb = tb;
     /* execute the generated code */
     trace_exec_tb_nocache(tb, tb->pc);
-    cpu_tb_exec(cpu, tb->tc_ptr);
+    cpu_tb_exec(cpu, tb);
     cpu->current_tb = NULL;
     tb_phys_invalidate(tb, -1);
     tb_free(tb);
@@ -343,7 +351,6 @@ int cpu_exec(CPUState *cpu)
 #endif
     int ret, interrupt_request;
     TranslationBlock *tb;
-    uint8_t *tc_ptr;
     uintptr_t next_tb;
     SyncClocks sc;
 
@@ -499,10 +506,6 @@ int cpu_exec(CPUState *cpu)
                     next_tb = 0;
                     tcg_ctx.tb_ctx.tb_invalidated_flag = 0;
                 }
-                if (qemu_loglevel_mask(CPU_LOG_EXEC)) {
-                    qemu_log("Trace %p [" TARGET_FMT_lx "] %s\n",
-                             tb->tc_ptr, tb->pc, lookup_symbol(tb->pc));
-                }
                 /* see if we can patch the calling TB. When the TB
                    spans two pages, we cannot safely do a direct
                    jump. */
@@ -514,10 +517,9 @@ int cpu_exec(CPUState *cpu)
                 tb_unlock();
                 if (likely(!cpu->exit_request)) {
                     trace_exec_tb(tb, tb->pc);
-                    tc_ptr = tb->tc_ptr;
                     /* execute the generated code */
                     cpu->current_tb = tb;
-                    next_tb = cpu_tb_exec(cpu, tc_ptr);
+                    next_tb = cpu_tb_exec(cpu, tb);
                     cpu->current_tb = NULL;
                     switch (next_tb & TB_EXIT_MASK) {
                     case TB_EXIT_REQUESTED:
diff --git a/include/exec/exec-all.h b/include/exec/exec-all.h
index 05a151d..1823ee3 100644
--- a/include/exec/exec-all.h
+++ b/include/exec/exec-all.h
@@ -379,6 +379,9 @@ static inline void tb_add_jump(TranslationBlock *tb, int n,
 {
     /* NOTE: this test is only needed for thread safety */
     if (!tb->jmp_next[n]) {
+        qemu_log_mask(CPU_LOG_EXEC, "Linking TBs %p [" TARGET_FMT_lx
+                      "] index %d -> %p [" TARGET_FMT_lx "]\n",
+                      tb->tc_ptr, tb->pc, n, tb_next->tc_ptr, tb_next->pc);
         /* patch the native jump address */
         tb_set_jmp_target(tb, n, (uintptr_t)tb_next->tc_ptr);
 
-- 
2.7.0

Re: [Qemu-devel] [PATCH v5 4/9] qemu-log: Improve the "exec" TB execution logging

[Richard Henderson]

On 02/05/2016 01:56 AM, Alex Bennée wrote:
> From: Peter Maydell<peter.maydell@linaro.org>
>
> Improve the TB execution logging so that it is easier to identify
> what is happening from trace logs:
>   * move the "Trace" logging of executed TBs into cpu_tb_exec()
>     so that it is emitted if and only if we actually execute a TB,
>     and for consistency for the CPU state logging
>   * log when we link two TBs together via tb_add_jump()
>   * log when cpu_tb_exec() returns early from a chain of TBs
>
> The new style logging looks like this:
>
> Trace 0x7fb7cc822ca0 [ffffffc0000dce00]
> Linking TBs 0x7fb7cc822ca0 [ffffffc0000dce00] index 0 -> 0x7fb7cc823110 [ffffffc0000dce10]
> Trace 0x7fb7cc823110 [ffffffc0000dce10]
> Trace 0x7fb7cc823420 [ffffffc000302688]
> Trace 0x7fb7cc8234a0 [ffffffc000302698]
> Trace 0x7fb7cc823520 [ffffffc0003026a4]
> Trace 0x7fb7cc823560 [ffffffc0000dce44]
> Linking TBs 0x7fb7cc823560 [ffffffc0000dce44] index 1 -> 0x7fb7cc8235d0 [ffffffc0000dce70]
> Trace 0x7fb7cc8235d0 [ffffffc0000dce70]
> Abandoned execution of TB chain before 0x7fb7cc8235d0 [ffffffc0000dce70]
> Trace 0x7fb7cc8235d0 [ffffffc0000dce70]
> Trace 0x7fb7cc822fd0 [ffffffc0000dd52c]
>
> Signed-off-by: Peter Maydell<peter.maydell@linaro.org>
> Signed-off-by: Alex Bennée<alex.bennee@linaro.org>
> [AJB: reword patch title]
> Reviewed-by: Aurelien Jarno<aurelien@aurel32.net>
> ---
>   cpu-exec.c              | 20 +++++++++++---------
>   include/exec/exec-all.h |  3 +++
>   2 files changed, 14 insertions(+), 9 deletions(-)

Looks good, though I quibble over the term "Abandoned".  To me that implies 
that nothing got executed, which isn't true.  I'd prefer "Stopped" or "Exited".

Otherwise,

Reviewed-by: Richard Henderson  <rth@twiddle.net>


r~

[Qemu-devel] [PATCH v5 5/9] qemu-log: support simple pid substitution in logfile

[Alex Bennée]

When debugging stuff that occurs over several forks it would be useful
not to keep overwriting the one logfile you've set-up. This allows a
simple %d to be included once in the logfile parameter which is
substituted with getpid().

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Leandro Dorileo <l@dorileo.org>
Reviewed-by: Aurelien Jarno <aurelien@aurel32.net>

---
v5
  - add another r-b
---
 qemu-log.c | 17 +++++++++++++++--
 1 file changed, 15 insertions(+), 2 deletions(-)

diff --git a/qemu-log.c b/qemu-log.c
index 8c59063..2eebac0 100644
--- a/qemu-log.c
+++ b/qemu-log.c
@@ -70,11 +70,24 @@ void do_qemu_set_log(int log_flags, bool use_own_buffers)
         qemu_log_close();
     }
 }
-
+/*
+ * Allow the user to include %d in their logfile which will be
+ * substituted with the current PID. This is useful for debugging many
+ * nested linux-user tasks but will result in lots of logs.
+ */
 void qemu_set_log_filename(const char *filename)
 {
     g_free(logfilename);
-    logfilename = g_strdup(filename);
+    if (g_strrstr(filename, "%d")) {
+        /* if we are going to format this we'd better validate first */
+        if (g_regex_match_simple("^[^%]+%d[^%]+$", filename, 0, 0)) {
+            logfilename = g_strdup_printf(filename, getpid());
+        } else {
+            g_error("Bad logfile format: %s", filename);
+        }
+    } else {
+        logfilename = g_strdup(filename);
+    }
     qemu_log_close();
     qemu_set_log(qemu_loglevel);
 }
-- 
2.7.0

Re: [Qemu-devel] [PATCH v5 5/9] qemu-log: support simple pid substitution in logfile

[Richard Henderson]

On 02/05/2016 01:56 AM, Alex Bennée wrote:
> +    if (g_strrstr(filename, "%d")) {
> +        /* if we are going to format this we'd better validate first */
> +        if (g_regex_match_simple("^[^%]+%d[^%]+$", filename, 0, 0)) {

Why g_strrstr instead of strstr?  There should be only one, so why look for the 
last?


r~

Re: [Qemu-devel] [PATCH v5 5/9] qemu-log: support simple pid substitution in logfile

[Eric Blake]

[-- Attachment #1: Type: text/plain, Size: 747 bytes --]

On 02/04/2016 03:26 PM, Richard Henderson wrote:
> On 02/05/2016 01:56 AM, Alex Bennée wrote:
>> +    if (g_strrstr(filename, "%d")) {
>> +        /* if we are going to format this we'd better validate first */
>> +        if (g_regex_match_simple("^[^%]+%d[^%]+$", filename, 0, 0)) {
> 
> Why g_strrstr instead of strstr?  There should be only one, so why look
> for the last?

For that matter, why use a heavyweight regex, when you can achieve the
same validation with the faster:

char *tmp = strchr(filename, '%');
if (tmp) {
    if (tmp[1] != 'd' || strchr(tmp + 2, '%')) {
        ...report invalid string
    }

-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

Re: [Qemu-devel] [PATCH v5 5/9] qemu-log: support simple pid substitution in logfile

[Alex Bennée]

Eric Blake <eblake@redhat.com> writes:

> On 02/04/2016 03:26 PM, Richard Henderson wrote:
>> On 02/05/2016 01:56 AM, Alex Bennée wrote:
>>> +    if (g_strrstr(filename, "%d")) {
>>> +        /* if we are going to format this we'd better validate first */
>>> +        if (g_regex_match_simple("^[^%]+%d[^%]+$", filename, 0, 0)) {
>>
>> Why g_strrstr instead of strstr?  There should be only one, so why look
>> for the last?

Yeah, my fault for using the glib functions, I guess
g_strstr_len(filename, -1, "%d") would be the glib equivalent for
strstr.

> For that matter, why use a heavyweight regex, when you can achieve the
> same validation with the faster:
>
> char *tmp = strchr(filename, '%');
> if (tmp) {
>     if (tmp[1] != 'd' || strchr(tmp + 2, '%')) {
>         ...report invalid string
>     }

For option parsing I'm not too worried about speed. At least a regex
gives the explicit format we expect (for those that read regex). I guess
I can do it manually if preferred.

--
Alex Bennée

[Qemu-devel] [PATCH v5 6/9] qemu-log: new option -dfilter to limit output

[Alex Bennée]

When debugging big programs or system emulation sometimes you want both
the verbosity of cpu,exec et all but don't want to generate lots of logs
for unneeded stuff. This patch adds a new option -dfilter which allows
you to specify interesting address ranges in the form:

  -dfilter 0x8000..0x9000,0xffffffc000080000+0x200,...

Then logging code can use the new qemu_log_in_addr_range() function to
decide if it will output logging information for the given range.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

---

v2
  - More clean-ups to the documentation
v3
  - re-base
  - use GArray instead of GList to avoid cache bouncing
  - checkpatch fixes
v5
  - minor re-base conflicts
  - *did not* convert to -d dfilter=x fmt as easier to document
  - strtoul -> qemu_strtoul
  - fix a few checkpatch spacing warnings
  - made range operator .., - now intuitively subtracts from start
  - no added r-b tag as changes a bit
---
 include/qemu/log.h |  2 ++
 qemu-log.c         | 85 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 qemu-options.hx    | 18 ++++++++++++
 vl.c               |  3 ++
 4 files changed, 108 insertions(+)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index 776ceaf..34a8fe6 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -190,6 +190,8 @@ static inline void qemu_set_log(int log_flags)
 }
 
 void qemu_set_log_filename(const char *filename);
+void qemu_set_dfilter_ranges(const char *ranges);
+bool qemu_log_in_addr_range(uint64_t addr);
 int qemu_str_to_log_mask(const char *str);
 
 /* Print a usage message listing all the valid logging categories
diff --git a/qemu-log.c b/qemu-log.c
index 2eebac0..5433a78 100644
--- a/qemu-log.c
+++ b/qemu-log.c
@@ -19,11 +19,13 @@
 
 #include "qemu-common.h"
 #include "qemu/log.h"
+#include "qemu/range.h"
 
 static char *logfilename;
 FILE *qemu_logfile;
 int qemu_loglevel;
 static int log_append = 0;
+static GArray *debug_regions;
 
 void qemu_log(const char *fmt, ...)
 {
@@ -92,6 +94,89 @@ void qemu_set_log_filename(const char *filename)
     qemu_set_log(qemu_loglevel);
 }
 
+/* Returns true if addr is in our debug filter or no filter defined
+ */
+bool qemu_log_in_addr_range(uint64_t addr)
+{
+    if (debug_regions) {
+        int i = 0;
+        for (i = 0; i < debug_regions->len; i++) {
+            struct Range *range = &g_array_index(debug_regions, Range, i);
+            if (addr >= range->begin && addr <= range->end) {
+                return true;
+            }
+        }
+        return false;
+    } else {
+        return true;
+    }
+}
+
+
+void qemu_set_dfilter_ranges(const char *filter_spec)
+{
+    gchar **ranges = g_strsplit(filter_spec, ",", 0);
+    if (ranges) {
+        gchar **next = ranges;
+        gchar *r = *next++;
+        debug_regions = g_array_sized_new(FALSE, FALSE,
+                                          sizeof(Range), g_strv_length(ranges));
+        while (r) {
+            gchar *range_op = g_strstr_len(r, -1, "-");
+            if (!range_op) {
+                range_op = g_strstr_len(r, -1, "+");
+            }
+            if (!range_op) {
+                range_op = g_strstr_len(r, -1, ".");
+            }
+            if (range_op) {
+                struct Range range;
+                int err;
+                gchar d = *range_op;
+                gchar *range_val = range_op + 1;
+                /* ensure first value terminated and stray extra
+                 * range_ops are swallowed to keep qemu_stroul happy
+                 */
+                *range_op = 0;
+                g_strdelimit(range_val, ".", ' ');
+
+                err = qemu_strtoul(r, NULL, 0, &range.begin);
+                switch (d) {
+                case '+':
+                {
+                    unsigned long len;
+                    err |= qemu_strtoul(range_val, NULL, 0, &len);
+                    range.end = range.begin + len;
+                    break;
+                }
+                case '-':
+                {
+                    unsigned long len;
+                    err |= qemu_strtoul(range_val, NULL, 0, &len);
+                    range.end = range.begin;
+                    range.begin = range.end - len;
+                    break;
+                }
+                case '.':
+                    err |= qemu_strtoul(range_val, NULL, 0, &range.end);
+                    break;
+                default:
+                    g_assert_not_reached();
+                }
+                if (err) {
+                    g_error("Failed to parse range in: %s, %d", r, err);
+                } else {
+                    g_array_append_val(debug_regions, range);
+                }
+            } else {
+                g_error("Bad range specifier in: %s", r);
+            }
+            r = *next++;
+        }
+        g_strfreev(ranges);
+    }
+}
+
 const QEMULogItem qemu_log_items[] = {
     { CPU_LOG_TB_OUT_ASM, "out_asm",
       "show generated host assembly code for each compiled TB" },
diff --git a/qemu-options.hx b/qemu-options.hx
index f31a240..ca0f4c9 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3090,6 +3090,24 @@ STEXI
 Output log in @var{logfile} instead of to stderr
 ETEXI
 
+DEF("dfilter", HAS_ARG, QEMU_OPTION_DFILTER, \
+    "-dfilter range,..  filter debug output to range of addresses (useful for -d cpu,exec,etc..)\n",
+    QEMU_ARCH_ALL)
+STEXI
+@item -dfilter @var{range1}[,...]
+@findex -dfilter
+Filter debug output to that relevant to a range of target addresses. The filter
+spec can be either @var{start}+@var{size}, @var{start}-@var{size} or
+@var{start}..@var{end} where @var{start} @var{end} and @var{size} are the
+addresses and sizes required. For example:
+@example
+    -dfilter 0x8000..0x9000,0xffffffc000080000+0x200,0xffffffc000060000-0x1000
+@end example
+Will dump output for any code in the 0x1000 sized block starting at 0x8000 and
+the 0x200 sized block starting at 0xffffffc000080000 and another 0x1000 sized
+block starting at 0xffffffc00005f000.
+ETEXI
+
 DEF("L", HAS_ARG, QEMU_OPTION_L, \
     "-L path         set the directory for the BIOS, VGA BIOS and keymaps\n",
     QEMU_ARCH_ALL)
diff --git a/vl.c b/vl.c
index f043009..a0a546f 100644
--- a/vl.c
+++ b/vl.c
@@ -3361,6 +3361,9 @@ int main(int argc, char **argv, char **envp)
             case QEMU_OPTION_D:
                 log_file = optarg;
                 break;
+            case QEMU_OPTION_DFILTER:
+                qemu_set_dfilter_ranges(optarg);
+                break;
             case QEMU_OPTION_s:
                 add_device_config(DEV_GDB, "tcp::" DEFAULT_GDBSTUB_PORT);
                 break;
-- 
2.7.0

Re: [Qemu-devel] [PATCH v5 6/9] qemu-log: new option -dfilter to limit output

[Richard Henderson]

On 02/05/2016 01:56 AM, Alex Bennée wrote:
> +            gchar *range_op = g_strstr_len(r, -1, "-");

This is strchr.

> +                range_op = g_strstr_len(r, -1, ".");

Or at least if you're going to make use of strstr, search for "..".

> +                g_strdelimit(range_val, ".", ' ');

Cause this is just weird.  It accepts "1+.2" just the same as "1..2".

> +                err = qemu_strtoul(r, NULL, 0, &range.begin);

This should be strtoull.  You probably broke 32-bit compilation here.

> +                case '+':
> +                {
> +                    unsigned long len;
> +                    err |= qemu_strtoul(range_val, NULL, 0, &len);
> +                    range.end = range.begin + len;
> +                    break;
> +                }
> +                case '-':
> +                {
> +                    unsigned long len;
> +                    err |= qemu_strtoul(range_val, NULL, 0, &len);
> +                    range.end = range.begin;
> +                    range.begin = range.end - len;
> +                    break;
> +                }

Both of these have off-by-one bugs, since end is inclusive.

> +                case '.':
> +                    err |= qemu_strtoul(range_val, NULL, 0, &range.end);
> +                    break;

I'd think multiple dot detection belongs here, and you need not smash them to ' 
' but merely notice that there are two of them and then strtoull range_val+1.


r~

Re: [Qemu-devel] [PATCH v5 6/9] qemu-log: new option -dfilter to limit output

[Alex Bennée]

Richard Henderson <rth@twiddle.net> writes:

> On 02/05/2016 01:56 AM, Alex Bennée wrote:
>> +            gchar *range_op = g_strstr_len(r, -1, "-");
>
> This is strchr.
>
>> +                range_op = g_strstr_len(r, -1, ".");
>
> Or at least if you're going to make use of strstr, search for "..".
>
>> +                g_strdelimit(range_val, ".", ' ');
>
> Cause this is just weird.  It accepts "1+.2" just the same as "1..2".
>
>> +                err = qemu_strtoul(r, NULL, 0, &range.begin);
>
> This should be strtoull.  You probably broke 32-bit compilation here.

OK I think this version is a lot cleaner:

  void qemu_set_dfilter_ranges(const char *filter_spec)
  {
      gchar **ranges = g_strsplit(filter_spec, ",", 0);
      if (ranges) {
          gchar **next = ranges;
          gchar *r = *next++;
          debug_regions = g_array_sized_new(FALSE, FALSE,
                                            sizeof(Range), g_strv_length(ranges));
          while (r) {
              gchar *range_op = g_strstr_len(r, -1, "-");
              gchar *r2 = range_op ? range_op + 1 : NULL;
              if (!range_op) {
                  range_op = g_strstr_len(r, -1, "+");
                  r2 = range_op ? range_op + 1 : NULL;
              }
              if (!range_op) {
                  range_op = g_strstr_len(r, -1, "..");
                  r2 = range_op ? range_op + 2 : NULL;
              }
              if (range_op) {
                  struct Range range;
                  int err;
                  const char *e = NULL;

                  err = qemu_strtoull(r, &e, 0, &range.begin);

                  g_assert(e == range_op);

                  switch (*range_op) {
                  case '+':
                  {
                      unsigned long len;
                      err |= qemu_strtoull(r2, NULL, 0, &len);
                      range.end = range.begin + len;
                      break;
                  }
                  case '-':
                  {
                      unsigned long len;
                      err |= qemu_strtoull(r2, NULL, 0, &len);
                      range.end = range.begin;
                      range.begin = range.end - len;
                      break;
                  }
                  case '.':
                      err |= qemu_strtoull(r2, NULL, 0, &range.end);
                      break;
                  default:
                      g_assert_not_reached();
                  }
                  if (err) {
                      g_error("Failed to parse range in: %s, %d", r, err);
                  } else {
                      g_array_append_val(debug_regions, range);
                  }
              } else {
                  g_error("Bad range specifier in: %s", r);
              }
              r = *next++;
          }
          g_strfreev(ranges);
      }
  }


>
>> +                case '+':
>> +                {
>> +                    unsigned long len;
>> +                    err |= qemu_strtoul(range_val, NULL, 0, &len);
>> +                    range.end = range.begin + len;
>> +                    break;
>> +                }
>> +                case '-':
>> +                {
>> +                    unsigned long len;
>> +                    err |= qemu_strtoul(range_val, NULL, 0, &len);
>> +                    range.end = range.begin;
>> +                    range.begin = range.end - len;
>> +                    break;
>> +                }
>
> Both of these have off-by-one bugs, since end is inclusive.

Sorry I don't quite follow, do you mean the position of range_val (now
r2) or the final value of range.end?

>
>> +                case '.':
>> +                    err |= qemu_strtoul(range_val, NULL, 0, &range.end);
>> +                    break;
>
> I'd think multiple dot detection belongs here, and you need not smash them to '
> ' but merely notice that there are two of them and then strtoull
> range_val+1.

I think this is covered with the new code now.

>
>
> r~


--
Alex Bennée

Re: [Qemu-devel] [PATCH v5 6/9] qemu-log: new option -dfilter to limit output

[Richard Henderson]

On 02/11/2016 04:40 AM, Alex Bennée wrote:
> OK I think this version is a lot cleaner:
>
>    void qemu_set_dfilter_ranges(const char *filter_spec)
>    {
>        gchar **ranges = g_strsplit(filter_spec, ",", 0);
>        if (ranges) {
>            gchar **next = ranges;
>            gchar *r = *next++;
>            debug_regions = g_array_sized_new(FALSE, FALSE,
>                                              sizeof(Range), g_strv_length(ranges));
>            while (r) {
>                gchar *range_op = g_strstr_len(r, -1, "-");
>                gchar *r2 = range_op ? range_op + 1 : NULL;
>                if (!range_op) {
>                    range_op = g_strstr_len(r, -1, "+");
>                    r2 = range_op ? range_op + 1 : NULL;
>                }
>                if (!range_op) {
>                    range_op = g_strstr_len(r, -1, "..");
>                    r2 = range_op ? range_op + 2 : NULL;
>                }

I guess I'll quit quibbling about silly glib functions.  But really, with the 
-1 argument, you gain nothing except obfuscation over using the standard C library.

>                if (range_op) {
>                    struct Range range;
>                    int err;
>                    const char *e = NULL;
>
>                    err = qemu_strtoull(r, &e, 0, &range.begin);
>
>                    g_assert(e == range_op);
>
>                    switch (*range_op) {
>                    case '+':
>                    {
>                        unsigned long len;
>                        err |= qemu_strtoull(r2, NULL, 0, &len);

You can't or errno's together and then...

>                        g_error("Failed to parse range in: %s, %d", r, err);

... expect to get anything meaningful out of them.

>>> +                case '+':
>>> +                {
>>> +                    unsigned long len;
>>> +                    err |= qemu_strtoul(range_val, NULL, 0, &len);
>>> +                    range.end = range.begin + len;
>>> +                    break;
>>> +                }
>>> +                case '-':
>>> +                {
>>> +                    unsigned long len;
>>> +                    err |= qemu_strtoul(range_val, NULL, 0, &len);
>>> +                    range.end = range.begin;
>>> +                    range.begin = range.end - len;
>>> +                    break;
>>> +                }
>>
>> Both of these have off-by-one bugs, since end is inclusive.
>
> Sorry I don't quite follow, do you mean the position of range_val (now
> r2) or the final value of range.end?

Final value of range.end.  In that

    0x1000..0x1000
and
    0x1000+1

should both produce a range that covers a single byte at 0x1000.


r~

Re: [Qemu-devel] [PATCH v5 6/9] qemu-log: new option -dfilter to limit output

[Alex Bennée]

Richard Henderson <rth@twiddle.net> writes:

> On 02/11/2016 04:40 AM, Alex Bennée wrote:
>> OK I think this version is a lot cleaner:
>>
>>    void qemu_set_dfilter_ranges(const char *filter_spec)
>>    {
>>        gchar **ranges = g_strsplit(filter_spec, ",", 0);
>>        if (ranges) {
>>            gchar **next = ranges;
>>            gchar *r = *next++;
>>            debug_regions = g_array_sized_new(FALSE, FALSE,
>>                                              sizeof(Range), g_strv_length(ranges));
>>            while (r) {
>>                gchar *range_op = g_strstr_len(r, -1, "-");
>>                gchar *r2 = range_op ? range_op + 1 : NULL;
>>                if (!range_op) {
>>                    range_op = g_strstr_len(r, -1, "+");
>>                    r2 = range_op ? range_op + 1 : NULL;
>>                }
>>                if (!range_op) {
>>                    range_op = g_strstr_len(r, -1, "..");
>>                    r2 = range_op ? range_op + 2 : NULL;
>>                }
>
> I guess I'll quit quibbling about silly glib functions.  But really, with the
> -1 argument, you gain nothing except obfuscation over using the
> standard C library.

No you are quite right to quibble. It's a hard habit to break because
I've gotten used to glib's arguably more predictable behaviour when
string munging.

>
>>                if (range_op) {
>>                    struct Range range;
>>                    int err;
>>                    const char *e = NULL;
>>
>>                    err = qemu_strtoull(r, &e, 0, &range.begin);
>>
>>                    g_assert(e == range_op);
>>
>>                    switch (*range_op) {
>>                    case '+':
>>                    {
>>                        unsigned long len;
>>                        err |= qemu_strtoull(r2, NULL, 0, &len);
>
> You can't or errno's together and then...
>
>>                        g_error("Failed to parse range in: %s, %d", r, err);
>
> ... expect to get anything meaningful out of them.

True, I'll drop the %d, I was just trying to avoid having multiple error
handling legs.

>
>>>> +                case '+':
>>>> +                {
>>>> +                    unsigned long len;
>>>> +                    err |= qemu_strtoul(range_val, NULL, 0, &len);
>>>> +                    range.end = range.begin + len;
>>>> +                    break;
>>>> +                }
>>>> +                case '-':
>>>> +                {
>>>> +                    unsigned long len;
>>>> +                    err |= qemu_strtoul(range_val, NULL, 0, &len);
>>>> +                    range.end = range.begin;
>>>> +                    range.begin = range.end - len;
>>>> +                    break;
>>>> +                }
>>>
>>> Both of these have off-by-one bugs, since end is inclusive.
>>
>> Sorry I don't quite follow, do you mean the position of range_val (now
>> r2) or the final value of range.end?
>
> Final value of range.end.  In that
>
>     0x1000..0x1000
> and
>     0x1000+1
>
> should both produce a range that covers a single byte at 0x1000.

Ahh OK. I suppose if I'm being good about this I should add some tests
to defend the ranges. I wonder how easy command line parsing unit tests
are in qtest?

>
>
> r~


--
Alex Bennée

[Qemu-devel] [PATCH v5 7/9] qemu-log: dfilter-ise exec, out_asm, op and opt_op

[Alex Bennée]

This ensures the code generation debug code will honour -dfilter if set.
For the "exec" tracing I've added a new inline macro for efficiency's
sake.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Aurelien Jarno <aurelien@aureL32.net>

----
v2
   - checkpatch updates
   - add qemu_log_mask_and_addr macro for inline dump for traces
   - re-base on re-factored tcg layout
   - include new Trace & Link lines
v5
   - add r-b tag
   - slight reword to commit now LOG_OP is common
---
 cpu-exec.c              | 13 +++++++------
 include/exec/exec-all.h |  8 +++++---
 include/qemu/log.h      | 15 +++++++++++++++
 tcg/tcg.c               |  6 ++++--
 translate-all.c         |  3 ++-
 5 files changed, 33 insertions(+), 12 deletions(-)

diff --git a/cpu-exec.c b/cpu-exec.c
index 8151e6f..d6fb033 100644
--- a/cpu-exec.c
+++ b/cpu-exec.c
@@ -138,8 +138,9 @@ static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb)
     uintptr_t next_tb;
     uint8_t *tb_ptr = itb->tc_ptr;
 
-    qemu_log_mask(CPU_LOG_EXEC, "Trace %p [" TARGET_FMT_lx "] %s\n",
-                  itb->tc_ptr, itb->pc, lookup_symbol(itb->pc));
+    qemu_log_mask_and_addr(CPU_LOG_EXEC, itb->pc,
+                           "Trace %p [" TARGET_FMT_lx "] %s\n",
+                           itb->tc_ptr, itb->pc, lookup_symbol(itb->pc));
 
 #if defined(DEBUG_DISAS)
     if (qemu_loglevel_mask(CPU_LOG_TB_CPU)) {
@@ -170,10 +171,10 @@ static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb)
          */
         CPUClass *cc = CPU_GET_CLASS(cpu);
         TranslationBlock *tb = (TranslationBlock *)(next_tb & ~TB_EXIT_MASK);
-        qemu_log_mask(CPU_LOG_EXEC,
-                      "Abandoned execution of TB chain before %p ["
-                      TARGET_FMT_lx "] %s\n",
-                      itb->tc_ptr, itb->pc, lookup_symbol(itb->pc));
+        qemu_log_mask_and_addr(CPU_LOG_EXEC, itb->pc,
+                               "Abandoned execution of TB chain before %p ["
+                               TARGET_FMT_lx "] %s\n",
+                               itb->tc_ptr, itb->pc, lookup_symbol(itb->pc));
         if (cc->synchronize_from_tb) {
             cc->synchronize_from_tb(cpu, tb);
         } else {
diff --git a/include/exec/exec-all.h b/include/exec/exec-all.h
index 1823ee3..7362095 100644
--- a/include/exec/exec-all.h
+++ b/include/exec/exec-all.h
@@ -379,9 +379,11 @@ static inline void tb_add_jump(TranslationBlock *tb, int n,
 {
     /* NOTE: this test is only needed for thread safety */
     if (!tb->jmp_next[n]) {
-        qemu_log_mask(CPU_LOG_EXEC, "Linking TBs %p [" TARGET_FMT_lx
-                      "] index %d -> %p [" TARGET_FMT_lx "]\n",
-                      tb->tc_ptr, tb->pc, n, tb_next->tc_ptr, tb_next->pc);
+        qemu_log_mask_and_addr(CPU_LOG_EXEC, tb->pc,
+                               "Linking TBs %p [" TARGET_FMT_lx
+                               "] index %d -> %p [" TARGET_FMT_lx "]\n",
+                               tb->tc_ptr, tb->pc, n,
+                               tb_next->tc_ptr, tb_next->pc);
         /* patch the native jump address */
         tb_set_jmp_target(tb, n, (uintptr_t)tb_next->tc_ptr);
 
diff --git a/include/qemu/log.h b/include/qemu/log.h
index 34a8fe6..de9ec7f 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -85,6 +85,21 @@ qemu_log_vprintf(const char *fmt, va_list va)
         }                                               \
     } while (0)
 
+/* log only if a bit is set on the current loglevel mask
+ * and we are in the address range we care about:
+ * @mask: bit to check in the mask
+ * @addr: address to check in dfilter
+ * @fmt: printf-style format string
+ * @args: optional arguments for format string
+ */
+#define qemu_log_mask_and_addr(MASK, ADDR, FMT, ...)    \
+    do {                                                \
+        if (unlikely(qemu_loglevel_mask(MASK)) &&       \
+                     qemu_log_in_addr_range(ADDR)) {    \
+            qemu_log(FMT, ## __VA_ARGS__);              \
+        }                                               \
+    } while (0)
+
 /* Special cases: */
 
 /* cpu_dump_state() logging functions: */
diff --git a/tcg/tcg.c b/tcg/tcg.c
index 0101cc1..ad697cf 100644
--- a/tcg/tcg.c
+++ b/tcg/tcg.c
@@ -2339,7 +2339,8 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
 #endif
 
 #ifdef DEBUG_DISAS
-    if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP))) {
+    if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP)
+                 && qemu_log_in_addr_range(tb->pc))) {
         qemu_log("OP:\n");
         tcg_dump_ops(s);
         qemu_log("\n");
@@ -2366,7 +2367,8 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
 #endif
 
 #ifdef DEBUG_DISAS
-    if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP_OPT))) {
+    if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP_OPT)
+                 && qemu_log_in_addr_range(tb->pc))) {
         qemu_log("OP after optimization and liveness analysis:\n");
         tcg_dump_ops(s);
         qemu_log("\n");
diff --git a/translate-all.c b/translate-all.c
index dce00d5..37003a7 100644
--- a/translate-all.c
+++ b/translate-all.c
@@ -1134,7 +1134,8 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
 #endif
 
 #ifdef DEBUG_DISAS
-    if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM)) {
+    if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM) &&
+        qemu_log_in_addr_range(tb->pc)) {
         qemu_log("OUT: [size=%d]\n", gen_code_size);
         log_disas(tb->tc_ptr, gen_code_size);
         qemu_log("\n");
-- 
2.7.0

Re: [Qemu-devel] [PATCH v5 7/9] qemu-log: dfilter-ise exec, out_asm, op and opt_op

[Richard Henderson]

On 02/05/2016 01:56 AM, Alex Bennée wrote:
> This ensures the code generation debug code will honour -dfilter if set.
> For the "exec" tracing I've added a new inline macro for efficiency's
> sake.
>
> Signed-off-by: Alex Bennée<alex.bennee@linaro.org>
> Reviewed-by: Aurelien Jarno<aurelien@aureL32.net>
>
> ----
> v2
>     - checkpatch updates
>     - add qemu_log_mask_and_addr macro for inline dump for traces
>     - re-base on re-factored tcg layout
>     - include new Trace & Link lines
> v5
>     - add r-b tag
>     - slight reword to commit now LOG_OP is common
> ---
>   cpu-exec.c              | 13 +++++++------
>   include/exec/exec-all.h |  8 +++++---
>   include/qemu/log.h      | 15 +++++++++++++++
>   tcg/tcg.c               |  6 ++++--
>   translate-all.c         |  3 ++-
>   5 files changed, 33 insertions(+), 12 deletions(-)

Reviewed-by: Richard Henderson <rth@twiddle.net>


r~

[Qemu-devel] [PATCH v5 8/9] target-arm: dfilter support for in_asm

[Alex Bennée]

Each individual architecture needs to use the qemu_log_in_addr_range()
feature for enabling in_asm output as it is part of the frontend.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Aurelien Jarno <aurelien@aurel32.net>

---
v5
  - no longer wrapping tcg_gen_insn_start (was tcg_gen_debug)
  - reword to handle only in_asm
  - added r-b tag
---
 target-arm/translate-a64.c | 3 ++-
 target-arm/translate.c     | 3 ++-
 2 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/target-arm/translate-a64.c b/target-arm/translate-a64.c
index 80f6c20..f488218 100644
--- a/target-arm/translate-a64.c
+++ b/target-arm/translate-a64.c
@@ -11210,7 +11210,8 @@ done_generating:
     gen_tb_end(tb, num_insns);
 
 #ifdef DEBUG_DISAS
-    if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)) {
+    if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM) &&
+        qemu_log_in_addr_range(pc_start)) {
         qemu_log("----------------\n");
         qemu_log("IN: %s\n", lookup_symbol(pc_start));
         log_target_disas(cs, pc_start, dc->pc - pc_start,
diff --git a/target-arm/translate.c b/target-arm/translate.c
index cff511b..5dd1054 100644
--- a/target-arm/translate.c
+++ b/target-arm/translate.c
@@ -11580,7 +11580,8 @@ done_generating:
     gen_tb_end(tb, num_insns);
 
 #ifdef DEBUG_DISAS
-    if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)) {
+    if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM) &&
+        qemu_log_in_addr_range(pc_start)) {
         qemu_log("----------------\n");
         qemu_log("IN: %s\n", lookup_symbol(pc_start));
         log_target_disas(cs, pc_start, dc->pc - pc_start,
-- 
2.7.0

[Qemu-devel] [PATCH v5 9/9] cputlb: modernise the debug support

[Alex Bennée]

To avoid cluttering the code with #ifdef legs we wrap up the print
statements into a tlb_debug() macro. As access to the virtual TLB can
get quite heavy defining DEBUG_TLB_LOG will ensure all the logs go to
the qemu_log target of CPU_LOG_MMU instead of stderr. This remains
compile time optional as these debug statements haven't been considered
for usefulness for user visible logging.

I've also removed DEBUG_TLB_CHECK which wasn't used.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

---
v2
  - ensure compiler checks format strings even if debug is optimised out
v5
  - reword commit to justify not just using qemu_log at this time
---
 cputlb.c | 54 +++++++++++++++++++++++++++++++++++-------------------
 1 file changed, 35 insertions(+), 19 deletions(-)

diff --git a/cputlb.c b/cputlb.c
index 3973030..f259b04 100644
--- a/cputlb.c
+++ b/cputlb.c
@@ -30,8 +30,30 @@
 #include "exec/ram_addr.h"
 #include "tcg/tcg.h"
 
-//#define DEBUG_TLB
-//#define DEBUG_TLB_CHECK
+/* DEBUG defines, enable DEBUG_TLB_LOG to log to the CPU_LOG_MMU target */
+/* #define DEBUG_TLB */
+/* #define DEBUG_TLB_LOG */
+
+#ifdef DEBUG_TLB
+# define DEBUG_TLB_GATE 1
+# ifdef DEBUG_TLB_LOG
+#  define DEBUG_TLB_LOG_GATE 1
+# else
+#  define DEBUG_TLB_LOG_GATE 0
+# endif
+#else
+# define DEBUG_TLB_GATE 0
+# define DEBUG_TLB_LOG_GATE 0
+#endif
+
+#define tlb_debug(fmt, ...) do { \
+    if (DEBUG_TLB_LOG_GATE) { \
+        qemu_log_mask(CPU_LOG_MMU, "%s: " fmt, __func__, \
+                      ## __VA_ARGS__); \
+    } else if (DEBUG_TLB_GATE) { \
+        fprintf(stderr, "%s: " fmt, __func__, ## __VA_ARGS__); \
+    } \
+} while (0)
 
 /* statistics */
 int tlb_flush_count;
@@ -52,9 +74,8 @@ void tlb_flush(CPUState *cpu, int flush_global)
 {
     CPUArchState *env = cpu->env_ptr;
 
-#if defined(DEBUG_TLB)
-    printf("tlb_flush:\n");
-#endif
+    tlb_debug("(%d)\n", flush_global);
+
     /* must reset current TB so that interrupts cannot modify the
        links while we are modifying them */
     cpu->current_tb = NULL;
@@ -128,16 +149,14 @@ void tlb_flush_page(CPUState *cpu, target_ulong addr)
     int i;
     int mmu_idx;
 
-#if defined(DEBUG_TLB)
-    printf("tlb_flush_page: " TARGET_FMT_lx "\n", addr);
-#endif
+    tlb_debug("page :" TARGET_FMT_lx "\n", addr);
+
     /* Check if we need to flush due to large pages.  */
     if ((addr & env->tlb_flush_mask) == env->tlb_flush_addr) {
-#if defined(DEBUG_TLB)
-        printf("tlb_flush_page: forced full flush ("
-               TARGET_FMT_lx "/" TARGET_FMT_lx ")\n",
-               env->tlb_flush_addr, env->tlb_flush_mask);
-#endif
+        tlb_debug("forcing full flush ("
+                  TARGET_FMT_lx "/" TARGET_FMT_lx ")\n",
+                  env->tlb_flush_addr, env->tlb_flush_mask);
+
         tlb_flush(cpu, 1);
         return;
     }
@@ -367,12 +386,9 @@ void tlb_set_page_with_attrs(CPUState *cpu, target_ulong vaddr,
     section = address_space_translate_for_iotlb(cpu, asidx, paddr, &xlat, &sz);
     assert(sz >= TARGET_PAGE_SIZE);
 
-#if defined(DEBUG_TLB)
-    qemu_log_mask(CPU_LOG_MMU,
-           "tlb_set_page: vaddr=" TARGET_FMT_lx " paddr=0x" TARGET_FMT_plx
-           " prot=%x idx=%d\n",
-           vaddr, paddr, prot, mmu_idx);
-#endif
+    tlb_debug("tlb_set_page: vaddr=" TARGET_FMT_lx " paddr=0x" TARGET_FMT_plx
+              " prot=%x idx=%d\n",
+              vaddr, paddr, prot, mmu_idx);
 
     address = vaddr;
     if (!memory_region_is_ram(section->mr) && !memory_region_is_romd(section->mr)) {
-- 
2.7.0

Re: [Qemu-devel] [PATCH v5 9/9] cputlb: modernise the debug support

[Richard Henderson]

On 02/05/2016 01:56 AM, Alex Bennée wrote:
> To avoid cluttering the code with #ifdef legs we wrap up the print
> statements into a tlb_debug() macro. As access to the virtual TLB can
> get quite heavy defining DEBUG_TLB_LOG will ensure all the logs go to
> the qemu_log target of CPU_LOG_MMU instead of stderr. This remains
> compile time optional as these debug statements haven't been considered
> for usefulness for user visible logging.
>
> I've also removed DEBUG_TLB_CHECK which wasn't used.
>
> Signed-off-by: Alex Bennée<alex.bennee@linaro.org>
>
> ---
> v2
>    - ensure compiler checks format strings even if debug is optimised out
> v5
>    - reword commit to justify not just using qemu_log at this time
> ---
>   cputlb.c | 54 +++++++++++++++++++++++++++++++++++-------------------
>   1 file changed, 35 insertions(+), 19 deletions(-)

Reviewed-by: Richard Henderson <rth@twiddle.net>


r~