| Message ID | 1438593291-27109-6-git-send-email-alex.bennee@linaro.org |
|---|---|
| State | New |
| Headers | show |
On 2015-08-03 10:14, 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] > --- > 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 75694f3..a039f1a 100644 > --- a/cpu-exec.c > +++ b/cpu-exec.c > @@ -175,10 +175,14 @@ void cpu_reload_memory_map(CPUState *cpu) > #endif > > /* 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)) { > @@ -209,6 +213,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 { > @@ -247,7 +255,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); > @@ -356,7 +364,6 @@ int cpu_exec(CPUState *cpu) > #endif > int ret, interrupt_request; > TranslationBlock *tb; > - uint8_t *tc_ptr; > uintptr_t next_tb; > SyncClocks sc; > > @@ -491,10 +498,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. */ > @@ -513,9 +516,8 @@ int cpu_exec(CPUState *cpu) > barrier(); > if (likely(!cpu->exit_request)) { > trace_exec_tb(tb, tb->pc); > - tc_ptr = tb->tc_ptr; > /* execute the generated code */ > - next_tb = cpu_tb_exec(cpu, tc_ptr); > + next_tb = cpu_tb_exec(cpu, tb); > switch (next_tb & TB_EXIT_MASK) { > case TB_EXIT_REQUESTED: > /* Something asked us to stop executing > diff --git a/include/exec/exec-all.h b/include/exec/exec-all.h > index 7ac8e7e..361d3d2 100644 > --- a/include/exec/exec-all.h > +++ b/include/exec/exec-all.h > @@ -282,6 +282,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); > Reviewed-by: Aurelien Jarno <aurelien@aurel32.net>
Hi Peter, Alex, On 08/03/2015 05:14 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] Do you think there's some way to log the loop count when a circular chain is executed? System Emulation started at Mon Aug 10 15:30:49 2015 Invocation:aarch64-softmmu/qemu-system-aarch64 -M virt -cpu cortex-a57 -m 2G -kernel psci-exit -d exec,int,in_asm -nodefaults -nographic -monitor none -icount shift=0 ---------------- IN: 0x0000000080000000: d2800140 mov x0, #0xa 0x0000000080000004: f1000400 subs x0, x0, #0x1 (1) 0x0000000080000008: 54ffffe1 b.ne #-0x4 (addr 0x80000004) Trace 0x7f38787cb000 [0000000080000000] ---------------- IN: 0x0000000080000004: f1000400 subs x0, x0, #0x1 (1) 0x0000000080000008: 54ffffe1 b.ne #-0x4 (addr 0x80000004) Linking TBs 0x7f38787cb000 [0000000080000000] index 1 -> 0x7f38787cb0d0 [0000000080000004] Trace 0x7f38787cb0d0 [0000000080000004] Linking TBs 0x7f38787cb0d0 [0000000080000004] index 1 -> 0x7f38787cb0d0 [0000000080000004] Trace 0x7f38787cb0d0 [0000000080000004] ---------------- IN: 0x000000008000000c: d2800100 mov x0, #0x8 0x0000000080000010: f2b08000 movk x0, #0x8400, lsl #16 0x0000000080000014: d4000002 hvc #0x0 Linking TBs 0x7f38787cb0d0 [0000000080000004] index 0 -> 0x7f38787cb1c0 [000000008000000c] Trace 0x7f38787cb1c0 [000000008000000c] Taking exception 11 [Hypervisor Call] ...from EL1 ...with ESR 0x5a000000 Thanks, Christopher Covington
Christopher Covington <cov@codeaurora.org> writes: > Hi Peter, Alex, > > On 08/03/2015 05:14 AM, Alex Bennée wrote: >> From: Peter Maydell <peter.maydell@linaro.org> >> <snip> > > Do you think there's some way to log the loop count when a circular chain is > executed? Possibly but I'm going to treat this as a future enhancement. -- Alex Bennée
diff --git a/cpu-exec.c b/cpu-exec.c index 75694f3..a039f1a 100644 --- a/cpu-exec.c +++ b/cpu-exec.c @@ -175,10 +175,14 @@ void cpu_reload_memory_map(CPUState *cpu) #endif /* 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)) { @@ -209,6 +213,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 { @@ -247,7 +255,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); @@ -356,7 +364,6 @@ int cpu_exec(CPUState *cpu) #endif int ret, interrupt_request; TranslationBlock *tb; - uint8_t *tc_ptr; uintptr_t next_tb; SyncClocks sc; @@ -491,10 +498,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. */ @@ -513,9 +516,8 @@ int cpu_exec(CPUState *cpu) barrier(); if (likely(!cpu->exit_request)) { trace_exec_tb(tb, tb->pc); - tc_ptr = tb->tc_ptr; /* execute the generated code */ - next_tb = cpu_tb_exec(cpu, tc_ptr); + next_tb = cpu_tb_exec(cpu, tb); switch (next_tb & TB_EXIT_MASK) { case TB_EXIT_REQUESTED: /* Something asked us to stop executing diff --git a/include/exec/exec-all.h b/include/exec/exec-all.h index 7ac8e7e..361d3d2 100644 --- a/include/exec/exec-all.h +++ b/include/exec/exec-all.h @@ -282,6 +282,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);