[Qemu-devel] [PATCH v4 00/11] qemu-log, perfmap and other logging tweaks

[Qemu-devel] [PATCH v4 00/11] qemu-log, perfmap and other logging tweaks

[Alex Bennée]

Hi,

This is mostly just a re-base to keep current with master. I've added
a couple of outstanding s-o-b and r-b tags. There are also two new
patches in this series which seemed to be worth keeping together:

 - a simple patch to dump invocation info in the log
 - the cputlb logging clean-up posted as an RFC last month

Could folks interested in TCG stuff have a look over the light
re-factor and perf map patches please?

It would be nice to get these in the next cycle but I'm unsure who's
tree I should be targeting? Most of the top level files touched
(cputlb, translate-all, qemu-log) just have the list marked as the
maintainer ;-)

Alex Bennée (9):
  tcg: add ability to dump /tmp/perf-<pid>.map files
  tcg: light re-factor and pass down TranslationBlock
  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, and op_opt
  target-arm: dfilter support for in_asm, op, opt_op
  vl.c: log system invocation when enabled
  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

 configure                  |  2 +-
 cpu-exec.c                 | 21 ++++++-----
 cputlb.c                   | 54 ++++++++++++++++++----------
 include/exec/exec-all.h    |  9 +++--
 include/qemu-common.h      |  2 ++
 include/qemu/log.h         | 28 +++++++++++++--
 qemu-log.c                 | 87 ++++++++++++++++++++++++++++++++++++++--------
 qemu-options.hx            | 25 +++++++++++++
 target-arm/translate-a64.c |  6 ++--
 target-arm/translate.c     |  6 ++--
 tcg/tcg.c                  | 28 +++++++++------
 tcg/tcg.h                  |  5 ++-
 translate-all.c            | 70 ++++++++++++++++++++++++-------------
 vl.c                       | 25 +++++++++++++
 14 files changed, 278 insertions(+), 90 deletions(-)

-- 
2.5.0

[Qemu-devel] [PATCH v4 01/11] tcg: add ability to dump /tmp/perf-<pid>.map files

[Alex Bennée]

This allows the perf tool to map samples to each individual translation
block. This could be expanded for user space but currently it gives
enough information to find any hotblocks by other means.

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

---

v2:
  - hoist up into translate-all.c
  - don't use pointless glib wrappers
  - use proper format types for portability
  - mark prologue/epilog area
  - rebase

v3:
  - fix bracket for perf-map
  - find an include for the tb_enable_perfmap() declaration
  - checkpatch clean-ups
---
 include/qemu-common.h |  2 ++
 qemu-options.hx       |  9 +++++++++
 translate-all.c       | 26 ++++++++++++++++++++++++++
 vl.c                  |  4 ++++
 4 files changed, 41 insertions(+)

