From 3f5e36e15ff340036fc0fa3d93d8e94d9318b71a Mon Sep 17 00:00:00 2001 From: Peter Maydell Date: Thu, 22 Feb 2018 09:37:45 -0500 Subject: [PATCH] qemu-log: Improve the exec TB execution logging 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] Stopped execution of TB chain before 0x7fb7cc8235d0 [ffffffc0000dce70] Trace 0x7fb7cc8235d0 [ffffffc0000dce70] Trace 0x7fb7cc822fd0 [ffffffc0000dd52c] Backports commit 1a830635229e14c403600167823ea6b3b79d3097 from qemu --- qemu/cpu-exec.c | 18 +++++++++++++----- qemu/include/exec/exec-all.h | 3 +++ 2 files changed, 16 insertions(+), 5 deletions(-) diff --git a/qemu/cpu-exec.c b/qemu/cpu-exec.c index cf0a9fa1..b52fdcd2 100644 --- a/qemu/cpu-exec.c +++ b/qemu/cpu-exec.c @@ -27,7 +27,7 @@ #include "uc_priv.h" -static tcg_target_ulong cpu_tb_exec(CPUState *cpu, uint8_t *tb_ptr); +static tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb); static TranslationBlock *tb_find_slow(CPUState *cpu, target_ulong pc, target_ulong cs_base, uint64_t flags); static TranslationBlock *tb_find_fast(CPUState *cpu); @@ -45,7 +45,6 @@ int cpu_exec(struct uc_struct *uc, CPUState *cpu) #endif int ret, interrupt_request; TranslationBlock *tb; - uint8_t *tc_ptr; uintptr_t next_tb; struct hook *hook; @@ -209,10 +208,9 @@ int cpu_exec(struct uc_struct *uc, CPUState *cpu) } if (likely(!cpu->exit_request)) { - tc_ptr = tb->tc_ptr; cpu->current_tb = tb; /* execute the generated code */ - next_tb = cpu_tb_exec(cpu, tc_ptr); // UNICORN + next_tb = cpu_tb_exec(cpu, tb); cpu->current_tb = NULL; switch (next_tb & TB_EXIT_MASK) { @@ -278,11 +276,16 @@ int cpu_exec(struct uc_struct *uc, CPUState *cpu) } /* Execute a TB, and fix up the CPU state afterwards if necessary */ -static 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; TCGContext *tcg_ctx = env->uc->tcg_ctx; uintptr_t next_tb; + uint8_t *tb_ptr = itb->tc_ptr; + + // Unicorn: commented out + //qemu_log_mask(CPU_LOG_EXEC, "Trace %p [" TARGET_FMT_lx "] %s\n", + // itb->tc_ptr, itb->pc, lookup_symbol(itb->pc)); next_tb = tcg_qemu_tb_exec(env, tb_ptr); @@ -293,6 +296,11 @@ static tcg_target_ulong cpu_tb_exec(CPUState *cpu, uint8_t *tb_ptr) */ CPUClass *cc = CPU_GET_CLASS(env->uc, cpu); TranslationBlock *tb = (TranslationBlock *)(next_tb & ~TB_EXIT_MASK); + // Unicorn: commented out + //qemu_log_mask(CPU_LOG_EXEC, + // "Stopped 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) { // avoid sync twice when helper_uc_tracecode() already did this. if (env->uc->emu_counter <= env->uc->emu_count && diff --git a/qemu/include/exec/exec-all.h b/qemu/include/exec/exec-all.h index e22be9e0..d6456202 100644 --- a/qemu/include/exec/exec-all.h +++ b/qemu/include/exec/exec-all.h @@ -373,6 +373,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);