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

Commit Message

Alex Bennée Feb. 4, 2016, 2:56 p.m. UTC

From: Peter Maydell <[e-mail]>

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 <[e-mail]>
Signed-off-by: Alex Bennée <[e-mail]>
[AJB: reword patch title]
Reviewed-by: Aurelien Jarno <[e-mail]>
---
 cpu-exec.c              | 20 +++++++++++---------
 include/exec/exec-all.h |  3 +++
 2 files changed, 14 insertions(+), 9 deletions(-)

Comments

Richard Henderson Feb. 4, 2016, 10:17 p.m. UTC | #1

On 02/05/2016 01:56 AM, Alex Bennée wrote:
> From: Peter Maydell<[e-mail]>
>
> 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<[e-mail]>
> Signed-off-by: Alex Bennée<[e-mail]>
> [AJB: reword patch title]
> Reviewed-by: Aurelien Jarno<[e-mail]>
> ---
>   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  <[e-mail]>


r~

Patch

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);