diff --git a/include/qemu-common.h b/include/qemu-common.h
index fb3da6c..60b87d0 100644
--- a/include/qemu-common.h
+++ b/include/qemu-common.h
@@ -382,6 +382,8 @@ typedef struct PCIHostDeviceAddress {
 void tcg_exec_init(unsigned long tb_size);
 bool tcg_enabled(void);
 
+void tb_enable_perfmap(void);
+
 void cpu_exec_init_all(void);
 
 /* CPU save/load.  */
diff --git a/qemu-options.hx b/qemu-options.hx
index 77f5853..ae53346 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3572,6 +3572,15 @@ to the RNG daemon.
 
 ETEXI
 
+DEF("perfmap", 0, QEMU_OPTION_PERFMAP, \
+    "-perfmap        generate a /tmp/perf-${pid}.map file for perf\n",
+    QEMU_ARCH_ALL)
+STEXI
+@item -perfmap
+@findex -perfmap
+This will cause QEMU to generate a map file for Linux perf tools that will allow
+basic profiling information to be broken down into basic blocks.
+ETEXI
 
 HXCOMM This is the last statement. Insert new options before this line!
 STEXI
diff --git a/translate-all.c b/translate-all.c
index 60a3d8b..c05e2a5 100644
--- a/translate-all.c
+++ b/translate-all.c
@@ -27,6 +27,7 @@
 #include <stdio.h>
 #include <string.h>
 #include <inttypes.h>
+#include <glib.h>
 
 #include "config.h"
 
@@ -133,6 +134,24 @@ static void tb_link_page(TranslationBlock *tb, tb_page_addr_t phys_pc,
                          tb_page_addr_t phys_page2);
 static TranslationBlock *tb_find_pc(uintptr_t tc_ptr);
 
+static FILE *tb_perfmap;
+
+void tb_enable_perfmap(void)
+{
+    gchar *map_file = g_strdup_printf("/tmp/perf-%d.map", getpid());
+    tb_perfmap = fopen(map_file, "w");
+    g_free(map_file);
+}
+
+static void tb_write_perfmap(tcg_insn_unit *start, int size, target_ulong pc)
+{
+    if (tb_perfmap) {
+        fprintf(tb_perfmap,
+                "%"PRIxPTR" %x subject-"TARGET_FMT_lx"\n",
+                (uintptr_t) start, size, pc);
+    }
+}
+
 void cpu_gen_init(void)
 {
     tcg_context_init(&tcg_ctx); 
@@ -190,6 +209,7 @@ int cpu_gen_code(CPUArchState *env, TranslationBlock *tb, int *gen_code_size_ptr
     s->code_out_len += gen_code_size;
 #endif
 
+    tb_write_perfmap(gen_code_buf, gen_code_size, tb->pc);
 #ifdef DEBUG_DISAS
     if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM)) {
         qemu_log("OUT: [size=%d]\n", gen_code_size);
@@ -669,6 +689,12 @@ static inline void code_gen_alloc(size_t tb_size)
             tcg_ctx.code_gen_buffer_size - 1024;
     tcg_ctx.code_gen_buffer_size -= 1024;
 
+    if (tb_perfmap) {
+        fprintf(tb_perfmap,
+                "%"PRIxPTR" %x tcg-prologue-buffer\n",
+                (uintptr_t) tcg_ctx.code_gen_prologue, 1024);
+    }
+
     tcg_ctx.code_gen_buffer_max_size = tcg_ctx.code_gen_buffer_size -
         (TCG_MAX_OP_SIZE * OPC_BUF_SIZE);
     tcg_ctx.code_gen_max_blocks = tcg_ctx.code_gen_buffer_size /
diff --git a/vl.c b/vl.c
index 0adbbd6..1d2de4f 100644
--- a/vl.c
+++ b/vl.c
@@ -122,6 +122,7 @@ int main(int argc, char **argv)
 #include "qapi-event.h"
 #include "exec/semihost.h"
 #include "crypto/init.h"
+#include "qemu-common.h"
 
 #define MAX_VIRTIO_CONSOLES 1
 #define MAX_SCLP_CONSOLES 1
@@ -3348,6 +3349,9 @@ int main(int argc, char **argv, char **envp)
             case QEMU_OPTION_D:
                 log_file = optarg;
                 break;
+            case QEMU_OPTION_PERFMAP:
+                tb_enable_perfmap();
+                break;
             case QEMU_OPTION_s:
                 add_device_config(DEV_GDB, "tcp::" DEFAULT_GDBSTUB_PORT);
                 break;
-- 
2.5.0

[Qemu-devel] [PATCH v4 02/11] tcg: light re-factor and pass down TranslationBlock

[Alex Bennée]

My later debugging patches need access to the origin PC. At the same
time we have a slightly clumsy pass-by-reference access to the size of
the translated block again for debugging purposes.

To simplify the code I have expanded the TranslationBlock structure to
include a tc_size variable to compliment the tc_ptr (and the subject pc,
block size). This is set on code generation and then accessed directly
by all the people that need it.

I've also cleaned up some comments and removed un-used return variables.

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

---
v1
 - checkpatch fixes
---
 include/exec/exec-all.h |  4 ++--
 tcg/tcg.c               | 22 +++++++++++++---------
 tcg/tcg.h               |  5 ++---
 translate-all.c         | 43 ++++++++++++++++++-------------------------
 4 files changed, 35 insertions(+), 39 deletions(-)

diff --git a/include/exec/exec-all.h b/include/exec/exec-all.h
index a6fce04..7ac8e7e 100644
--- a/include/exec/exec-all.h
+++ b/include/exec/exec-all.h
@@ -78,8 +78,7 @@ void restore_state_to_opc(CPUArchState *env, struct TranslationBlock *tb,
                           int pc_pos);
 
 void cpu_gen_init(void);
-int cpu_gen_code(CPUArchState *env, struct TranslationBlock *tb,
-                 int *gen_code_size_ptr);
+void cpu_gen_code(CPUArchState *env, struct TranslationBlock *tb);
 bool cpu_restore_state(CPUState *cpu, uintptr_t searched_pc);
 void page_size_init(void);
 
@@ -153,6 +152,7 @@ struct TranslationBlock {
 #define CF_USE_ICOUNT  0x20000
 
     void *tc_ptr;    /* pointer to the translated code */
+    uint32_t tc_size;/* size of translated code */
     /* next matching tb for physical address. */
     struct TranslationBlock *phys_hash_next;
     /* first and second physical page containing code. The lower bit
diff --git a/tcg/tcg.c b/tcg/tcg.c
index 0892a9b..587bd89 100644
--- a/tcg/tcg.c
+++ b/tcg/tcg.c
@@ -2295,12 +2295,15 @@ void tcg_dump_op_count(FILE *f, fprintf_function cpu_fprintf)
 #endif
 
 
-static inline int tcg_gen_code_common(TCGContext *s,
-                                      tcg_insn_unit *gen_code_buf,
+static inline int tcg_gen_code_common(TCGContext *s, TranslationBlock *tb,
                                       long search_pc)
 {
     int oi, oi_next;
 
+    /* if we are coming via cpu_restore_state we already have a
+       generated block */
+     g_assert(tb->tc_size == 0 || search_pc > 0);
+
 #ifdef DEBUG_DISAS
     if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP))) {
         qemu_log("OP:\n");
@@ -2338,8 +2341,8 @@ static inline int tcg_gen_code_common(TCGContext *s,
 
     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);
 
@@ -2402,7 +2405,7 @@ static inline int tcg_gen_code_common(TCGContext *s,
     return -1;
 }
 
-int tcg_gen_code(TCGContext *s, tcg_insn_unit *gen_code_buf)
+void tcg_gen_code(TCGContext *s, TranslationBlock *tb)
 {
 #ifdef CONFIG_PROFILER
     {
@@ -2422,22 +2425,23 @@ int tcg_gen_code(TCGContext *s, tcg_insn_unit *gen_code_buf)
     }
 #endif
 
-    tcg_gen_code_common(s, gen_code_buf, -1);
+    tcg_gen_code_common(s, tb, -1);
 
     /* flush instruction cache */
     flush_icache_range((uintptr_t)s->code_buf, (uintptr_t)s->code_ptr);
 
-    return tcg_current_code_size(s);
+    tb->tc_size = tcg_current_code_size(s);
+    return;
 }
 
 /* Return the index of the micro operation such as the pc after is <
    offset bytes from the start of the TB.  The contents of gen_code_buf must
    not be changed, though writing the same values is ok.
    Return -1 if not found. */
-int tcg_gen_code_search_pc(TCGContext *s, tcg_insn_unit *gen_code_buf,
+int tcg_gen_code_search_pc(TCGContext *s, TranslationBlock *tb,
                            long offset)
 {
-    return tcg_gen_code_common(s, gen_code_buf, offset);
+    return tcg_gen_code_common(s, tb, offset);
 }
 
 #ifdef CONFIG_PROFILER
diff --git a/tcg/tcg.h b/tcg/tcg.h
index 231a781..e4f9f97 100644
--- a/tcg/tcg.h
+++ b/tcg/tcg.h
@@ -613,9 +613,8 @@ 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_search_pc(TCGContext *s, tcg_insn_unit *gen_code_buf,
-                           long offset);
+void tcg_gen_code(TCGContext *s, TranslationBlock *tb);
+int  tcg_gen_code_search_pc(TCGContext *s, TranslationBlock *tb, long offset);
 
 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 c05e2a5..e8072d8 100644
--- a/translate-all.c
+++ b/translate-all.c
@@ -157,17 +157,12 @@ void cpu_gen_init(void)
     tcg_context_init(&tcg_ctx); 
 }
 
-/* return non zero if the very first instruction is invalid so that
-   the virtual CPU can trigger an exception.
-
-   '*gen_code_size_ptr' contains the size of the generated code (host
-   code).
+/* code generation. On return tb->tc_size will reflect the size of
+ * generated code.
 */
-int cpu_gen_code(CPUArchState *env, TranslationBlock *tb, int *gen_code_size_ptr)
+void cpu_gen_code(CPUArchState *env, TranslationBlock *tb)
 {
     TCGContext *s = &tcg_ctx;
-    tcg_insn_unit *gen_code_buf;
-    int gen_code_size;
 #ifdef CONFIG_PROFILER
     int64_t ti;
 #endif
@@ -184,7 +179,6 @@ int cpu_gen_code(CPUArchState *env, TranslationBlock *tb, int *gen_code_size_ptr
     trace_translate_block(tb, tb->pc, tb->tc_ptr);
 
     /* generate machine code */
-    gen_code_buf = tb->tc_ptr;
     tb->tb_next_offset[0] = 0xffff;
     tb->tb_next_offset[1] = 0xffff;
     s->tb_next_offset = tb->tb_next_offset;
@@ -201,24 +195,23 @@ int cpu_gen_code(CPUArchState *env, TranslationBlock *tb, int *gen_code_size_ptr
     s->interm_time += profile_getclock() - ti;
     s->code_time -= profile_getclock();
 #endif
-    gen_code_size = tcg_gen_code(s, gen_code_buf);
-    *gen_code_size_ptr = gen_code_size;
+   tcg_gen_code(s, tb);
+
 #ifdef CONFIG_PROFILER
     s->code_time += profile_getclock();
     s->code_in_len += tb->size;
-    s->code_out_len += gen_code_size;
+    s->code_out_len += tb->tc_size;
 #endif
 
-    tb_write_perfmap(gen_code_buf, gen_code_size, tb->pc);
+    tb_write_perfmap(tb->tc_ptr, tb->tc_size, tb->pc);
 #ifdef DEBUG_DISAS
     if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM)) {
-        qemu_log("OUT: [size=%d]\n", gen_code_size);
-        log_disas(tb->tc_ptr, gen_code_size);
+        qemu_log("OUT: [size=%d]\n", tb->tc_size);
+        log_disas(tb->tc_ptr, tb->tc_size);
         qemu_log("\n");
         qemu_log_flush();
     }
 #endif
-    return 0;
 }
 
 /* The cpu state corresponding to 'searched_pc' is restored.
@@ -229,7 +222,6 @@ static int cpu_restore_state_from_tb(CPUState *cpu, TranslationBlock *tb,
     CPUArchState *env = cpu->env_ptr;
     TCGContext *s = &tcg_ctx;
     int j;
-    uintptr_t tc_ptr;
 #ifdef CONFIG_PROFILER
     int64_t ti;
 #endif
@@ -249,9 +241,9 @@ static int cpu_restore_state_from_tb(CPUState *cpu, TranslationBlock *tb,
     }
 
     /* find opc index corresponding to search_pc */
-    tc_ptr = (uintptr_t)tb->tc_ptr;
-    if (searched_pc < tc_ptr)
+    if (searched_pc < (uintptr_t) tb->tc_ptr) {
         return -1;
+    }
 
     s->tb_next_offset = tb->tb_next_offset;
 #ifdef USE_DIRECT_JUMP
@@ -261,8 +253,8 @@ static int cpu_restore_state_from_tb(CPUState *cpu, TranslationBlock *tb,
     s->tb_jmp_offset = NULL;
     s->tb_next = tb->tb_next;
 #endif
-    j = tcg_gen_code_search_pc(s, (tcg_insn_unit *)tc_ptr,
-                               searched_pc - tc_ptr);
+    j = tcg_gen_code_search_pc(s, tb,
+                               searched_pc - (uintptr_t) tb->tc_ptr);
     if (j < 0)
         return -1;
     /* now find start of instruction before */
@@ -1029,7 +1021,6 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
     TranslationBlock *tb;
     tb_page_addr_t phys_pc, phys_page2;
     target_ulong virt_page2;
-    int code_gen_size;
 
     phys_pc = get_page_addr_code(env, pc);
     if (use_icount) {
@@ -1045,12 +1036,14 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
         tcg_ctx.tb_ctx.tb_invalidated_flag = 1;
     }
     tb->tc_ptr = tcg_ctx.code_gen_ptr;
+    tb->tc_size = 0;
     tb->cs_base = cs_base;
     tb->flags = flags;
     tb->cflags = cflags;
-    cpu_gen_code(env, tb, &code_gen_size);
-    tcg_ctx.code_gen_ptr = (void *)(((uintptr_t)tcg_ctx.code_gen_ptr +
-            code_gen_size + CODE_GEN_ALIGN - 1) & ~(CODE_GEN_ALIGN - 1));
+    cpu_gen_code(env, tb);
+    tcg_ctx.code_gen_ptr = (void *) (
+        ((uintptr_t) tcg_ctx.code_gen_ptr + tb->tc_size + CODE_GEN_ALIGN - 1)
+        & ~(CODE_GEN_ALIGN - 1));
 
     /* check next page if needed */
     virt_page2 = (pc + tb->size - 1) & TARGET_PAGE_MASK;
-- 
2.5.0

[Qemu-devel] [PATCH v4 03/11] 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
---
 qemu-log.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/qemu-log.c b/qemu-log.c
index 13f3813..be8405e 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 each executed TB (lots of logs)" },
     { CPU_LOG_MMU, "mmu",
       "log MMU-related activities" },
     { CPU_LOG_PCALL, "pcall",
-- 
2.5.0

[Qemu-devel] [PATCH v4 04/11] 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 f880e66..b80f8f5 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -65,10 +65,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 be8405e..7036076 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.5.0

[Qemu-devel] [PATCH v4 05/11] 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]
---
 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);
 
-- 
2.5.0

[Qemu-devel] [PATCH v4 06/11] 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>
---
 qemu-log.c | 17 +++++++++++++++--
 1 file changed, 15 insertions(+), 2 deletions(-)

diff --git a/qemu-log.c b/qemu-log.c
index 7036076..77ed7bc 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.5.0

[Qemu-devel] [PATCH v4 07/11] 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
---
 include/qemu/log.h |  2 ++
 qemu-log.c         | 57 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 qemu-options.hx    | 16 +++++++++++++++
 vl.c               |  3 +++
 4 files changed, 78 insertions(+)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index b80f8f5..ade1f76 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -182,6 +182,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 77ed7bc..b3ebd3c 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,61 @@ 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 *delim = g_strrstr(r, "-");
+            if (!delim) {
+                delim = g_strrstr(r, "+");
+            }
+            if (delim) {
+                struct Range range;
+                range.begin = strtoul(r, NULL, 0);
+                switch (*delim) {
+                case '+':
+                    range.end = range.begin + strtoul(delim+1, NULL, 0);
+                    break;
+                case '-':
+                    range.end = strtoul(delim+1, NULL, 0);
+                    break;
+                default:
+                    g_assert_not_reached();
+                }
+                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 ae53346..90f0df9 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -2987,6 +2987,22 @@ 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{end} or @var{start}+@var{size} where @var{start}
+@var{end} and @var{size} are the addresses and sizes required. For example:
+@example
+    -dfilter 0x8000-0x9000,0xffffffc000080000+0x200
+@end example
+Will dump output for any code in the 0x1000 sized block starting at 0x8000 and
+the 0x200 sized block starting at 0xffffffc000080000.
+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 1d2de4f..05211cf 100644
--- a/vl.c
+++ b/vl.c
@@ -3349,6 +3349,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_PERFMAP:
                 tb_enable_perfmap();
                 break;
-- 
2.5.0

[Qemu-devel] [PATCH v4 08/11] qemu-log: dfilter-ise exec, out_asm, and op_opt

[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. I've not touched CPU_LOG_TB_OP as this is buried in each
individual target.

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

----

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
---
 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 a039f1a..d01d08e 100644
--- a/cpu-exec.c
+++ b/cpu-exec.c
@@ -181,8 +181,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)) {
@@ -213,10 +214,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 361d3d2..51276ab 100644
--- a/include/exec/exec-all.h
+++ b/include/exec/exec-all.h
@@ -282,9 +282,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 ade1f76..0b0eef5 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -77,6 +77,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 587bd89..ed42204 100644
--- a/tcg/tcg.c
+++ b/tcg/tcg.c
@@ -2305,7 +2305,8 @@ static inline int tcg_gen_code_common(TCGContext *s, TranslationBlock *tb,
      g_assert(tb->tc_size == 0 || search_pc > 0);
 
 #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");
@@ -2332,7 +2333,8 @@ static inline int tcg_gen_code_common(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 e8072d8..facd516 100644
--- a/translate-all.c
+++ b/translate-all.c
@@ -205,7 +205,8 @@ void cpu_gen_code(CPUArchState *env, TranslationBlock *tb)
 
     tb_write_perfmap(tb->tc_ptr, tb->tc_size, tb->pc);
 #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", tb->tc_size);
         log_disas(tb->tc_ptr, tb->tc_size);
         qemu_log("\n");
-- 
2.5.0

[Qemu-devel] [PATCH v4 09/11] target-arm: dfilter support for in_asm, op, opt_op

[Alex Bennée]

Each individual architecture needs to use the qemu_log_in_addr_range()
feature for enabling in_asm and marking blocks for op/opt_op output.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 target-arm/translate-a64.c | 6 ++++--
 target-arm/translate.c     | 6 ++++--
 2 files changed, 8 insertions(+), 4 deletions(-)

diff --git a/target-arm/translate-a64.c b/target-arm/translate-a64.c
index 689f2be..0b0f4ae 100644
--- a/target-arm/translate-a64.c
+++ b/target-arm/translate-a64.c
@@ -11026,7 +11026,8 @@ void gen_intermediate_code_internal_a64(ARMCPU *cpu,
             gen_io_start();
         }
 
-        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT))) {
+        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT) &&
+                     qemu_log_in_addr_range(dc->pc))) {
             tcg_gen_debug_insn_start(dc->pc);
         }
 
@@ -11131,7 +11132,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 69ac18c..c914be0 100644
--- a/target-arm/translate.c
+++ b/target-arm/translate.c
@@ -11316,7 +11316,8 @@ static inline void gen_intermediate_code_internal(ARMCPU *cpu,
         if (num_insns + 1 == max_insns && (tb->cflags & CF_LAST_IO))
             gen_io_start();
 
-        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT))) {
+        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT)) &&
+            qemu_log_in_addr_range(dc->pc)) {
             tcg_gen_debug_insn_start(dc->pc);
         }
 
@@ -11489,7 +11490,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.5.0

[Qemu-devel] [PATCH v4 10/11] vl.c: log system invocation when enabled

[Alex Bennée]

This makes it a little easier to remember how you generated that 100Mb
trace log you saved for a future date.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 configure |  2 +-
 vl.c      | 18 ++++++++++++++++++
 2 files changed, 19 insertions(+), 1 deletion(-)

diff --git a/configure b/configure
index 704b34c..9cc6a48 100755
--- a/configure
+++ b/configure
@@ -1445,7 +1445,7 @@ else
 fi
 
 gcc_flags="-Wold-style-declaration -Wold-style-definition -Wtype-limits"
-gcc_flags="-Wformat-security -Wformat-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
+gcc_flags="-Wformat-security -Wno-format-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
 gcc_flags="-Wmissing-include-dirs -Wempty-body -Wnested-externs $gcc_flags"
 gcc_flags="-Wendif-labels $gcc_flags"
 gcc_flags="-Wno-initializer-overrides $gcc_flags"
diff --git a/vl.c b/vl.c
index 05211cf..6f0ae74 100644
--- a/vl.c
+++ b/vl.c
@@ -4094,12 +4094,30 @@ int main(int argc, char **argv, char **envp)
 
     if (log_mask) {
         int mask;
+        char fmt_time[512];
+        time_t start_time = time(NULL);
+        struct tm *local_start = localtime(&start_time);
+
+
+        if (log_file) {
+            qemu_set_log_filename(log_file);
+        }
+
         mask = qemu_str_to_log_mask(log_mask);
         if (!mask) {
             qemu_print_log_usage(stdout);
             exit(1);
         }
         qemu_set_log(mask);
+
+        if (strftime(fmt_time, sizeof(fmt_time), "%c", local_start) > 0) {
+            qemu_log("System Emulation started at %s\n", fmt_time);
+            qemu_log("Invocation:");
+            for (i = 0; i < argc; i++) {
+                qemu_log("%s ", argv[i]);
+            }
+            qemu_log("\n");
+        }
     }
 
     if (!is_daemonized()) {
-- 
2.5.0

[Qemu-devel] [PATCH v4 11/11] 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.

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

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

---
v2
  - ensure the compiler checks format strings even if debug is optimised out
---
 cputlb.c | 54 +++++++++++++++++++++++++++++++++++-------------------
 1 file changed, 35 insertions(+), 19 deletions(-)

diff --git a/cputlb.c b/cputlb.c
index a506086..7095e6f 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;
@@ -87,16 +108,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;
     }
@@ -271,12 +290,9 @@ void tlb_set_page_with_attrs(CPUState *cpu, target_ulong vaddr,
     section = address_space_translate_for_iotlb(cpu, 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.5.0

Re: [Qemu-devel] [PATCH v4 01/11] tcg: add ability to dump /tmp/perf-<pid>.map files

[Paolo Bonzini]

On 03/08/2015 11:14, Alex Bennée wrote:
> This allows the perf tool to map samples to each individual translation
> block. This could be expanded for user space but currently it gives
> enough information to find any hotblocks by other means.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

What happens if you encounter a tb_flush?

Paolo

Re: [Qemu-devel] [PATCH v4 01/11] tcg: add ability to dump /tmp/perf-<pid>.map files

[Alex Bennée]

Paolo Bonzini <pbonzini@redhat.com> writes:

> On 03/08/2015 11:14, Alex Bennée wrote:
>> This allows the perf tool to map samples to each individual translation
>> block. This could be expanded for user space but currently it gives
>> enough information to find any hotblocks by other means.
>> 
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>
> What happens if you encounter a tb_flush?

At the point of a tb_flush all bets are off as we will re-generate all
the blocks at potentially different locations in the translation buffer.
However for most analysis cases you are unlikely to cause the code
buffer to overflow. Most other uses of tb_flush are the result
debugging.

I could add a printf when --perfmap is enabled to flag when a flush
happens to signal to the user? I guess some more caveats in the flag
description wouldn't hurt.

We could consider truncating and re-starting the JIT dump at each flush?


>
> Paolo

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH v4 01/11] tcg: add ability to dump /tmp/perf-<pid>.map files

[Paolo Bonzini]

On 04/08/2015 09:39, Alex Bennée wrote:
> At the point of a tb_flush all bets are off as we will re-generate all
> the blocks at potentially different locations in the translation buffer.
> However for most analysis cases you are unlikely to cause the code
> buffer to overflow. Most other uses of tb_flush are the result
> debugging.
> 
> I could add a printf when --perfmap is enabled to flag when a flush
> happens to signal to the user? I guess some more caveats in the flag
> description wouldn't hurt.
> 
> We could consider truncating and re-starting the JIT dump at each flush?

Yes, it makes sense to me.  printf + truncation would work.

Paolo

Re: [Qemu-devel] [PATCH v4 01/11] tcg: add ability to dump /tmp/perf-<pid>.map files

[Aurelien Jarno]

On 2015-08-04 08:39, Alex Bennée wrote:
> 
> Paolo Bonzini <pbonzini@redhat.com> writes:
> 
> > On 03/08/2015 11:14, Alex Bennée wrote:
> >> This allows the perf tool to map samples to each individual translation
> >> block. This could be expanded for user space but currently it gives
> >> enough information to find any hotblocks by other means.
> >> 
> >> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> >
> > What happens if you encounter a tb_flush?
> 
> At the point of a tb_flush all bets are off as we will re-generate all
> the blocks at potentially different locations in the translation buffer.
> However for most analysis cases you are unlikely to cause the code
> buffer to overflow. Most other uses of tb_flush are the result
> debugging.
> 
> I could add a printf when --perfmap is enabled to flag when a flush
> happens to signal to the user? I guess some more caveats in the flag
> description wouldn't hurt.
> 
> We could consider truncating and re-starting the JIT dump at each flush?

You also need to take care about TB invalidation. When the last
generated TB is invalidated, the code pointer is rolled back to the
end of the previous TB. In that case the last entry of the dump might
should be replaced by the new value. If the invalidated TB is not the
last one, it is just left in the generated code.

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 01/11] tcg: add ability to dump /tmp/perf-<pid>.map files

[Aurelien Jarno]

On 2015-08-03 10:14, Alex Bennée wrote:
> This allows the perf tool to map samples to each individual translation
> block. This could be expanded for user space but currently it gives
> enough information to find any hotblocks by other means.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> 
> ---
> 
> v2:
>   - hoist up into translate-all.c
>   - don't use pointless glib wrappers
>   - use proper format types for portability
>   - mark prologue/epilog area
>   - rebase
> 
> v3:
>   - fix bracket for perf-map
>   - find an include for the tb_enable_perfmap() declaration
>   - checkpatch clean-ups
> ---
>  include/qemu-common.h |  2 ++
>  qemu-options.hx       |  9 +++++++++
>  translate-all.c       | 26 ++++++++++++++++++++++++++
>  vl.c                  |  4 ++++
>  4 files changed, 41 insertions(+)
> 
> diff --git a/include/qemu-common.h b/include/qemu-common.h
> index fb3da6c..60b87d0 100644
> --- a/include/qemu-common.h
> +++ b/include/qemu-common.h
> @@ -382,6 +382,8 @@ typedef struct PCIHostDeviceAddress {
>  void tcg_exec_init(unsigned long tb_size);
>  bool tcg_enabled(void);
>  
> +void tb_enable_perfmap(void);
> +
>  void cpu_exec_init_all(void);
>  
>  /* CPU save/load.  */
> diff --git a/qemu-options.hx b/qemu-options.hx
> index 77f5853..ae53346 100644
> --- a/qemu-options.hx
> +++ b/qemu-options.hx
> @@ -3572,6 +3572,15 @@ to the RNG daemon.
>  
>  ETEXI
>  
> +DEF("perfmap", 0, QEMU_OPTION_PERFMAP, \
> +    "-perfmap        generate a /tmp/perf-${pid}.map file for perf\n",
> +    QEMU_ARCH_ALL)
> +STEXI
> +@item -perfmap
> +@findex -perfmap
> +This will cause QEMU to generate a map file for Linux perf tools that will allow
> +basic profiling information to be broken down into basic blocks.
> +ETEXI
>  
>  HXCOMM This is the last statement. Insert new options before this line!
>  STEXI
> diff --git a/translate-all.c b/translate-all.c
> index 60a3d8b..c05e2a5 100644
> --- a/translate-all.c
> +++ b/translate-all.c
> @@ -27,6 +27,7 @@
>  #include <stdio.h>
>  #include <string.h>
>  #include <inttypes.h>
> +#include <glib.h>
>  
>  #include "config.h"
>  
> @@ -133,6 +134,24 @@ static void tb_link_page(TranslationBlock *tb, tb_page_addr_t phys_pc,
>                           tb_page_addr_t phys_page2);
>  static TranslationBlock *tb_find_pc(uintptr_t tc_ptr);
>  
> +static FILE *tb_perfmap;
> +
> +void tb_enable_perfmap(void)
> +{
> +    gchar *map_file = g_strdup_printf("/tmp/perf-%d.map", getpid());
> +    tb_perfmap = fopen(map_file, "w");

What about symlink attacks there?

> +    g_free(map_file);
> +}
> +
> +static void tb_write_perfmap(tcg_insn_unit *start, int size, target_ulong pc)
> +{
> +    if (tb_perfmap) {
> +        fprintf(tb_perfmap,
> +                "%"PRIxPTR" %x subject-"TARGET_FMT_lx"\n",
> +                (uintptr_t) start, size, pc);
> +    }
> +}
> +
>  void cpu_gen_init(void)
>  {
>      tcg_context_init(&tcg_ctx); 
> @@ -190,6 +209,7 @@ int cpu_gen_code(CPUArchState *env, TranslationBlock *tb, int *gen_code_size_ptr
>      s->code_out_len += gen_code_size;
>  #endif
>  
> +    tb_write_perfmap(gen_code_buf, gen_code_size, tb->pc);
>  #ifdef DEBUG_DISAS
>      if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM)) {
>          qemu_log("OUT: [size=%d]\n", gen_code_size);
> @@ -669,6 +689,12 @@ static inline void code_gen_alloc(size_t tb_size)
>              tcg_ctx.code_gen_buffer_size - 1024;
>      tcg_ctx.code_gen_buffer_size -= 1024;
>  
> +    if (tb_perfmap) {
> +        fprintf(tb_perfmap,
> +                "%"PRIxPTR" %x tcg-prologue-buffer\n",
> +                (uintptr_t) tcg_ctx.code_gen_prologue, 1024);
> +    }
> +
>      tcg_ctx.code_gen_buffer_max_size = tcg_ctx.code_gen_buffer_size -
>          (TCG_MAX_OP_SIZE * OPC_BUF_SIZE);
>      tcg_ctx.code_gen_max_blocks = tcg_ctx.code_gen_buffer_size /
> diff --git a/vl.c b/vl.c
> index 0adbbd6..1d2de4f 100644
> --- a/vl.c
> +++ b/vl.c
> @@ -122,6 +122,7 @@ int main(int argc, char **argv)
>  #include "qapi-event.h"
>  #include "exec/semihost.h"
>  #include "crypto/init.h"
> +#include "qemu-common.h"
>  
>  #define MAX_VIRTIO_CONSOLES 1
>  #define MAX_SCLP_CONSOLES 1
> @@ -3348,6 +3349,9 @@ int main(int argc, char **argv, char **envp)
>              case QEMU_OPTION_D:
>                  log_file = optarg;
>                  break;
> +            case QEMU_OPTION_PERFMAP:
> +                tb_enable_perfmap();
> +                break;
>              case QEMU_OPTION_s:
>                  add_device_config(DEV_GDB, "tcp::" DEFAULT_GDBSTUB_PORT);
>                  break;
> -- 
> 2.5.0
> 
> 

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Aurelien Jarno]

On 2015-08-03 10:14, 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>
> 
> ---
> v4
>   - add r-b tag
> ---
>  qemu-log.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/qemu-log.c b/qemu-log.c
> index 13f3813..be8405e 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 each executed TB (lots of logs)" },
>      { CPU_LOG_MMU, "mmu",
>        "log MMU-related activities" },
>      { CPU_LOG_PCALL, "pcall",

In practice this is not true for linked TB. Should we also disable TB
linking when this option is enabled?

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 04/11] qemu-log: Avoid function call for disabled qemu_log_mask logging

[Aurelien Jarno]

On 2015-08-03 10:14, Alex Bennée wrote:
> 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 f880e66..b80f8f5 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -65,10 +65,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 be8405e..7036076 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)
>  {

Good idea.

Reviewed-by: Aurelien Jarno <aurelien@aurel32.net>


-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 05/11] qemu-log: Improve the "exec" TB execution logging

[Aurelien Jarno]

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>

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 06/11] qemu-log: support simple pid substitution in logfile

[Aurelien Jarno]

On 2015-08-03 10:14, Alex Bennée wrote:
> 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>
> ---
>  qemu-log.c | 17 +++++++++++++++--
>  1 file changed, 15 insertions(+), 2 deletions(-)
> 
> diff --git a/qemu-log.c b/qemu-log.c
> index 7036076..77ed7bc 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);
>  }

Reviewed-by: Aurelien Jarno <aurelien@aurel32.net>


-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 07/11] qemu-log: new option -dfilter to limit output

[Aurelien Jarno]

On 2015-08-03 10:14, Alex Bennée wrote:
> 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
> ---
>  include/qemu/log.h |  2 ++
>  qemu-log.c         | 57 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
>  qemu-options.hx    | 16 +++++++++++++++
>  vl.c               |  3 +++
>  4 files changed, 78 insertions(+)
> 
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index b80f8f5..ade1f76 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -182,6 +182,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 77ed7bc..b3ebd3c 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,61 @@ 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 *delim = g_strrstr(r, "-");
> +            if (!delim) {
> +                delim = g_strrstr(r, "+");
> +            }
> +            if (delim) {
> +                struct Range range;
> +                range.begin = strtoul(r, NULL, 0);
> +                switch (*delim) {
> +                case '+':
> +                    range.end = range.begin + strtoul(delim+1, NULL, 0);
> +                    break;
> +                case '-':
> +                    range.end = strtoul(delim+1, NULL, 0);
> +                    break;
> +                default:
> +                    g_assert_not_reached();
> +                }
> +                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 ae53346..90f0df9 100644
> --- a/qemu-options.hx
> +++ b/qemu-options.hx
> @@ -2987,6 +2987,22 @@ 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{end} or @var{start}+@var{size} where @var{start}
> +@var{end} and @var{size} are the addresses and sizes required. For example:
> +@example
> +    -dfilter 0x8000-0x9000,0xffffffc000080000+0x200
> +@end example
> +Will dump output for any code in the 0x1000 sized block starting at 0x8000 and
> +the 0x200 sized block starting at 0xffffffc000080000.
> +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 1d2de4f..05211cf 100644
> --- a/vl.c
> +++ b/vl.c
> @@ -3349,6 +3349,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_PERFMAP:
>                  tb_enable_perfmap();
>                  break;

I do wonder if it should just be a suboption of -d, like for example:
qemu-system-i386 -d cpu,exec,dfilter=0x8000-0x9000

Otherwise:

Reviewed-by: Aurelien Jarno <aurelien@aurel32.net>

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 08/11] qemu-log: dfilter-ise exec, out_asm, and op_opt

[Aurelien Jarno]

On 2015-08-03 10:14, 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. I've not touched CPU_LOG_TB_OP as this is buried in each
> individual target.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> 
> ----
> 
> 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
> ---
>  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 a039f1a..d01d08e 100644
> --- a/cpu-exec.c
> +++ b/cpu-exec.c
> @@ -181,8 +181,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)) {
> @@ -213,10 +214,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 361d3d2..51276ab 100644
> --- a/include/exec/exec-all.h
> +++ b/include/exec/exec-all.h
> @@ -282,9 +282,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 ade1f76..0b0eef5 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -77,6 +77,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 587bd89..ed42204 100644
> --- a/tcg/tcg.c
> +++ b/tcg/tcg.c
> @@ -2305,7 +2305,8 @@ static inline int tcg_gen_code_common(TCGContext *s, TranslationBlock *tb,
>       g_assert(tb->tc_size == 0 || search_pc > 0);
>  
>  #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");
> @@ -2332,7 +2333,8 @@ static inline int tcg_gen_code_common(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 e8072d8..facd516 100644
> --- a/translate-all.c
> +++ b/translate-all.c
> @@ -205,7 +205,8 @@ void cpu_gen_code(CPUArchState *env, TranslationBlock *tb)
>  
>      tb_write_perfmap(tb->tc_ptr, tb->tc_size, tb->pc);
>  #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", tb->tc_size);
>          log_disas(tb->tc_ptr, tb->tc_size);
>          qemu_log("\n");
> -- 
> 2.5.0

Reviewed-by: Aurelien Jarno <aurelien@aureL32.net>

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 09/11] target-arm: dfilter support for in_asm, op, opt_op

[Aurelien Jarno]

On 2015-08-03 10:14, Alex Bennée wrote:
> Each individual architecture needs to use the qemu_log_in_addr_range()
> feature for enabling in_asm and marking blocks for op/opt_op output.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  target-arm/translate-a64.c | 6 ++++--
>  target-arm/translate.c     | 6 ++++--
>  2 files changed, 8 insertions(+), 4 deletions(-)
> 
> diff --git a/target-arm/translate-a64.c b/target-arm/translate-a64.c
> index 689f2be..0b0f4ae 100644
> --- a/target-arm/translate-a64.c
> +++ b/target-arm/translate-a64.c
> @@ -11026,7 +11026,8 @@ void gen_intermediate_code_internal_a64(ARMCPU *cpu,
>              gen_io_start();
>          }
>  
> -        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT))) {
> +        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT) &&
> +                     qemu_log_in_addr_range(dc->pc))) {
>              tcg_gen_debug_insn_start(dc->pc);
>          }
>  
> @@ -11131,7 +11132,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 69ac18c..c914be0 100644
> --- a/target-arm/translate.c
> +++ b/target-arm/translate.c
> @@ -11316,7 +11316,8 @@ static inline void gen_intermediate_code_internal(ARMCPU *cpu,
>          if (num_insns + 1 == max_insns && (tb->cflags & CF_LAST_IO))
>              gen_io_start();
>  
> -        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT))) {
> +        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT)) &&
> +            qemu_log_in_addr_range(dc->pc)) {
>              tcg_gen_debug_insn_start(dc->pc);
>          }
>  
> @@ -11489,7 +11490,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,

We probably want to do the same for the other architectures.

Reviewed-by: Aurelien Jarno <aurelien@aurel32.net>

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 10/11] vl.c: log system invocation when enabled

[Aurelien Jarno]

On 2015-08-03 10:14, Alex Bennée wrote:
> This makes it a little easier to remember how you generated that 100Mb
> trace log you saved for a future date.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  configure |  2 +-
>  vl.c      | 18 ++++++++++++++++++
>  2 files changed, 19 insertions(+), 1 deletion(-)
> 
> diff --git a/configure b/configure
> index 704b34c..9cc6a48 100755
> --- a/configure
> +++ b/configure
> @@ -1445,7 +1445,7 @@ else
>  fi
>  
>  gcc_flags="-Wold-style-declaration -Wold-style-definition -Wtype-limits"
> -gcc_flags="-Wformat-security -Wformat-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
> +gcc_flags="-Wformat-security -Wno-format-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
>  gcc_flags="-Wmissing-include-dirs -Wempty-body -Wnested-externs $gcc_flags"
>  gcc_flags="-Wendif-labels $gcc_flags"
>  gcc_flags="-Wno-initializer-overrides $gcc_flags"
> diff --git a/vl.c b/vl.c
> index 05211cf..6f0ae74 100644
> --- a/vl.c
> +++ b/vl.c
> @@ -4094,12 +4094,30 @@ int main(int argc, char **argv, char **envp)
>  
>      if (log_mask) {
>          int mask;
> +        char fmt_time[512];
> +        time_t start_time = time(NULL);
> +        struct tm *local_start = localtime(&start_time);
> +
> +
> +        if (log_file) {
> +            qemu_set_log_filename(log_file);
> +        }
> +
>          mask = qemu_str_to_log_mask(log_mask);
>          if (!mask) {
>              qemu_print_log_usage(stdout);
>              exit(1);
>          }
>          qemu_set_log(mask);
> +
> +        if (strftime(fmt_time, sizeof(fmt_time), "%c", local_start) > 0) {

Given we don't allow translation in qemu_log, shouldn't we just use a
fixed date/time format? It looks like other parts of QEMU has more or
less standardized to %Y-%m-%d %H:%M:%S, with some changes at the
separator level.

> +            qemu_log("System Emulation started at %s\n", fmt_time);
> +            qemu_log("Invocation:");
> +            for (i = 0; i < argc; i++) {
> +                qemu_log("%s ", argv[i]);
> +            }
> +            qemu_log("\n");
> +        }
>      }
>  
>      if (!is_daemonized()) {

Otherwise:

Reviewed-by: Aurelien Jarno <aurelien@aurel32.net>


-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 11/11] cputlb: modernise the debug support

[Aurelien Jarno]

On 2015-08-03 10:14, 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.
> 
> I've also removed DEBUG_TLB_CHECK which wasn't used.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> 
> ---
> v2
>   - ensure the compiler checks format strings even if debug is optimised out
> ---
>  cputlb.c | 54 +++++++++++++++++++++++++++++++++++-------------------
>  1 file changed, 35 insertions(+), 19 deletions(-)
> 
> diff --git a/cputlb.c b/cputlb.c
> index a506086..7095e6f 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)

Do we really want to support sending debug logs to either the logfile or
stderr? It's already possible to send the debug logs through stderr when
not specifying -D file.

>  /* 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;
> @@ -87,16 +108,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;
>      }
> @@ -271,12 +290,9 @@ void tlb_set_page_with_attrs(CPUState *cpu, target_ulong vaddr,
>      section = address_space_translate_for_iotlb(cpu, 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.5.0
> 
> 

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 02/11] tcg: light re-factor and pass down TranslationBlock

[Aurelien Jarno]

On 2015-08-03 10:14, Alex Bennée wrote:
> My later debugging patches need access to the origin PC. At the same
> time we have a slightly clumsy pass-by-reference access to the size of
> the translated block again for debugging purposes.
> 
> To simplify the code I have expanded the TranslationBlock structure to
> include a tc_size variable to compliment the tc_ptr (and the subject pc,
> block size). This is set on code generation and then accessed directly
> by all the people that need it.
> 
> I've also cleaned up some comments and removed un-used return variables.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> 
> ---
> v1
>  - checkpatch fixes
> ---
>  include/exec/exec-all.h |  4 ++--
>  tcg/tcg.c               | 22 +++++++++++++---------
>  tcg/tcg.h               |  5 ++---
>  translate-all.c         | 43 ++++++++++++++++++-------------------------
>  4 files changed, 35 insertions(+), 39 deletions(-)
> 
> diff --git a/include/exec/exec-all.h b/include/exec/exec-all.h
> index a6fce04..7ac8e7e 100644
> --- a/include/exec/exec-all.h
> +++ b/include/exec/exec-all.h
> @@ -78,8 +78,7 @@ void restore_state_to_opc(CPUArchState *env, struct TranslationBlock *tb,
>                            int pc_pos);
>  
>  void cpu_gen_init(void);
> -int cpu_gen_code(CPUArchState *env, struct TranslationBlock *tb,
> -                 int *gen_code_size_ptr);
> +void cpu_gen_code(CPUArchState *env, struct TranslationBlock *tb);
>  bool cpu_restore_state(CPUState *cpu, uintptr_t searched_pc);
>  void page_size_init(void);
>  
> @@ -153,6 +152,7 @@ struct TranslationBlock {
>  #define CF_USE_ICOUNT  0x20000
>  
>      void *tc_ptr;    /* pointer to the translated code */
> +    uint32_t tc_size;/* size of translated code */
>      /* next matching tb for physical address. */
>      struct TranslationBlock *phys_hash_next;
>      /* first and second physical page containing code. The lower bit

What's the impact on the memory here? Given the alignement, we add 8
bytes to the structure on a 64-bit host.

> diff --git a/tcg/tcg.c b/tcg/tcg.c
> index 0892a9b..587bd89 100644
> --- a/tcg/tcg.c
> +++ b/tcg/tcg.c
> @@ -2295,12 +2295,15 @@ void tcg_dump_op_count(FILE *f, fprintf_function cpu_fprintf)
>  #endif
>  
>  
> -static inline int tcg_gen_code_common(TCGContext *s,
> -                                      tcg_insn_unit *gen_code_buf,
> +static inline int tcg_gen_code_common(TCGContext *s, TranslationBlock *tb,
>                                        long search_pc)
>  {
>      int oi, oi_next;
>  
> +    /* if we are coming via cpu_restore_state we already have a
> +       generated block */
> +     g_assert(tb->tc_size == 0 || search_pc > 0);

In TCG code, you should use tcg_debug_assert.

> +
>  #ifdef DEBUG_DISAS
>      if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP))) {
>          qemu_log("OP:\n");
> @@ -2338,8 +2341,8 @@ static inline int tcg_gen_code_common(TCGContext *s,
>  
>      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);
>  
> @@ -2402,7 +2405,7 @@ static inline int tcg_gen_code_common(TCGContext *s,
>      return -1;
>  }
>  
> -int tcg_gen_code(TCGContext *s, tcg_insn_unit *gen_code_buf)
> +void tcg_gen_code(TCGContext *s, TranslationBlock *tb)
>  {
>  #ifdef CONFIG_PROFILER
>      {
> @@ -2422,22 +2425,23 @@ int tcg_gen_code(TCGContext *s, tcg_insn_unit *gen_code_buf)
>      }
>  #endif
>  
> -    tcg_gen_code_common(s, gen_code_buf, -1);
> +    tcg_gen_code_common(s, tb, -1);
>  
>      /* flush instruction cache */
>      flush_icache_range((uintptr_t)s->code_buf, (uintptr_t)s->code_ptr);
>  
> -    return tcg_current_code_size(s);
> +    tb->tc_size = tcg_current_code_size(s);
> +    return;
>  }
>  
>  /* Return the index of the micro operation such as the pc after is <
>     offset bytes from the start of the TB.  The contents of gen_code_buf must
>     not be changed, though writing the same values is ok.
>     Return -1 if not found. */
> -int tcg_gen_code_search_pc(TCGContext *s, tcg_insn_unit *gen_code_buf,
> +int tcg_gen_code_search_pc(TCGContext *s, TranslationBlock *tb,
>                             long offset)
>  {
> -    return tcg_gen_code_common(s, gen_code_buf, offset);
> +    return tcg_gen_code_common(s, tb, offset);
>  }
>  
>  #ifdef CONFIG_PROFILER
> diff --git a/tcg/tcg.h b/tcg/tcg.h
> index 231a781..e4f9f97 100644
> --- a/tcg/tcg.h
> +++ b/tcg/tcg.h
> @@ -613,9 +613,8 @@ 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_search_pc(TCGContext *s, tcg_insn_unit *gen_code_buf,
> -                           long offset);
> +void tcg_gen_code(TCGContext *s, TranslationBlock *tb);
> +int  tcg_gen_code_search_pc(TCGContext *s, TranslationBlock *tb, long offset);
>  
>  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 c05e2a5..e8072d8 100644
> --- a/translate-all.c
> +++ b/translate-all.c
> @@ -157,17 +157,12 @@ void cpu_gen_init(void)
>      tcg_context_init(&tcg_ctx); 
>  }
>  
> -/* return non zero if the very first instruction is invalid so that
> -   the virtual CPU can trigger an exception.
> -
> -   '*gen_code_size_ptr' contains the size of the generated code (host
> -   code).
> +/* code generation. On return tb->tc_size will reflect the size of
> + * generated code.
>  */
> -int cpu_gen_code(CPUArchState *env, TranslationBlock *tb, int *gen_code_size_ptr)
> +void cpu_gen_code(CPUArchState *env, TranslationBlock *tb)
>  {
>      TCGContext *s = &tcg_ctx;
> -    tcg_insn_unit *gen_code_buf;
> -    int gen_code_size;
>  #ifdef CONFIG_PROFILER
>      int64_t ti;
>  #endif
> @@ -184,7 +179,6 @@ int cpu_gen_code(CPUArchState *env, TranslationBlock *tb, int *gen_code_size_ptr
>      trace_translate_block(tb, tb->pc, tb->tc_ptr);
>  
>      /* generate machine code */
> -    gen_code_buf = tb->tc_ptr;
>      tb->tb_next_offset[0] = 0xffff;
>      tb->tb_next_offset[1] = 0xffff;
>      s->tb_next_offset = tb->tb_next_offset;
> @@ -201,24 +195,23 @@ int cpu_gen_code(CPUArchState *env, TranslationBlock *tb, int *gen_code_size_ptr
>      s->interm_time += profile_getclock() - ti;
>      s->code_time -= profile_getclock();
>  #endif
> -    gen_code_size = tcg_gen_code(s, gen_code_buf);
> -    *gen_code_size_ptr = gen_code_size;
> +   tcg_gen_code(s, tb);

Watch the indentation here.

> +
>  #ifdef CONFIG_PROFILER
>      s->code_time += profile_getclock();
>      s->code_in_len += tb->size;
> -    s->code_out_len += gen_code_size;
> +    s->code_out_len += tb->tc_size;
>  #endif
>  
> -    tb_write_perfmap(gen_code_buf, gen_code_size, tb->pc);
> +    tb_write_perfmap(tb->tc_ptr, tb->tc_size, tb->pc);
>  #ifdef DEBUG_DISAS
>      if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM)) {
> -        qemu_log("OUT: [size=%d]\n", gen_code_size);
> -        log_disas(tb->tc_ptr, gen_code_size);
> +        qemu_log("OUT: [size=%d]\n", tb->tc_size);
> +        log_disas(tb->tc_ptr, tb->tc_size);
>          qemu_log("\n");
>          qemu_log_flush();
>      }
>  #endif
> -    return 0;
>  }
>  
>  /* The cpu state corresponding to 'searched_pc' is restored.
> @@ -229,7 +222,6 @@ static int cpu_restore_state_from_tb(CPUState *cpu, TranslationBlock *tb,
>      CPUArchState *env = cpu->env_ptr;
>      TCGContext *s = &tcg_ctx;
>      int j;
> -    uintptr_t tc_ptr;
>  #ifdef CONFIG_PROFILER
>      int64_t ti;
>  #endif
> @@ -249,9 +241,9 @@ static int cpu_restore_state_from_tb(CPUState *cpu, TranslationBlock *tb,
>      }
>  
>      /* find opc index corresponding to search_pc */
> -    tc_ptr = (uintptr_t)tb->tc_ptr;
> -    if (searched_pc < tc_ptr)
> +    if (searched_pc < (uintptr_t) tb->tc_ptr) {
>          return -1;
> +    }
>  
>      s->tb_next_offset = tb->tb_next_offset;
>  #ifdef USE_DIRECT_JUMP
> @@ -261,8 +253,8 @@ static int cpu_restore_state_from_tb(CPUState *cpu, TranslationBlock *tb,
>      s->tb_jmp_offset = NULL;
>      s->tb_next = tb->tb_next;
>  #endif
> -    j = tcg_gen_code_search_pc(s, (tcg_insn_unit *)tc_ptr,
> -                               searched_pc - tc_ptr);
> +    j = tcg_gen_code_search_pc(s, tb,
> +                               searched_pc - (uintptr_t) tb->tc_ptr);
>      if (j < 0)
>          return -1;
>      /* now find start of instruction before */
> @@ -1029,7 +1021,6 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>      TranslationBlock *tb;
>      tb_page_addr_t phys_pc, phys_page2;
>      target_ulong virt_page2;
> -    int code_gen_size;
>  
>      phys_pc = get_page_addr_code(env, pc);
>      if (use_icount) {
> @@ -1045,12 +1036,14 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
>          tcg_ctx.tb_ctx.tb_invalidated_flag = 1;
>      }
>      tb->tc_ptr = tcg_ctx.code_gen_ptr;
> +    tb->tc_size = 0;
>      tb->cs_base = cs_base;
>      tb->flags = flags;
>      tb->cflags = cflags;
> -    cpu_gen_code(env, tb, &code_gen_size);
> -    tcg_ctx.code_gen_ptr = (void *)(((uintptr_t)tcg_ctx.code_gen_ptr +
> -            code_gen_size + CODE_GEN_ALIGN - 1) & ~(CODE_GEN_ALIGN - 1));
> +    cpu_gen_code(env, tb);
> +    tcg_ctx.code_gen_ptr = (void *) (
> +        ((uintptr_t) tcg_ctx.code_gen_ptr + tb->tc_size + CODE_GEN_ALIGN - 1)
> +        & ~(CODE_GEN_ALIGN - 1));
>  
>      /* check next page if needed */
>      virt_page2 = (pc + tb->size - 1) & TARGET_PAGE_MASK;
> -- 
> 2.5.0
> 
> 

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 10/11] vl.c: log system invocation when enabled

[Peter Maydell]

On 3 August 2015 at 10:14, Alex Bennée <alex.bennee@linaro.org> wrote:
> This makes it a little easier to remember how you generated that 100Mb
> trace log you saved for a future date.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  configure |  2 +-
>  vl.c      | 18 ++++++++++++++++++
>  2 files changed, 19 insertions(+), 1 deletion(-)
>
> diff --git a/configure b/configure
> index 704b34c..9cc6a48 100755
> --- a/configure
> +++ b/configure
> @@ -1445,7 +1445,7 @@ else
>  fi
>
>  gcc_flags="-Wold-style-declaration -Wold-style-definition -Wtype-limits"
> -gcc_flags="-Wformat-security -Wformat-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
> +gcc_flags="-Wformat-security -Wno-format-y2k -Winit-self -Wignored-qualifiers $gcc_flags"

Why do we need this warning switch change?

thanks
-- PMM

Re: [Qemu-devel] [PATCH v4 10/11] vl.c: log system invocation when enabled

[Aurelien Jarno]

On 2015-08-04 13:40, Peter Maydell wrote:
> On 3 August 2015 at 10:14, Alex Bennée <alex.bennee@linaro.org> wrote:
> > This makes it a little easier to remember how you generated that 100Mb
> > trace log you saved for a future date.
> >
> > Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> > ---
> >  configure |  2 +-
> >  vl.c      | 18 ++++++++++++++++++
> >  2 files changed, 19 insertions(+), 1 deletion(-)
> >
> > diff --git a/configure b/configure
> > index 704b34c..9cc6a48 100755
> > --- a/configure
> > +++ b/configure
> > @@ -1445,7 +1445,7 @@ else
> >  fi
> >
> >  gcc_flags="-Wold-style-declaration -Wold-style-definition -Wtype-limits"
> > -gcc_flags="-Wformat-security -Wformat-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
> > +gcc_flags="-Wformat-security -Wno-format-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
> 
> Why do we need this warning switch change?

Some locales might have the year on 2 digits only, so this triggers a
warning. That's also a reason I suggested to use a fixed date format.

-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 01/11] tcg: add ability to dump /tmp/perf-<pid>.map files

[Alex Bennée]

Aurelien Jarno <aurelien@aurel32.net> writes:

> On 2015-08-04 08:39, Alex Bennée wrote:
>> 
>> Paolo Bonzini <pbonzini@redhat.com> writes:
>> 
>> > On 03/08/2015 11:14, Alex Bennée wrote:
>> >> This allows the perf tool to map samples to each individual translation
>> >> block. This could be expanded for user space but currently it gives
>> >> enough information to find any hotblocks by other means.
>> >> 
>> >> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> >
>> > What happens if you encounter a tb_flush?
>> 
>> At the point of a tb_flush all bets are off as we will re-generate all
>> the blocks at potentially different locations in the translation buffer.
>> However for most analysis cases you are unlikely to cause the code
>> buffer to overflow. Most other uses of tb_flush are the result
>> debugging.
>> 
>> I could add a printf when --perfmap is enabled to flag when a flush
>> happens to signal to the user? I guess some more caveats in the flag
>> description wouldn't hurt.
>> 
>> We could consider truncating and re-starting the JIT dump at each flush?
>
> You also need to take care about TB invalidation. When the last
> generated TB is invalidated, the code pointer is rolled back to the
> end of the previous TB. In that case the last entry of the dump might
> should be replaced by the new value. If the invalidated TB is not the
> last one, it is just left in the generated code.

Can we only invalidate the previous TB and not any earlier ones?

We could keep the output line until the next TB is generated but then
you would never have a mapping for the last TB generated.

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH v4 10/11] vl.c: log system invocation when enabled

[Peter Maydell]

On 4 August 2015 at 13:46, Aurelien Jarno <aurelien@aurel32.net> wrote:
> On 2015-08-04 13:40, Peter Maydell wrote:
>> On 3 August 2015 at 10:14, Alex Bennée <alex.bennee@linaro.org> wrote:
>> >  gcc_flags="-Wold-style-declaration -Wold-style-definition -Wtype-limits"
>> > -gcc_flags="-Wformat-security -Wformat-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
>> > +gcc_flags="-Wformat-security -Wno-format-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
>>
>> Why do we need this warning switch change?
>
> Some locales might have the year on 2 digits only, so this triggers a
> warning. That's also a reason I suggested to use a fixed date format.

Agreed -- we don't want locale-specific log formats.

thanks
-- PMM

Re: [Qemu-devel] [PATCH v4 09/11] target-arm: dfilter support for in_asm, op, opt_op

[Richard Henderson]

On 08/03/2015 02:14 AM, Alex Bennée wrote:
> Each individual architecture needs to use the qemu_log_in_addr_range()
> feature for enabling in_asm and marking blocks for op/opt_op output.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  target-arm/translate-a64.c | 6 ++++--
>  target-arm/translate.c     | 6 ++++--
>  2 files changed, 8 insertions(+), 4 deletions(-)
> 
> diff --git a/target-arm/translate-a64.c b/target-arm/translate-a64.c
> index 689f2be..0b0f4ae 100644
> --- a/target-arm/translate-a64.c
> +++ b/target-arm/translate-a64.c
> @@ -11026,7 +11026,8 @@ void gen_intermediate_code_internal_a64(ARMCPU *cpu,
>              gen_io_start();
>          }
>  
> -        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT))) {
> +        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT) &&
> +                     qemu_log_in_addr_range(dc->pc))) {
>              tcg_gen_debug_insn_start(dc->pc);
>          }

If there's more than one or two ranges, it's probably quicker to
generate the debug opcode regardless of the range.  Remember, this
check is happening once per insn, not once per tb.


r~

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Alex Bennée]

Aurelien Jarno <aurelien@aurel32.net> writes:

> On 2015-08-03 10:14, 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>
>> 
>> ---
>> v4
>>   - add r-b tag
>> ---
>>  qemu-log.c | 2 +-
>>  1 file changed, 1 insertion(+), 1 deletion(-)
>> 
>> diff --git a/qemu-log.c b/qemu-log.c
>> index 13f3813..be8405e 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 each executed TB (lots of logs)" },
>>      { CPU_LOG_MMU, "mmu",
>>        "log MMU-related activities" },
>>      { CPU_LOG_PCALL, "pcall",
>
> In practice this is not true for linked TB. Should we also disable TB
> linking when this option is enabled?

Good question. I suspect yes because if you've gone to level of wanting
exec tracing you'll probably get confused by the chaining. Of course it
will run a lot slower then.


-- 
Alex Bennée

Re: [Qemu-devel] [PATCH v4 10/11] vl.c: log system invocation when enabled

[Alex Bennée]

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

> On 4 August 2015 at 13:46, Aurelien Jarno <aurelien@aurel32.net> wrote:
>> On 2015-08-04 13:40, Peter Maydell wrote:
>>> On 3 August 2015 at 10:14, Alex Bennée <alex.bennee@linaro.org> wrote:
>>> >  gcc_flags="-Wold-style-declaration -Wold-style-definition -Wtype-limits"
>>> > -gcc_flags="-Wformat-security -Wformat-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
>>> > +gcc_flags="-Wformat-security -Wno-format-y2k -Winit-self -Wignored-qualifiers $gcc_flags"
>>>
>>> Why do we need this warning switch change?
>>
>> Some locales might have the year on 2 digits only, so this triggers a
>> warning. That's also a reason I suggested to use a fixed date format.
>
> Agreed -- we don't want locale-specific log formats.

Is is worth pulling out the standard log date fmt into a #define somewhere?
>
> thanks
> -- PMM

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Peter Maydell]

On 4 August 2015 at 16:11, Alex Bennée <alex.bennee@linaro.org> wrote:
> Aurelien Jarno <aurelien@aurel32.net> writes:
>> On 2015-08-03 10:14, Alex Bennée wrote:
>> In practice this is not true for linked TB. Should we also disable TB
>> linking when this option is enabled?
>
> Good question. I suspect yes because if you've gone to level of wanting
> exec tracing you'll probably get confused by the chaining. Of course it
> will run a lot slower then.

Unless the bug you were trying to track down is caused by the exec
chaining, of course... But yes, I think we get more people wanting
chaining to be disableable.

Not sure we want to tie it to the 'cpu' debug option, though -- it
applies just as much to 'exec'.

-- PMM

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Richard Henderson]

On 08/04/2015 08:15 AM, Peter Maydell wrote:
> On 4 August 2015 at 16:11, Alex Bennée <alex.bennee@linaro.org> wrote:
>> Aurelien Jarno <aurelien@aurel32.net> writes:
>>> On 2015-08-03 10:14, Alex Bennée wrote:
>>> In practice this is not true for linked TB. Should we also disable TB
>>> linking when this option is enabled?
>>
>> Good question. I suspect yes because if you've gone to level of wanting
>> exec tracing you'll probably get confused by the chaining. Of course it
>> will run a lot slower then.
> 
> Unless the bug you were trying to track down is caused by the exec
> chaining, of course... But yes, I think we get more people wanting
> chaining to be disableable.
> 
> Not sure we want to tie it to the 'cpu' debug option, though -- it
> applies just as much to 'exec'.

Does it make more sense to have a 'nochain' debug option, and not tie it to
either 'cpu' or 'exec'?  It might be occasionally useful on its own, simply to
determine if a bug does exist in the exec chaining.


r~

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Alex Bennée]

Richard Henderson <rth@twiddle.net> writes:

> On 08/04/2015 08:15 AM, Peter Maydell wrote:
>> On 4 August 2015 at 16:11, Alex Bennée <alex.bennee@linaro.org> wrote:
>>> Aurelien Jarno <aurelien@aurel32.net> writes:
>>>> On 2015-08-03 10:14, Alex Bennée wrote:
>>>> In practice this is not true for linked TB. Should we also disable TB
>>>> linking when this option is enabled?
>>>
>>> Good question. I suspect yes because if you've gone to level of wanting
>>> exec tracing you'll probably get confused by the chaining. Of course it
>>> will run a lot slower then.
>> 
>> Unless the bug you were trying to track down is caused by the exec
>> chaining, of course... But yes, I think we get more people wanting
>> chaining to be disableable.
>> 
>> Not sure we want to tie it to the 'cpu' debug option, though -- it
>> applies just as much to 'exec'.
>
> Does it make more sense to have a 'nochain' debug option, and not tie it to
> either 'cpu' or 'exec'?  It might be occasionally useful on its own, simply to
> determine if a bug does exist in the exec chaining.

Would that make sense as a debug option or should we have a specific set
of TCG options to alter its behaviour?

>
>
> r~

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH v4 09/11] target-arm: dfilter support for in_asm, op, opt_op

[Alex Bennée]

Richard Henderson <rth@twiddle.net> writes:

> On 08/03/2015 02:14 AM, Alex Bennée wrote:
>> Each individual architecture needs to use the qemu_log_in_addr_range()
>> feature for enabling in_asm and marking blocks for op/opt_op output.
>> 
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> ---
>>  target-arm/translate-a64.c | 6 ++++--
>>  target-arm/translate.c     | 6 ++++--
>>  2 files changed, 8 insertions(+), 4 deletions(-)
>> 
>> diff --git a/target-arm/translate-a64.c b/target-arm/translate-a64.c
>> index 689f2be..0b0f4ae 100644
>> --- a/target-arm/translate-a64.c
>> +++ b/target-arm/translate-a64.c
>> @@ -11026,7 +11026,8 @@ void gen_intermediate_code_internal_a64(ARMCPU *cpu,
>>              gen_io_start();
>>          }
>>  
>> -        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT))) {
>> +        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT) &&
>> +                     qemu_log_in_addr_range(dc->pc))) {
>>              tcg_gen_debug_insn_start(dc->pc);
>>          }
>
> If there's more than one or two ranges, it's probably quicker to
> generate the debug opcode regardless of the range.  Remember, this
> check is happening once per insn, not once per tb.

Maybe I should hoist the check up to the start of a block? This would
mean we would dump all instructions in a block even if they went past
the end-point but the reverse case is probably just confusing.

We'll still not dump anything that starts outside the range.

>
>
> r~

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Richard Henderson]

On 08/04/2015 10:22 AM, Alex Bennée wrote:
> 
> Richard Henderson <rth@twiddle.net> writes:
> 
>> On 08/04/2015 08:15 AM, Peter Maydell wrote:
>>> On 4 August 2015 at 16:11, Alex Bennée <alex.bennee@linaro.org> wrote:
>>>> Aurelien Jarno <aurelien@aurel32.net> writes:
>>>>> On 2015-08-03 10:14, Alex Bennée wrote:
>>>>> In practice this is not true for linked TB. Should we also disable TB
>>>>> linking when this option is enabled?
>>>>
>>>> Good question. I suspect yes because if you've gone to level of wanting
>>>> exec tracing you'll probably get confused by the chaining. Of course it
>>>> will run a lot slower then.
>>>
>>> Unless the bug you were trying to track down is caused by the exec
>>> chaining, of course... But yes, I think we get more people wanting
>>> chaining to be disableable.
>>>
>>> Not sure we want to tie it to the 'cpu' debug option, though -- it
>>> applies just as much to 'exec'.
>>
>> Does it make more sense to have a 'nochain' debug option, and not tie it to
>> either 'cpu' or 'exec'?  It might be occasionally useful on its own, simply to
>> determine if a bug does exist in the exec chaining.
> 
> Would that make sense as a debug option or should we have a specific set
> of TCG options to alter its behaviour?


That's what I'm saying -- probably a separate debug option is better.


r~

Re: [Qemu-devel] [PATCH v4 09/11] target-arm: dfilter support for in_asm, op, opt_op

[Richard Henderson]

On 08/04/2015 10:26 AM, Alex Bennée wrote:
> 
> Richard Henderson <rth@twiddle.net> writes:
> 
>> On 08/03/2015 02:14 AM, Alex Bennée wrote:
>>> Each individual architecture needs to use the qemu_log_in_addr_range()
>>> feature for enabling in_asm and marking blocks for op/opt_op output.
>>>
>>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>>> ---
>>>  target-arm/translate-a64.c | 6 ++++--
>>>  target-arm/translate.c     | 6 ++++--
>>>  2 files changed, 8 insertions(+), 4 deletions(-)
>>>
>>> diff --git a/target-arm/translate-a64.c b/target-arm/translate-a64.c
>>> index 689f2be..0b0f4ae 100644
>>> --- a/target-arm/translate-a64.c
>>> +++ b/target-arm/translate-a64.c
>>> @@ -11026,7 +11026,8 @@ void gen_intermediate_code_internal_a64(ARMCPU *cpu,
>>>              gen_io_start();
>>>          }
>>>  
>>> -        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT))) {
>>> +        if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP | CPU_LOG_TB_OP_OPT) &&
>>> +                     qemu_log_in_addr_range(dc->pc))) {
>>>              tcg_gen_debug_insn_start(dc->pc);
>>>          }
>>
>> If there's more than one or two ranges, it's probably quicker to
>> generate the debug opcode regardless of the range.  Remember, this
>> check is happening once per insn, not once per tb.
> 
> Maybe I should hoist the check up to the start of a block? This would
> mean we would dump all instructions in a block even if they went past
> the end-point but the reverse case is probably just confusing.
> 
> We'll still not dump anything that starts outside the range.

Why hoist when the loglevel_mask check is so quick?
Processing of these debug opcodes is equally quick.

It's really only the dumping of the opcodes elsewhere
that needs to check the addr_range.


r~

Re: [Qemu-devel] [PATCH v4 01/11] tcg: add ability to dump /tmp/perf-<pid>.map files

[Aurelien Jarno]

On 2015-08-04 13:55, Alex Bennée wrote:
> 
> Aurelien Jarno <aurelien@aurel32.net> writes:
> 
> > On 2015-08-04 08:39, Alex Bennée wrote:
> >> 
> >> Paolo Bonzini <pbonzini@redhat.com> writes:
> >> 
> >> > On 03/08/2015 11:14, Alex Bennée wrote:
> >> >> This allows the perf tool to map samples to each individual translation
> >> >> block. This could be expanded for user space but currently it gives
> >> >> enough information to find any hotblocks by other means.
> >> >> 
> >> >> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> >> >
> >> > What happens if you encounter a tb_flush?
> >> 
> >> At the point of a tb_flush all bets are off as we will re-generate all
> >> the blocks at potentially different locations in the translation buffer.
> >> However for most analysis cases you are unlikely to cause the code
> >> buffer to overflow. Most other uses of tb_flush are the result
> >> debugging.
> >> 
> >> I could add a printf when --perfmap is enabled to flag when a flush
> >> happens to signal to the user? I guess some more caveats in the flag
> >> description wouldn't hurt.
> >> 
> >> We could consider truncating and re-starting the JIT dump at each flush?
> >
> > You also need to take care about TB invalidation. When the last
> > generated TB is invalidated, the code pointer is rolled back to the
> > end of the previous TB. In that case the last entry of the dump might
> > should be replaced by the new value. If the invalidated TB is not the
> > last one, it is just left in the generated code.
> 
> Can we only invalidate the previous TB and not any earlier ones?
> 
> We could keep the output line until the next TB is generated but then
> you would never have a mapping for the last TB generated.

I have just looked at the cde and it can (at least currently) happen only
when executing with nocache, so only in icount mode.

Aurelin


-- 
Aurelien Jarno                          GPG: 4096R/1DDD8C9B
aurelien@aurel32.net                 http://www.aurel32.net

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Alex Bennée]

Richard Henderson <rth@twiddle.net> writes:

> On 08/04/2015 10:22 AM, Alex Bennée wrote:
>> 
>> Richard Henderson <rth@twiddle.net> writes:
>> 
>>> On 08/04/2015 08:15 AM, Peter Maydell wrote:
>>>> On 4 August 2015 at 16:11, Alex Bennée <alex.bennee@linaro.org> wrote:
>>>>> Aurelien Jarno <aurelien@aurel32.net> writes:
>>>>>> On 2015-08-03 10:14, Alex Bennée wrote:
>>>>>> In practice this is not true for linked TB. Should we also disable TB
>>>>>> linking when this option is enabled?
>>>>>
>>>>> Good question. I suspect yes because if you've gone to level of wanting
>>>>> exec tracing you'll probably get confused by the chaining. Of course it
>>>>> will run a lot slower then.
>>>>
>>>> Unless the bug you were trying to track down is caused by the exec
>>>> chaining, of course... But yes, I think we get more people wanting
>>>> chaining to be disableable.
>>>>
>>>> Not sure we want to tie it to the 'cpu' debug option, though -- it
>>>> applies just as much to 'exec'.
>>>
>>> Does it make more sense to have a 'nochain' debug option, and not tie it to
>>> either 'cpu' or 'exec'?  It might be occasionally useful on its own, simply to
>>> determine if a bug does exist in the exec chaining.
>> 
>> Would that make sense as a debug option or should we have a specific set
>> of TCG options to alter its behaviour?
>
>
> That's what I'm saying -- probably a separate debug option is better.

Sorry I meant should we add it to -d (as in -d nochain) or have some tcg
opts (--tcg nochain,blah)

>
>
> r~

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Richard Henderson]

On 08/04/2015 12:08 PM, Alex Bennée wrote:
>>> Would that make sense as a debug option or should we have a specific set
>>> of TCG options to alter its behaviour?
>>
>>
>> That's what I'm saying -- probably a separate debug option is better.
> 
> Sorry I meant should we add it to -d (as in -d nochain) or have some tcg
> opts (--tcg nochain,blah)

I was suggesting the former: -d nochain.


r~

Re: [Qemu-devel] [PATCH v4 07/11] qemu-log: new option -dfilter to limit output

[Christopher Covington]

Hi Alex,

On 08/03/2015 05:14 AM, Alex Bennée wrote:
> 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>

My usual flow is to filter based on mode (CurrentEL on AArch64) and PID
(CONTEXTIDR on AArch64). Do you foresee any problems with adding such filters?

Thanks,
Christopher Covington

> v2
>   - More clean-ups to the documentation
> 
> v3
>   - re-base
>   - use GArray instead of GList to avoid cache bouncing
>   - checkpatch fixes
> ---
>  include/qemu/log.h |  2 ++
>  qemu-log.c         | 57 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
>  qemu-options.hx    | 16 +++++++++++++++
>  vl.c               |  3 +++
>  4 files changed, 78 insertions(+)
> 
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index b80f8f5..ade1f76 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -182,6 +182,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 77ed7bc..b3ebd3c 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,61 @@ 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 *delim = g_strrstr(r, "-");
> +            if (!delim) {
> +                delim = g_strrstr(r, "+");
> +            }
> +            if (delim) {
> +                struct Range range;
> +                range.begin = strtoul(r, NULL, 0);
> +                switch (*delim) {
> +                case '+':
> +                    range.end = range.begin + strtoul(delim+1, NULL, 0);
> +                    break;
> +                case '-':
> +                    range.end = strtoul(delim+1, NULL, 0);
> +                    break;
> +                default:
> +                    g_assert_not_reached();
> +                }
> +                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 ae53346..90f0df9 100644
> --- a/qemu-options.hx
> +++ b/qemu-options.hx
> @@ -2987,6 +2987,22 @@ 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{end} or @var{start}+@var{size} where @var{start}
> +@var{end} and @var{size} are the addresses and sizes required. For example:
> +@example
> +    -dfilter 0x8000-0x9000,0xffffffc000080000+0x200
> +@end example
> +Will dump output for any code in the 0x1000 sized block starting at 0x8000 and
> +the 0x200 sized block starting at 0xffffffc000080000.
> +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 1d2de4f..05211cf 100644
> --- a/vl.c
> +++ b/vl.c
> @@ -3349,6 +3349,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_PERFMAP:
>                  tb_enable_perfmap();
>                  break;
> 


-- 
Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [Qemu-devel] [PATCH v4 07/11] qemu-log: new option -dfilter to limit output

[Alex Bennée]

Christopher Covington <cov@codeaurora.org> writes:

> Hi Alex,
>
> On 08/03/2015 05:14 AM, Alex Bennée wrote:
>> 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>
>
> My usual flow is to filter based on mode (CurrentEL on AArch64) and PID
> (CONTEXTIDR on AArch64). Do you foresee any problems with adding such
> filters?

I have indeed added such filters on for my own debugging efforts.
However the problem is they are very target focused and I don't want to
pollute the generic code with target specific hacks. I suspect we need
two things:

  - a way to add target specific options to the UI
  - a target agnostic hook which allows additional refinement of the filter

>
> Thanks,
> Christopher Covington
>
>> v2
>>   - More clean-ups to the documentation
>> 
>> v3
>>   - re-base
>>   - use GArray instead of GList to avoid cache bouncing
>>   - checkpatch fixes
>> ---
>>  include/qemu/log.h |  2 ++
>>  qemu-log.c         | 57 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
>>  qemu-options.hx    | 16 +++++++++++++++
>>  vl.c               |  3 +++
>>  4 files changed, 78 insertions(+)
>> 
>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>> index b80f8f5..ade1f76 100644
>> --- a/include/qemu/log.h
>> +++ b/include/qemu/log.h
>> @@ -182,6 +182,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 77ed7bc..b3ebd3c 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,61 @@ 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 *delim = g_strrstr(r, "-");
>> +            if (!delim) {
>> +                delim = g_strrstr(r, "+");
>> +            }
>> +            if (delim) {
>> +                struct Range range;
>> +                range.begin = strtoul(r, NULL, 0);
>> +                switch (*delim) {
>> +                case '+':
>> +                    range.end = range.begin + strtoul(delim+1, NULL, 0);
>> +                    break;
>> +                case '-':
>> +                    range.end = strtoul(delim+1, NULL, 0);
>> +                    break;
>> +                default:
>> +                    g_assert_not_reached();
>> +                }
>> +                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 ae53346..90f0df9 100644
>> --- a/qemu-options.hx
>> +++ b/qemu-options.hx
>> @@ -2987,6 +2987,22 @@ 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{end} or @var{start}+@var{size} where @var{start}
>> +@var{end} and @var{size} are the addresses and sizes required. For example:
>> +@example
>> +    -dfilter 0x8000-0x9000,0xffffffc000080000+0x200
>> +@end example
>> +Will dump output for any code in the 0x1000 sized block starting at 0x8000 and
>> +the 0x200 sized block starting at 0xffffffc000080000.
>> +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 1d2de4f..05211cf 100644
>> --- a/vl.c
>> +++ b/vl.c
>> @@ -3349,6 +3349,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_PERFMAP:
>>                  tb_enable_perfmap();
>>                  break;
>> 

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH v4 05/11] qemu-log: Improve the "exec" TB execution logging

[Christopher Covington]

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

-- 
Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [Qemu-devel] [PATCH v4 00/11] qemu-log, perfmap and other logging tweaks

[Michael Tokarev]

03.08.2015 12:14, Alex Bennée wrote:
> Hi,
> 
> This is mostly just a re-base to keep current with master. I've added
> a couple of outstanding s-o-b and r-b tags. There are also two new
> patches in this series which seemed to be worth keeping together:
> 
>  - a simple patch to dump invocation info in the log
>  - the cputlb logging clean-up posted as an RFC last month
> 
> Could folks interested in TCG stuff have a look over the light
> re-factor and perf map patches please?
> 
> It would be nice to get these in the next cycle but I'm unsure who's
> tree I should be targeting? Most of the top level files touched
> (cputlb, translate-all, qemu-log) just have the list marked as the
> maintainer ;-)

With this many review comments and somewhat hot discussion about some
patches, I think I have a good excuse to not apply this series
to qemu-tivial tree ;)

Keep up the good work please!

/mjt

Re: [Qemu-devel] [PATCH v4 00/11] qemu-log, perfmap and other logging tweaks

[Alex Bennée]

Michael Tokarev <mjt@tls.msk.ru> writes:

> 03.08.2015 12:14, Alex Bennée wrote:
>> Hi,
>> 
>> This is mostly just a re-base to keep current with master. I've added
>> a couple of outstanding s-o-b and r-b tags. There are also two new
>> patches in this series which seemed to be worth keeping together:
>> 
>>  - a simple patch to dump invocation info in the log
>>  - the cputlb logging clean-up posted as an RFC last month
>> 
>> Could folks interested in TCG stuff have a look over the light
>> re-factor and perf map patches please?
>> 
>> It would be nice to get these in the next cycle but I'm unsure who's
>> tree I should be targeting? Most of the top level files touched
>> (cputlb, translate-all, qemu-log) just have the list marked as the
>> maintainer ;-)
>
> With this many review comments and somewhat hot discussion about some
> patches, I think I have a good excuse to not apply this series
> to qemu-tivial tree ;)

Yeah makes sense. I'll do a re-spin and probably drop the perfmap stuff
for now. There is a proposal for better JIT tracking in perf for JAVA so
I suspect we should target that.

It's a handy patch to keep around for your own analysis though ;-)

>
> Keep up the good work please!
>
> /mjt

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Peter Maydell]

On 4 August 2015 at 20:16, Richard Henderson <rth@twiddle.net> wrote:
> On 08/04/2015 12:08 PM, Alex Bennée wrote:
>>>> Would that make sense as a debug option or should we have a specific set
>>>> of TCG options to alter its behaviour?
>>>
>>>
>>> That's what I'm saying -- probably a separate debug option is better.
>>
>> Sorry I meant should we add it to -d (as in -d nochain) or have some tcg
>> opts (--tcg nochain,blah)
>
> I was suggesting the former: -d nochain.

Did anybody ever write the patch to add 'nochain' support?

thanks
-- PMM

Re: [Qemu-devel] [PATCH v4 03/11] qemu-log: correct help text for -d cpu

[Richard Henderson]

On 09/15/2015 12:28 PM, Peter Maydell wrote:
> On 4 August 2015 at 20:16, Richard Henderson <rth@twiddle.net> wrote:
>> On 08/04/2015 12:08 PM, Alex Bennée wrote:
>>>>> Would that make sense as a debug option or should we have a specific set
>>>>> of TCG options to alter its behaviour?
>>>>
>>>>
>>>> That's what I'm saying -- probably a separate debug option is better.
>>>
>>> Sorry I meant should we add it to -d (as in -d nochain) or have some tcg
>>> opts (--tcg nochain,blah)
>>
>> I was suggesting the former: -d nochain.
> 
> Did anybody ever write the patch to add 'nochain' support?

Nope.  ;-)


r~

Re: [Qemu-devel] [PATCH v4 02/11] tcg: light re-factor and pass down TranslationBlock

[Alex Bennée]

Aurelien Jarno <aurelien@aurel32.net> writes:

> On 2015-08-03 10:14, Alex Bennée wrote:
>> My later debugging patches need access to the origin PC. At the same
>> time we have a slightly clumsy pass-by-reference access to the size of
>> the translated block again for debugging purposes.
<snip>
>>      void *tc_ptr;    /* pointer to the translated code */
>> +    uint32_t tc_size;/* size of translated code */
>>      /* next matching tb for physical address. */
>>      struct TranslationBlock *phys_hash_next;
>>      /* first and second physical page containing code. The lower bit
>
> What's the impact on the memory here? Given the alignement, we add 8
> bytes to the structure on a 64-bit host.
<snip>

Well this has all got a lot simpler thanks to Richard's clean-up work
since this was last posted.

--
Alex Bennée

Re: [Qemu-devel] [PATCH v4 05/11] qemu-log: Improve the "exec" TB execution logging

[Alex Bennée]

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

Re: [Qemu-devel] [PATCH v4 11/11] cputlb: modernise the debug support

[Alex Bennée]

Aurelien Jarno <aurelien@aurel32.net> writes:

> On 2015-08-03 10:14, 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.
>>
>> I've also removed DEBUG_TLB_CHECK which wasn't used.
>>
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>>
>> ---
>> v2
>>   - ensure the compiler checks format strings even if debug is optimised out
>> ---
>>  cputlb.c | 54 +++++++++++++++++++++++++++++++++++-------------------
>>  1 file changed, 35 insertions(+), 19 deletions(-)
>>
>> diff --git a/cputlb.c b/cputlb.c
>> index a506086..7095e6f 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)
>
> Do we really want to support sending debug logs to either the logfile or
> stderr? It's already possible to send the debug logs through stderr when
> not specifying -D file.

It preserves the old behaviour (and the general behaviour of DEBUG_FOO
going to stderr). However I'm happy to make it default to using the log
output.

It does raise the question of if we should just enable the debugging by
default?

--
Alex Bennée

Re: [Qemu-devel] [PATCH v4 11/11] cputlb: modernise the debug support

[Peter Maydell]

On 3 February 2016 at 18:54, Alex Bennée <alex.bennee@linaro.org> wrote:
> It preserves the old behaviour (and the general behaviour of DEBUG_FOO
> going to stderr). However I'm happy to make it default to using the log
> output.
>
> It does raise the question of if we should just enable the debugging by
> default?

Not without thinking carefully about it. This is programmer
debug code for figuring out what's happening in a performance
sensitive bit of code. "Just print to stderr" is the classic
way to do this, and I don't think we should just convert that
into userfacing trace.

There may be useful user facing trace we can do of TLB
operations but I wouldn't assume that our current debug
printfs are it.

thanks
-- PMM

Re: [Qemu-devel] [PATCH v4 11/11] cputlb: modernise the debug support

[Alex Bennée]

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

> On 3 February 2016 at 18:54, Alex Bennée <alex.bennee@linaro.org> wrote:
>> It preserves the old behaviour (and the general behaviour of DEBUG_FOO
>> going to stderr). However I'm happy to make it default to using the log
>> output.
>>
>> It does raise the question of if we should just enable the debugging by
>> default?
>
> Not without thinking carefully about it. This is programmer
> debug code for figuring out what's happening in a performance
> sensitive bit of code. "Just print to stderr" is the classic
> way to do this, and I don't think we should just convert that
> into userfacing trace.

Shall I just go back to the original fprintf output then? I made the
output optional a few review comments back.

>
> There may be useful user facing trace we can do of TLB
> operations but I wouldn't assume that our current debug
> printfs are it.
>
> thanks
> -- PMM


--
Alex Bennée