From: "Vanderson M. do Rosario" <vandersonmr2@gmail.com>
These commands allow the exploration of TBs generated by the TCG.
Understand which one hotter, with more guest/host instructions... and
examine their guest, host and IR code.
The goal of this command is to allow the dynamic exploration of TCG
behavior and code quality. Therefore, for now, a corresponding QMP
command is not worthwhile.
[AJB: WIP - we still can't be safely sure a translation will succeed]
Example of output:
TB id:1 | phys:0x34d54 virt:0x0000000000034d54 flags:0x0000f0
| exec:4828932/0 guest inst cov:16.38%
| trans:1 ints: g:3 op:82 op_opt:34 spills:3
| h/g (host bytes / guest insts): 90.666664
| time to gen at 2.4GHz => code:3150.83(ns) IR:712.08(ns)
| targets: 0x0000000000034d5e (id:11), 0x0000000000034d0d (id:2)
TB id:2 | phys:0x34d0d virt:0x0000000000034d0d flags:0x0000f0
| exec:4825842/0 guest inst cov:21.82%
| trans:1 ints: g:4 op:80 op_opt:38 spills:2
| h/g (host bytes / guest insts): 84.000000
| time to gen at 2.4GHz => code:3362.92(ns) IR:793.75(ns)
| targets: 0x0000000000034d19 (id:12), 0x0000000000034d54 (id:1)
TB id:2 | phys:0x34d0d virt:0x0000000000034d0d flags:0x0000f0
| exec:6956495/0 guest inst cov:21.82%
| trans:2 ints: g:2 op:40 op_opt:19 spills:1
| h/g (host bytes / guest insts): 84.000000
| time to gen at 2.4GHz => code:3130.83(ns) IR:722.50(ns)
| targets: 0x0000000000034d19 (id:12), 0x0000000000034d54 (id:1)
----------------
IN:
0x00034d0d: 89 de movl %ebx, %esi
0x00034d0f: 26 8b 0e movl %es:(%esi), %ecx
0x00034d12: 26 f6 46 08 80 testb $0x80, %es:8(%esi)
0x00034d17: 75 3b jne 0x34d54
------------------------------
TB id:1 | phys:0x34d54 virt:0x0000000000034d54 flags:0x0000f0
| exec:5202686/0 guest inst cov:11.28%
| trans:1 ints: g:3 op:82 op_opt:34 spills:3
| h/g (host bytes / guest insts): 90.666664
| time to gen at 2.4GHz => code:2793.75(ns) IR:614.58(ns)
| targets: 0x0000000000034d5e (id:3), 0x0000000000034d0d (id:2)
TB id:2 | phys:0x34d0d virt:0x0000000000034d0d flags:0x0000f0
| exec:5199468/0 guest inst cov:15.03%
| trans:1 ints: g:4 op:80 op_opt:38 spills:2
| h/g (host bytes / guest insts): 84.000000
| time to gen at 2.4GHz => code:2958.75(ns) IR:719.58(ns)
| targets: 0x0000000000034d19 (id:4), 0x0000000000034d54 (id:1)
------------------------------
2 TBs to reach 25% of guest inst exec coverage
Total of guest insts exec: 138346727
------------------------------
Acked-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
Signed-off-by: Vanderson M. do Rosario <vandersonmr2@gmail.com>
Message-Id: <20190829173437.5926-10-vandersonmr2@gmail.com>
[AJB: fix authorship, dropped coverset]
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Signed-off-by: Fei Wu <fei2.wu@intel.com>
---
accel/tcg/monitor.c | 54 ++++++
accel/tcg/tb-stats.c | 322 +++++++++++++++++++++++++++++++++++
disas/disas.c | 24 ++-
hmp-commands-info.hx | 16 ++
include/exec/tb-stats.h | 33 +++-
include/monitor/hmp.h | 2 +
include/qemu/log-for-trace.h | 6 +-
include/qemu/log.h | 2 +
util/log.c | 66 +++++--
9 files changed, 507 insertions(+), 18 deletions(-)
diff --git a/accel/tcg/monitor.c b/accel/tcg/monitor.c
index 2e00f10267..a1780c5920 100644
--- a/accel/tcg/monitor.c
+++ b/accel/tcg/monitor.c
@@ -8,6 +8,7 @@
#include "qemu/osdep.h"
#include "qemu/accel.h"
+#include "qemu/log.h"
#include "qapi/error.h"
#include "qapi/type-helpers.h"
#include "qapi/qapi-commands-machine.h"
@@ -18,6 +19,7 @@
#include "sysemu/cpu-timers.h"
#include "sysemu/tcg.h"
#include "exec/tb-stats.h"
+#include "tb-context.h"
#include "internal.h"
@@ -132,6 +134,58 @@ void hmp_tbstats(Monitor *mon, const QDict *qdict)
}
+void hmp_info_tblist(Monitor *mon, const QDict *qdict)
+{
+ int number_int;
+ const char *sortedby_str = NULL;
+ if (!tcg_enabled()) {
+ error_report("TB information is only available with accel=tcg");
+ return;
+ }
+ if (!tb_ctx.tb_stats.map) {
+ error_report("no TB information recorded");
+ return;
+ }
+
+ number_int = qdict_get_try_int(qdict, "number", 10);
+ sortedby_str = qdict_get_try_str(qdict, "sortedby");
+
+ int sortedby = SORT_BY_HOTNESS;
+ if (sortedby_str == NULL || strcmp(sortedby_str, "hotness") == 0) {
+ sortedby = SORT_BY_HOTNESS;
+ } else if (strcmp(sortedby_str, "hg") == 0) {
+ sortedby = SORT_BY_HG;
+ } else if (strcmp(sortedby_str, "spills") == 0) {
+ sortedby = SORT_BY_SPILLS;
+ } else {
+ error_report("valid sort options are: hotness hg spills");
+ return;
+ }
+
+ dump_tbs_info(number_int, sortedby, true);
+}
+
+void hmp_info_tb(Monitor *mon, const QDict *qdict)
+{
+ const int id = qdict_get_int(qdict, "id");
+ const char *flags = qdict_get_try_str(qdict, "flags");
+ int mask;
+
+ if (!tcg_enabled()) {
+ error_report("TB information is only available with accel=tcg");
+ return;
+ }
+
+ mask = flags ? qemu_str_to_log_mask(flags) : CPU_LOG_TB_IN_ASM;
+
+ if (!mask) {
+ error_report("Unable to parse log flags, see 'help log'");
+ return;
+ }
+
+ dump_tb_info(id, mask, true);
+}
+
HumanReadableText *qmp_x_query_profile(Error **errp)
{
g_autoptr(GString) buf = g_string_new("");
diff --git a/accel/tcg/tb-stats.c b/accel/tcg/tb-stats.c
index 469e3e024b..cb28879a45 100644
--- a/accel/tcg/tb-stats.c
+++ b/accel/tcg/tb-stats.c
@@ -11,14 +11,18 @@
#include "disas/disas.h"
#include "exec/exec-all.h"
#include "tcg/tcg.h"
+#include "qapi/error.h"
#include "qemu/qemu-print.h"
#include "qemu/timer.h"
+#include "qemu/log.h"
#include "exec/tb-stats.h"
#include "exec/tb-flush.h"
#include "tb-context.h"
+#include "internal.h"
+
/* TBStatistic collection controls */
enum TBStatsStatus {
TB_STATS_DISABLED = 0,
@@ -32,8 +36,23 @@ static uint32_t default_tbstats_flag;
/* only accessed in safe work */
static GList *last_search;
+static int id = 1; /* display_id increment counter */
uint64_t dev_time;
+static TBStatistics *get_tbstats_by_id(int id)
+{
+ GList *iter;
+
+ for (iter = last_search; iter; iter = g_list_next(iter)) {
+ TBStatistics *tbs = iter->data;
+ if (tbs && tbs->display_id == id) {
+ return tbs;
+ break;
+ }
+ }
+ return NULL;
+}
+
struct jit_profile_info {
uint64_t translations;
uint64_t aborted;
@@ -296,6 +315,309 @@ void init_tb_stats_htable(void)
}
}
+static void collect_tb_stats(void *p, uint32_t hash, void *userp)
+{
+ last_search = g_list_prepend(last_search, p);
+}
+
+static void count_invalid_tbs(gpointer data, gpointer user_data)
+{
+ TranslationBlock *tb = (TranslationBlock *) data;
+ unsigned *counter = (unsigned *) user_data;
+ if (tb->cflags & CF_INVALID) {
+ *counter = *counter + 1;
+ }
+}
+
+static int dump_tb_header(TBStatistics *tbs)
+{
+ unsigned g = stat_per_translation(tbs, code.num_guest_inst);
+ unsigned ops = stat_per_translation(tbs, code.num_tcg_ops);
+ unsigned ops_opt = stat_per_translation(tbs, code.num_tcg_ops_opt);
+ unsigned spills = stat_per_translation(tbs, code.spills);
+ unsigned h = stat_per_translation(tbs, code.out_len);
+ unsigned act = tbs->tbs->len;
+ unsigned invalid = 0;
+
+ float guest_host_prop = g ? ((float) h / g) : 0;
+
+ g_ptr_array_foreach(tbs->tbs, &count_invalid_tbs, &invalid);
+
+ qemu_log("TB id:%d | phys:0x"TB_PAGE_ADDR_FMT" virt:0x"TARGET_FMT_lx
+ " flags:0x%08x %d inv/%d\n",
+ tbs->display_id, tbs->phys_pc, tbs->pc, tbs->flags,
+ invalid, act);
+
+ if (tbs_stats_enabled(tbs, TB_EXEC_STATS)) {
+ qemu_log("\t| exec:%lu/%lu guest inst cov:%.2f%%\n",
+ tbs->executions.normal,
+ tbs->executions.atomic, tbs->executions.coverage / 100.0f);
+ }
+
+ if (tbs_stats_enabled(tbs, TB_JIT_STATS)) {
+ qemu_log("\t| trans:%lu ints: g:%u op:%u op_opt:%u spills:%d"
+ "\n\t| h/g (host bytes / guest insts): %f\n",
+ tbs->translations.total, g, ops, ops_opt, spills, guest_host_prop);
+ }
+
+ if (tbs_stats_enabled(tbs, TB_JIT_TIME)) {
+ qemu_log("\t| time to gen at 2.4GHz => code:%0.2lf(ns) IR:%0.2lf(ns)\n",
+ tbs->gen_times.code / 2.4, tbs->gen_times.ir / 2.4);
+ }
+
+ qemu_log("\n");
+
+ return act - invalid;
+}
+
+static gint
+inverse_sort_tbs(gconstpointer p1, gconstpointer p2, gpointer psort_by)
+{
+ const TBStatistics *tbs1 = (TBStatistics *) p1;
+ const TBStatistics *tbs2 = (TBStatistics *) p2;
+ int sort_by = *((enum SortBy *) psort_by);
+ unsigned long c1 = 0;
+ unsigned long c2 = 0;
+
+ if (sort_by == SORT_BY_SPILLS) {
+ c1 = stat_per_translation(tbs1, code.spills);
+ c2 = stat_per_translation(tbs2, code.spills);
+ } else if (sort_by == SORT_BY_HOTNESS) {
+ c1 = stat_per_translation(tbs1, executions.normal);
+ c2 = stat_per_translation(tbs2, executions.normal);
+ } else if (sort_by == SORT_BY_HG) {
+ if (tbs1->code.num_guest_inst == 0) {
+ return -1;
+ }
+ if (tbs2->code.num_guest_inst == 0) {
+ return 1;
+ }
+
+ c1 = tbs1->code.out_len / tbs1->code.num_guest_inst;
+ c2 = tbs2->code.out_len / tbs2->code.num_guest_inst;
+ }
+ return c1 < c2 ? 1 : c1 == c2 ? 0 : -1;
+}
+
+static void dump_last_search_headers(int count)
+{
+ if (!last_search) {
+ qemu_log("No data collected yet\n");
+ return;
+ }
+
+ GList *l = last_search;
+ while (l != NULL && count--) {
+ TBStatistics *tbs = (TBStatistics *) l->data;
+ GList *next = l->next;
+ dump_tb_header(tbs);
+ l = next;
+ }
+}
+
+static uint64_t calculate_last_search_coverages(void)
+{
+ uint64_t total_exec_count = 0;
+ GList *i;
+
+ /* Compute total execution count for all tbs */
+ for (i = last_search; i; i = i->next) {
+ TBStatistics *tbs = (TBStatistics *) i->data;
+ total_exec_count +=
+ (tbs->executions.atomic + tbs->executions.normal)
+ * tbs->code.num_guest_inst;
+ }
+
+ for (i = last_search; i; i = i->next) {
+ TBStatistics *tbs = (TBStatistics *) i->data;
+ uint64_t tb_total_execs =
+ (tbs->executions.atomic + tbs->executions.normal)
+ * tbs->code.num_guest_inst;
+ tbs->executions.coverage =
+ (10000 * tb_total_execs) / (total_exec_count + 1);
+ }
+
+ return total_exec_count;
+}
+
+static void do_dump_tbs_info(int total, int sort_by)
+{
+ id = 1;
+ GList *i;
+ int count = total;
+
+ g_list_free(last_search);
+ last_search = NULL;
+
+ qht_iter(&tb_ctx.tb_stats, collect_tb_stats, NULL);
+
+ last_search = g_list_sort_with_data(last_search, inverse_sort_tbs,
+ &sort_by);
+
+ if (!last_search) {
+ qemu_printf("No data collected yet!\n");
+ return;
+ }
+
+ calculate_last_search_coverages();
+
+ for (i = last_search; i && count--; i = i->next) {
+ TBStatistics *tbs = (TBStatistics *) i->data;
+ tbs->display_id = id++;
+ }
+
+ /* free the unused bits */
+ if (i) {
+ if (i->next) {
+ i->next->prev = NULL;
+ }
+ g_list_free(i->next);
+ i->next = NULL;
+ }
+
+ dump_last_search_headers(total);
+}
+
+struct tbs_dump_info {
+ int count;
+ int sort_by;
+};
+
+static void do_dump_tbs_info_safe(CPUState *cpu, run_on_cpu_data tbdi)
+{
+ struct tbs_dump_info *info = tbdi.host_ptr;
+ qemu_log_to_monitor(true);
+ do_dump_tbs_info(info->count, info->sort_by);
+ qemu_log_to_monitor(false);
+ g_free(info);
+}
+
+/*
+ * When we dump_tbs_info on a live system via the HMP we want to
+ * ensure the system is quiessent before we start outputting stuff.
+ * Otherwise we could pollute the output with other logging output.
+ */
+
+void dump_tbs_info(int count, int sort_by, bool use_monitor)
+{
+ if (use_monitor) {
+ struct tbs_dump_info *tbdi = g_new(struct tbs_dump_info, 1);
+ tbdi->count = count;
+ tbdi->sort_by = sort_by;
+ async_safe_run_on_cpu(first_cpu, do_dump_tbs_info_safe,
+ RUN_ON_CPU_HOST_PTR(tbdi));
+ } else {
+ do_dump_tbs_info(count, sort_by);
+ }
+}
+
+/*
+ * We cannot always re-generate the code even if we know there are
+ * valid translations still in the cache. The reason being the guest
+ * may have un-mapped the page code. In real life this would be
+ * un-reachable as the jump cache is cleared and the following QHT
+ * lookup will do a get_page_addr_code() and fault.
+ *
+ * TODO: can we do this safely? We need to
+ * a) somehow recover the mmu_idx for this translation
+ * b) probe MMU_INST_FETCH to know it will succeed
+ */
+static GString *get_code_string(TBStatistics *tbs, int log_flags)
+{
+ int old_log_flags = qemu_loglevel;
+
+ CPUState *cpu = first_cpu;
+ uint32_t cflags = curr_cflags(cpu);
+ TranslationBlock *tb = NULL;
+
+ GString *code_s = g_string_new(NULL);
+ qemu_log_to_string(true, code_s);
+
+ Error *err = NULL;
+ if (!qemu_set_log(log_flags, &err)) {
+ g_string_append_printf(code_s, "%s", error_get_pretty(err));
+ error_free(err);
+ }
+
+ if (sigsetjmp(cpu->jmp_env, 0) == 0) {
+ mmap_lock();
+ tb = tb_gen_code(cpu, tbs->pc, tbs->cs_base, tbs->flags, cflags);
+ tb_phys_invalidate(tb, -1);
+ mmap_unlock();
+ } else {
+ /*
+ * The mmap_lock is dropped by tb_gen_code if it runs out of
+ * memory.
+ */
+ qemu_log("\ncould not gen code for this TB (no longer mapped?)\n");
+ assert_no_pages_locked();
+ }
+
+ qemu_set_log(old_log_flags, &err);
+ qemu_log_to_string(false, NULL);
+
+ return code_s;
+}
+
+static void do_tb_dump_with_statistics(TBStatistics *tbs, int log_flags)
+{
+ g_autoptr(GString) code_s = NULL;
+
+ qemu_log("\n------------------------------\n\n");
+
+ if (dump_tb_header(tbs) > 0) {
+ code_s = get_code_string(tbs, log_flags);
+ } else {
+ code_s = g_string_new("cannot re-translate non-active translation");
+ }
+ qemu_log("%s", code_s->str);
+ qemu_log("------------------------------\n");
+}
+
+struct tb_dump_info {
+ int id;
+ int log_flags;
+ bool use_monitor;
+};
+
+static void do_dump_tb_info_safe(CPUState *cpu, run_on_cpu_data info)
+{
+ struct tb_dump_info *tbdi = (struct tb_dump_info *) info.host_ptr;
+
+ if (!last_search) {
+ qemu_log("no search on record\n");
+ return;
+ }
+
+ qemu_log_to_monitor(tbdi->use_monitor);
+
+ TBStatistics *tbs = get_tbstats_by_id(tbdi->id);
+ if (tbs) {
+ do_tb_dump_with_statistics(tbs, tbdi->log_flags);
+ } else {
+ qemu_log("no TB statitics found with id %d\n", tbdi->id);
+ }
+
+ qemu_log_to_monitor(false);
+
+ g_free(tbdi);
+}
+
+void dump_tb_info(int id, int log_mask, bool use_monitor)
+{
+ struct tb_dump_info *tbdi = g_new(struct tb_dump_info, 1);
+
+ tbdi->id = id;
+ tbdi->log_flags = log_mask;
+ tbdi->use_monitor = use_monitor;
+
+ async_safe_run_on_cpu(first_cpu, do_dump_tb_info_safe,
+ RUN_ON_CPU_HOST_PTR(tbdi));
+
+ /* tbdi free'd by do_dump_tb_info_safe */
+}
+
+
void enable_collect_tb_stats(void)
{
tcg_collect_tb_stats = TB_STATS_RUNNING;
diff --git a/disas/disas.c b/disas/disas.c
index 0d2d06c2ec..6cdd797874 100644
--- a/disas/disas.c
+++ b/disas/disas.c
@@ -8,6 +8,8 @@
#include "hw/core/cpu.h"
#include "exec/memory.h"
+#include "qemu/log-for-trace.h"
+
/* Filled in by elfload.c. Simplistic, but will do for now. */
struct syminfo *syminfos = NULL;
@@ -199,6 +201,24 @@ static void initialize_debug_host(CPUDebug *s)
#endif
}
+static int
+__attribute__((format(printf, 2, 3)))
+fprintf_log(FILE *a, const char *b, ...)
+{
+ va_list ap;
+ va_start(ap, b);
+
+ if (!to_string) {
+ vfprintf(a, b, ap);
+ } else {
+ qemu_vlog(b, ap);
+ }
+
+ va_end(ap);
+
+ return 1;
+}
+
/* Disassemble this for me please... (debugging). */
void target_disas(FILE *out, CPUState *cpu, uint64_t code, size_t size)
{
@@ -221,9 +241,9 @@ void target_disas(FILE *out, CPUState *cpu, uint64_t code, size_t size)
}
for (pc = code; size > 0; pc += count, size -= count) {
- fprintf(out, "0x%08" PRIx64 ": ", pc);
+ fprintf_log(out, "0x%08" PRIx64 ": ", pc);
count = s.info.print_insn(pc, &s.info);
- fprintf(out, "\n");
+ fprintf_log(out, "\n");
if (count < 0) {
break;
}
diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx
index 47d63d26db..01d9658aea 100644
--- a/hmp-commands-info.hx
+++ b/hmp-commands-info.hx
@@ -262,6 +262,22 @@ ERST
.params = "",
.help = "show dynamic compiler info",
},
+ {
+ .name = "tb-list",
+ .args_type = "number:i?,sortedby:s?",
+ .params = "[number sortedby]",
+ .help = "show a [number] translated blocks sorted by [sortedby]"
+ "sortedby opts: hotness hg spills",
+ .cmd = hmp_info_tblist,
+ },
+ {
+ .name = "tb",
+ .args_type = "id:i,flags:s?",
+ .params = "id [flag1,flag2,...]",
+ .help = "show information about one translated block by id."
+ "dump flags can be used to set dump code level: out_asm in_asm op",
+ .cmd = hmp_info_tb,
+ },
#endif
SRST
diff --git a/include/exec/tb-stats.h b/include/exec/tb-stats.h
index 30b788f7b2..f2a6b09da9 100644
--- a/include/exec/tb-stats.h
+++ b/include/exec/tb-stats.h
@@ -36,8 +36,11 @@
enum SortBy { SORT_BY_HOTNESS, SORT_BY_HG /* Host/Guest */, SORT_BY_SPILLS };
enum TbstatsCmd { START, PAUSE, STOP, FILTER };
+#define tbs_stats_enabled(tbs, JIT_STATS) \
+ (tbs && (tbs->stats_enabled & JIT_STATS))
+
#define tb_stats_enabled(tb, JIT_STATS) \
- (tb && tb->tb_stats && (tb->tb_stats->stats_enabled & JIT_STATS))
+ (tb && tb->tb_stats && tbs_stats_enabled(tb->tb_stats, JIT_STATS))
#define stat_per_translation(stat, name) \
(stat->translations.total ? stat->name / stat->translations.total : 0)
@@ -66,6 +69,8 @@ struct TBStatistics {
struct {
unsigned long normal;
unsigned long atomic;
+ /* filled only when dumping x% cover set */
+ uint16_t coverage;
} executions;
/* JIT Stats - protected by lock */
@@ -88,7 +93,6 @@ struct TBStatistics {
struct {
unsigned long total;
- unsigned long uncached;
unsigned long spanning;
} translations;
@@ -108,6 +112,9 @@ struct TBStatistics {
uint64_t la;
uint64_t code;
} gen_times;
+
+ /* HMP information - used for referring to previous search */
+ int display_id;
};
bool tb_stats_cmp(const void *ap, const void *bp);
@@ -132,4 +139,26 @@ void do_hmp_tbstats_safe(CPUState *cpu, run_on_cpu_data icmd);
*/
void tbstats_reset_tbs(void);
+/**
+ * dump_tbs_info: report the hottest blocks
+ *
+ * @count: the limit of hotblocks
+ * @sort_by: property in which the dump will be sorted
+ * @use_monitor: redirect output to monitor
+ *
+ * Report the hottest blocks to either the log or monitor
+ */
+void dump_tbs_info(int count, int sort_by, bool use_monitor);
+
+/**
+ * dump_tb_info: dump information about one TB
+ *
+ * @id: the display id of the block (from previous search)
+ * @mask: the temporary logging mask
+ * @Use_monitor: redirect output to monitor
+ *
+ * Re-run a translation of a block at addr for the purposes of debug output
+ */
+void dump_tb_info(int id, int log_mask, bool use_monitor);
+
#endif
diff --git a/include/monitor/hmp.h b/include/monitor/hmp.h
index 2e7f141754..acdd6f1561 100644
--- a/include/monitor/hmp.h
+++ b/include/monitor/hmp.h
@@ -182,5 +182,7 @@ void hmp_boot_set(Monitor *mon, const QDict *qdict);
void hmp_info_mtree(Monitor *mon, const QDict *qdict);
void hmp_info_cryptodev(Monitor *mon, const QDict *qdict);
void hmp_tbstats(Monitor *mon, const QDict *qdict);
+void hmp_info_tblist(Monitor *mon, const QDict *qdict);
+void hmp_info_tb(Monitor *mon, const QDict *qdict);
#endif
diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
index d47c9cd446..5d0afc56c7 100644
--- a/include/qemu/log-for-trace.h
+++ b/include/qemu/log-for-trace.h
@@ -20,6 +20,9 @@
/* Private global variable, don't use */
extern int qemu_loglevel;
+extern bool to_string;
+
+extern int32_t max_num_hot_tbs_to_dump;
#define LOG_TRACE (1 << 15)
@@ -30,6 +33,7 @@ static inline bool qemu_loglevel_mask(int mask)
}
/* main logging function */
-void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
+int G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
+int G_GNUC_PRINTF(1, 0) qemu_vlog(const char *fmt, va_list va);
#endif
diff --git a/include/qemu/log.h b/include/qemu/log.h
index 6f3b8091cd..26b33151f3 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -85,6 +85,8 @@ extern const QEMULogItem qemu_log_items[];
bool qemu_set_log(int log_flags, Error **errp);
bool qemu_set_log_filename(const char *filename, Error **errp);
bool qemu_set_log_filename_flags(const char *name, int flags, Error **errp);
+void qemu_log_to_monitor(bool enable);
+void qemu_log_to_string(bool enable, GString *s);
void qemu_set_dfilter_ranges(const char *ranges, Error **errp);
bool qemu_log_in_addr_range(uint64_t addr);
int qemu_str_to_log_mask(const char *str);
diff --git a/util/log.c b/util/log.c
index 7ae471d97c..6477eb5a5f 100644
--- a/util/log.c
+++ b/util/log.c
@@ -50,6 +50,8 @@ int qemu_loglevel;
static bool log_per_thread;
static GArray *debug_regions;
int32_t max_num_hot_tbs_to_dump;
+static bool to_monitor;
+bool to_string;
/* Returns true if qemu_log() will really write somewhere. */
bool qemu_log_enabled(void)
@@ -146,19 +148,6 @@ void qemu_log_unlock(FILE *logfile)
}
}
-void qemu_log(const char *fmt, ...)
-{
- FILE *f = qemu_log_trylock();
- if (f) {
- va_list ap;
-
- va_start(ap, fmt);
- vfprintf(f, fmt, ap);
- va_end(ap);
- qemu_log_unlock(f);
- }
-}
-
static void __attribute__((__constructor__)) startup(void)
{
qemu_mutex_init(&global_mutex);
@@ -206,6 +195,55 @@ valid_filename_template(const char *filename, bool per_thread, Error **errp)
return filename ? vft_strdup : vft_stderr;
}
+GString *string;
+
+int qemu_vlog(const char *fmt, va_list va)
+{
+ int ret = 0;
+
+ if (to_string && string) {
+ g_string_append_vprintf(string, fmt, va);
+ } else if (to_monitor) {
+ ret = qemu_vprintf(fmt, va);
+ } else {
+ FILE *f = qemu_log_trylock();
+ if (f) {
+ ret = vfprintf(f, fmt, va);
+ }
+ qemu_log_unlock(f);
+ }
+
+ /* Don't pass back error results. */
+ if (ret < 0) {
+ ret = 0;
+ }
+ return ret;
+}
+
+/* Return the number of characters emitted. */
+int qemu_log(const char *fmt, ...)
+{
+ int ret = 0;
+ va_list ap;
+
+ va_start(ap, fmt);
+ ret = qemu_vlog(fmt, ap);
+ va_end(ap);
+
+ return ret;
+}
+
+void qemu_log_to_monitor(bool enable)
+{
+ to_monitor = enable;
+}
+
+void qemu_log_to_string(bool enable, GString *s)
+{
+ to_string = enable;
+ string = s;
+}
+
/* enable or disable low levels log */
static bool qemu_set_log_internal(const char *filename, bool changed_name,
int log_flags, Error **errp)
@@ -523,6 +561,7 @@ int qemu_str_to_log_mask(const char *str)
trace_enable_events((*tmp) + 6);
mask |= LOG_TRACE;
#endif
+#ifdef CONFIG_TCG
} else if (g_str_has_prefix(*tmp, "tb_stats")) {
mask |= CPU_LOG_TB_STATS;
set_default_tbstats_flag(TB_ALL_STATS);
@@ -553,6 +592,7 @@ int qemu_str_to_log_mask(const char *str)
}
set_default_tbstats_flag(flags);
}
+#endif
} else {
for (item = qemu_log_items; item->mask != 0; item++) {
if (g_str_equal(*tmp, item->name)) {
--
2.25.1
On 5/18/2023 9:57 PM, Fei Wu wrote:
> From: "Vanderson M. do Rosario" <vandersonmr2@gmail.com>
>
> These commands allow the exploration of TBs generated by the TCG.
> Understand which one hotter, with more guest/host instructions... and
> examine their guest, host and IR code.
>
> The goal of this command is to allow the dynamic exploration of TCG
> behavior and code quality. Therefore, for now, a corresponding QMP
> command is not worthwhile.
>
> [AJB: WIP - we still can't be safely sure a translation will succeed]
>
> Example of output:
>
> TB id:1 | phys:0x34d54 virt:0x0000000000034d54 flags:0x0000f0
> | exec:4828932/0 guest inst cov:16.38%
> | trans:1 ints: g:3 op:82 op_opt:34 spills:3
> | h/g (host bytes / guest insts): 90.666664
> | time to gen at 2.4GHz => code:3150.83(ns) IR:712.08(ns)
> | targets: 0x0000000000034d5e (id:11), 0x0000000000034d0d (id:2)
>
> TB id:2 | phys:0x34d0d virt:0x0000000000034d0d flags:0x0000f0
> | exec:4825842/0 guest inst cov:21.82%
> | trans:1 ints: g:4 op:80 op_opt:38 spills:2
> | h/g (host bytes / guest insts): 84.000000
> | time to gen at 2.4GHz => code:3362.92(ns) IR:793.75(ns)
> | targets: 0x0000000000034d19 (id:12), 0x0000000000034d54 (id:1)
>
> TB id:2 | phys:0x34d0d virt:0x0000000000034d0d flags:0x0000f0
> | exec:6956495/0 guest inst cov:21.82%
> | trans:2 ints: g:2 op:40 op_opt:19 spills:1
> | h/g (host bytes / guest insts): 84.000000
> | time to gen at 2.4GHz => code:3130.83(ns) IR:722.50(ns)
> | targets: 0x0000000000034d19 (id:12), 0x0000000000034d54 (id:1)
>
> ----------------
> IN:
> 0x00034d0d: 89 de movl %ebx, %esi
> 0x00034d0f: 26 8b 0e movl %es:(%esi), %ecx
> 0x00034d12: 26 f6 46 08 80 testb $0x80, %es:8(%esi)
> 0x00034d17: 75 3b jne 0x34d54
>
> ------------------------------
>
> TB id:1 | phys:0x34d54 virt:0x0000000000034d54 flags:0x0000f0
> | exec:5202686/0 guest inst cov:11.28%
> | trans:1 ints: g:3 op:82 op_opt:34 spills:3
> | h/g (host bytes / guest insts): 90.666664
> | time to gen at 2.4GHz => code:2793.75(ns) IR:614.58(ns)
> | targets: 0x0000000000034d5e (id:3), 0x0000000000034d0d (id:2)
>
> TB id:2 | phys:0x34d0d virt:0x0000000000034d0d flags:0x0000f0
> | exec:5199468/0 guest inst cov:15.03%
> | trans:1 ints: g:4 op:80 op_opt:38 spills:2
> | h/g (host bytes / guest insts): 84.000000
> | time to gen at 2.4GHz => code:2958.75(ns) IR:719.58(ns)
> | targets: 0x0000000000034d19 (id:4), 0x0000000000034d54 (id:1)
>
> ------------------------------
> 2 TBs to reach 25% of guest inst exec coverage
> Total of guest insts exec: 138346727
>
> ------------------------------
>
> Acked-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
> Signed-off-by: Vanderson M. do Rosario <vandersonmr2@gmail.com>
> Message-Id: <20190829173437.5926-10-vandersonmr2@gmail.com>
> [AJB: fix authorship, dropped coverset]
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> Signed-off-by: Fei Wu <fei2.wu@intel.com>
> ---
> accel/tcg/monitor.c | 54 ++++++
> accel/tcg/tb-stats.c | 322 +++++++++++++++++++++++++++++++++++
> disas/disas.c | 24 ++-
> hmp-commands-info.hx | 16 ++
> include/exec/tb-stats.h | 33 +++-
> include/monitor/hmp.h | 2 +
> include/qemu/log-for-trace.h | 6 +-
> include/qemu/log.h | 2 +
> util/log.c | 66 +++++--
> 9 files changed, 507 insertions(+), 18 deletions(-)
>
> diff --git a/accel/tcg/monitor.c b/accel/tcg/monitor.c
> index 2e00f10267..a1780c5920 100644
> --- a/accel/tcg/monitor.c
> +++ b/accel/tcg/monitor.c
> @@ -8,6 +8,7 @@
>
> #include "qemu/osdep.h"
> #include "qemu/accel.h"
> +#include "qemu/log.h"
> #include "qapi/error.h"
> #include "qapi/type-helpers.h"
> #include "qapi/qapi-commands-machine.h"
> @@ -18,6 +19,7 @@
> #include "sysemu/cpu-timers.h"
> #include "sysemu/tcg.h"
> #include "exec/tb-stats.h"
> +#include "tb-context.h"
> #include "internal.h"
>
>
> @@ -132,6 +134,58 @@ void hmp_tbstats(Monitor *mon, const QDict *qdict)
>
> }
>
> +void hmp_info_tblist(Monitor *mon, const QDict *qdict)
> +{
> + int number_int;
> + const char *sortedby_str = NULL;
> + if (!tcg_enabled()) {
> + error_report("TB information is only available with accel=tcg");
> + return;
> + }
> + if (!tb_ctx.tb_stats.map) {
> + error_report("no TB information recorded");
> + return;
> + }
> +
> + number_int = qdict_get_try_int(qdict, "number", 10);
> + sortedby_str = qdict_get_try_str(qdict, "sortedby");
> +
> + int sortedby = SORT_BY_HOTNESS;
> + if (sortedby_str == NULL || strcmp(sortedby_str, "hotness") == 0) {
> + sortedby = SORT_BY_HOTNESS;
> + } else if (strcmp(sortedby_str, "hg") == 0) {
> + sortedby = SORT_BY_HG;
> + } else if (strcmp(sortedby_str, "spills") == 0) {
> + sortedby = SORT_BY_SPILLS;
> + } else {
> + error_report("valid sort options are: hotness hg spills");
> + return;
> + }
> +
> + dump_tbs_info(number_int, sortedby, true);
> +}
> +
> +void hmp_info_tb(Monitor *mon, const QDict *qdict)
> +{
> + const int id = qdict_get_int(qdict, "id");
> + const char *flags = qdict_get_try_str(qdict, "flags");
> + int mask;
> +
> + if (!tcg_enabled()) {
> + error_report("TB information is only available with accel=tcg");
> + return;
> + }
> +
> + mask = flags ? qemu_str_to_log_mask(flags) : CPU_LOG_TB_IN_ASM;
> +
> + if (!mask) {
> + error_report("Unable to parse log flags, see 'help log'");
> + return;
> + }
> +
> + dump_tb_info(id, mask, true);
> +}
> +
> HumanReadableText *qmp_x_query_profile(Error **errp)
> {
> g_autoptr(GString) buf = g_string_new("");
> diff --git a/accel/tcg/tb-stats.c b/accel/tcg/tb-stats.c
> index 469e3e024b..cb28879a45 100644
> --- a/accel/tcg/tb-stats.c
> +++ b/accel/tcg/tb-stats.c
> @@ -11,14 +11,18 @@
> #include "disas/disas.h"
> #include "exec/exec-all.h"
> #include "tcg/tcg.h"
> +#include "qapi/error.h"
>
> #include "qemu/qemu-print.h"
> #include "qemu/timer.h"
> +#include "qemu/log.h"
>
> #include "exec/tb-stats.h"
> #include "exec/tb-flush.h"
> #include "tb-context.h"
>
> +#include "internal.h"
> +
> /* TBStatistic collection controls */
> enum TBStatsStatus {
> TB_STATS_DISABLED = 0,
> @@ -32,8 +36,23 @@ static uint32_t default_tbstats_flag;
> /* only accessed in safe work */
> static GList *last_search;
>
> +static int id = 1; /* display_id increment counter */
> uint64_t dev_time;
>
> +static TBStatistics *get_tbstats_by_id(int id)
> +{
> + GList *iter;
> +
> + for (iter = last_search; iter; iter = g_list_next(iter)) {
> + TBStatistics *tbs = iter->data;
> + if (tbs && tbs->display_id == id) {
> + return tbs;
> + break;
> + }
> + }
> + return NULL;
> +}
> +
> struct jit_profile_info {
> uint64_t translations;
> uint64_t aborted;
> @@ -296,6 +315,309 @@ void init_tb_stats_htable(void)
> }
> }
>
> +static void collect_tb_stats(void *p, uint32_t hash, void *userp)
> +{
> + last_search = g_list_prepend(last_search, p);
> +}
> +
> +static void count_invalid_tbs(gpointer data, gpointer user_data)
> +{
> + TranslationBlock *tb = (TranslationBlock *) data;
> + unsigned *counter = (unsigned *) user_data;
> + if (tb->cflags & CF_INVALID) {
> + *counter = *counter + 1;
> + }
> +}
> +
> +static int dump_tb_header(TBStatistics *tbs)
> +{
> + unsigned g = stat_per_translation(tbs, code.num_guest_inst);
> + unsigned ops = stat_per_translation(tbs, code.num_tcg_ops);
> + unsigned ops_opt = stat_per_translation(tbs, code.num_tcg_ops_opt);
> + unsigned spills = stat_per_translation(tbs, code.spills);
> + unsigned h = stat_per_translation(tbs, code.out_len);
> + unsigned act = tbs->tbs->len;
> + unsigned invalid = 0;
> +
> + float guest_host_prop = g ? ((float) h / g) : 0;
> +
> + g_ptr_array_foreach(tbs->tbs, &count_invalid_tbs, &invalid);
> +
> + qemu_log("TB id:%d | phys:0x"TB_PAGE_ADDR_FMT" virt:0x"TARGET_FMT_lx
> + " flags:0x%08x %d inv/%d\n",
> + tbs->display_id, tbs->phys_pc, tbs->pc, tbs->flags,
> + invalid, act);
> +
> + if (tbs_stats_enabled(tbs, TB_EXEC_STATS)) {
> + qemu_log("\t| exec:%lu/%lu guest inst cov:%.2f%%\n",
> + tbs->executions.normal,
> + tbs->executions.atomic, tbs->executions.coverage / 100.0f);
> + }
> +
> + if (tbs_stats_enabled(tbs, TB_JIT_STATS)) {
> + qemu_log("\t| trans:%lu ints: g:%u op:%u op_opt:%u spills:%d"
> + "\n\t| h/g (host bytes / guest insts): %f\n",
> + tbs->translations.total, g, ops, ops_opt, spills, guest_host_prop);
> + }
> +
> + if (tbs_stats_enabled(tbs, TB_JIT_TIME)) {
> + qemu_log("\t| time to gen at 2.4GHz => code:%0.2lf(ns) IR:%0.2lf(ns)\n",
> + tbs->gen_times.code / 2.4, tbs->gen_times.ir / 2.4);
> + }
> +
> + qemu_log("\n");
> +
> + return act - invalid;
> +}
> +
> +static gint
> +inverse_sort_tbs(gconstpointer p1, gconstpointer p2, gpointer psort_by)
> +{
> + const TBStatistics *tbs1 = (TBStatistics *) p1;
> + const TBStatistics *tbs2 = (TBStatistics *) p2;
> + int sort_by = *((enum SortBy *) psort_by);
> + unsigned long c1 = 0;
> + unsigned long c2 = 0;
> +
> + if (sort_by == SORT_BY_SPILLS) {
> + c1 = stat_per_translation(tbs1, code.spills);
> + c2 = stat_per_translation(tbs2, code.spills);
> + } else if (sort_by == SORT_BY_HOTNESS) {
> + c1 = stat_per_translation(tbs1, executions.normal);
> + c2 = stat_per_translation(tbs2, executions.normal);
> + } else if (sort_by == SORT_BY_HG) {
> + if (tbs1->code.num_guest_inst == 0) {
> + return -1;
> + }
> + if (tbs2->code.num_guest_inst == 0) {
> + return 1;
> + }
> +
> + c1 = tbs1->code.out_len / tbs1->code.num_guest_inst;
> + c2 = tbs2->code.out_len / tbs2->code.num_guest_inst;
> + }
> + return c1 < c2 ? 1 : c1 == c2 ? 0 : -1;
> +}
> +
> +static void dump_last_search_headers(int count)
> +{
> + if (!last_search) {
> + qemu_log("No data collected yet\n");
> + return;
> + }
> +
> + GList *l = last_search;
> + while (l != NULL && count--) {
> + TBStatistics *tbs = (TBStatistics *) l->data;
> + GList *next = l->next;
> + dump_tb_header(tbs);
> + l = next;
> + }
> +}
> +
> +static uint64_t calculate_last_search_coverages(void)
> +{
> + uint64_t total_exec_count = 0;
> + GList *i;
> +
> + /* Compute total execution count for all tbs */
> + for (i = last_search; i; i = i->next) {
> + TBStatistics *tbs = (TBStatistics *) i->data;
> + total_exec_count +=
> + (tbs->executions.atomic + tbs->executions.normal)
> + * tbs->code.num_guest_inst;
num_guest_inst is sum of all related translations, this looks not what
we want?
> + }
> +
> + for (i = last_search; i; i = i->next) {
> + TBStatistics *tbs = (TBStatistics *) i->data;
> + uint64_t tb_total_execs =
> + (tbs->executions.atomic + tbs->executions.normal)
> + * tbs->code.num_guest_inst;
> + tbs->executions.coverage =
> + (10000 * tb_total_execs) / (total_exec_count + 1);
> + }
> +
> + return total_exec_count;
> +}
> +
> +static void do_dump_tbs_info(int total, int sort_by)
> +{
> + id = 1;
> + GList *i;
> + int count = total;
> +
> + g_list_free(last_search);
> + last_search = NULL;
> +
> + qht_iter(&tb_ctx.tb_stats, collect_tb_stats, NULL);
> +
> + last_search = g_list_sort_with_data(last_search, inverse_sort_tbs,
> + &sort_by);
> +
> + if (!last_search) {
> + qemu_printf("No data collected yet!\n");
> + return;
> + }
> +
> + calculate_last_search_coverages();
> +
> + for (i = last_search; i && count--; i = i->next) {
> + TBStatistics *tbs = (TBStatistics *) i->data;
> + tbs->display_id = id++;
> + }
> +
> + /* free the unused bits */
> + if (i) {
> + if (i->next) {
> + i->next->prev = NULL;
> + }
> + g_list_free(i->next);
> + i->next = NULL;
> + }
> +
> + dump_last_search_headers(total);
> +}
> +
> +struct tbs_dump_info {
> + int count;
> + int sort_by;
> +};
> +
> +static void do_dump_tbs_info_safe(CPUState *cpu, run_on_cpu_data tbdi)
> +{
> + struct tbs_dump_info *info = tbdi.host_ptr;
> + qemu_log_to_monitor(true);
> + do_dump_tbs_info(info->count, info->sort_by);
> + qemu_log_to_monitor(false);
> + g_free(info);
> +}
> +
> +/*
> + * When we dump_tbs_info on a live system via the HMP we want to
> + * ensure the system is quiessent before we start outputting stuff.
> + * Otherwise we could pollute the output with other logging output.
> + */
> +
> +void dump_tbs_info(int count, int sort_by, bool use_monitor)
> +{
> + if (use_monitor) {
> + struct tbs_dump_info *tbdi = g_new(struct tbs_dump_info, 1);
> + tbdi->count = count;
> + tbdi->sort_by = sort_by;
> + async_safe_run_on_cpu(first_cpu, do_dump_tbs_info_safe,
> + RUN_ON_CPU_HOST_PTR(tbdi));
> + } else {
> + do_dump_tbs_info(count, sort_by);
> + }
> +}
> +
> +/*
> + * We cannot always re-generate the code even if we know there are
> + * valid translations still in the cache. The reason being the guest
> + * may have un-mapped the page code. In real life this would be
> + * un-reachable as the jump cache is cleared and the following QHT
> + * lookup will do a get_page_addr_code() and fault.
> + *
> + * TODO: can we do this safely? We need to
> + * a) somehow recover the mmu_idx for this translation
> + * b) probe MMU_INST_FETCH to know it will succeed
> + */
> +static GString *get_code_string(TBStatistics *tbs, int log_flags)
> +{
> + int old_log_flags = qemu_loglevel;
> +
> + CPUState *cpu = first_cpu;
> + uint32_t cflags = curr_cflags(cpu);
> + TranslationBlock *tb = NULL;
> +
> + GString *code_s = g_string_new(NULL);
> + qemu_log_to_string(true, code_s);
> +
> + Error *err = NULL;
> + if (!qemu_set_log(log_flags, &err)) {
> + g_string_append_printf(code_s, "%s", error_get_pretty(err));
> + error_free(err);
> + }
> +
> + if (sigsetjmp(cpu->jmp_env, 0) == 0) {
> + mmap_lock();
> + tb = tb_gen_code(cpu, tbs->pc, tbs->cs_base, tbs->flags, cflags);
> + tb_phys_invalidate(tb, -1);
> + mmap_unlock();
> + } else {
> + /*
> + * The mmap_lock is dropped by tb_gen_code if it runs out of
> + * memory.
> + */
> + qemu_log("\ncould not gen code for this TB (no longer mapped?)\n");
> + assert_no_pages_locked();
> + }
> +
> + qemu_set_log(old_log_flags, &err);
> + qemu_log_to_string(false, NULL);
> +
> + return code_s;
> +}
> +
> +static void do_tb_dump_with_statistics(TBStatistics *tbs, int log_flags)
> +{
> + g_autoptr(GString) code_s = NULL;
> +
> + qemu_log("\n------------------------------\n\n");
> +
> + if (dump_tb_header(tbs) > 0) {
> + code_s = get_code_string(tbs, log_flags);
> + } else {
> + code_s = g_string_new("cannot re-translate non-active translation");
> + }
> + qemu_log("%s", code_s->str);
> + qemu_log("------------------------------\n");
> +}
> +
> +struct tb_dump_info {
> + int id;
> + int log_flags;
> + bool use_monitor;
> +};
> +
> +static void do_dump_tb_info_safe(CPUState *cpu, run_on_cpu_data info)
> +{
> + struct tb_dump_info *tbdi = (struct tb_dump_info *) info.host_ptr;
> +
> + if (!last_search) {
> + qemu_log("no search on record\n");
> + return;
> + }
> +
> + qemu_log_to_monitor(tbdi->use_monitor);
> +
> + TBStatistics *tbs = get_tbstats_by_id(tbdi->id);
> + if (tbs) {
> + do_tb_dump_with_statistics(tbs, tbdi->log_flags);
> + } else {
> + qemu_log("no TB statitics found with id %d\n", tbdi->id);
> + }
> +
The HMP output has some small issues in my tests:
* enter monitor use 'c-a c', start tb-stats then after execution of
(qemu) info tb-list 1
the prompt (qemu) shows before the output instead of after
* enter monitor use 'telnet', the output of 'info tb-list' is not in the
telnet term, but the term starting qemu-system
* 'info tb 1', the addresses and instructions are seperated as follows:
----------------
IN:
Priv: 1; Virt: 0
6422 ld s0,8(sp)0141 addi
sp,sp,168082 ret
0xffffffff8059bca0:
0xffffffff8059bca2:
0xffffffff8059bca4:
------------------------------
Thanks,
Fei.
> + qemu_log_to_monitor(false);
> +
> + g_free(tbdi);
> +}
> +
> +void dump_tb_info(int id, int log_mask, bool use_monitor)
> +{
> + struct tb_dump_info *tbdi = g_new(struct tb_dump_info, 1);
> +
> + tbdi->id = id;
> + tbdi->log_flags = log_mask;
> + tbdi->use_monitor = use_monitor;
> +
> + async_safe_run_on_cpu(first_cpu, do_dump_tb_info_safe,
> + RUN_ON_CPU_HOST_PTR(tbdi));
> +
> + /* tbdi free'd by do_dump_tb_info_safe */
> +}
> +
> +
> void enable_collect_tb_stats(void)
> {
> tcg_collect_tb_stats = TB_STATS_RUNNING;
> diff --git a/disas/disas.c b/disas/disas.c
> index 0d2d06c2ec..6cdd797874 100644
> --- a/disas/disas.c
> +++ b/disas/disas.c
> @@ -8,6 +8,8 @@
> #include "hw/core/cpu.h"
> #include "exec/memory.h"
>
> +#include "qemu/log-for-trace.h"
> +
> /* Filled in by elfload.c. Simplistic, but will do for now. */
> struct syminfo *syminfos = NULL;
>
> @@ -199,6 +201,24 @@ static void initialize_debug_host(CPUDebug *s)
> #endif
> }
>
> +static int
> +__attribute__((format(printf, 2, 3)))
> +fprintf_log(FILE *a, const char *b, ...)
> +{
> + va_list ap;
> + va_start(ap, b);
> +
> + if (!to_string) {
> + vfprintf(a, b, ap);
> + } else {
> + qemu_vlog(b, ap);
> + }
> +
> + va_end(ap);
> +
> + return 1;
> +}
> +
> /* Disassemble this for me please... (debugging). */
> void target_disas(FILE *out, CPUState *cpu, uint64_t code, size_t size)
> {
> @@ -221,9 +241,9 @@ void target_disas(FILE *out, CPUState *cpu, uint64_t code, size_t size)
> }
>
> for (pc = code; size > 0; pc += count, size -= count) {
> - fprintf(out, "0x%08" PRIx64 ": ", pc);
> + fprintf_log(out, "0x%08" PRIx64 ": ", pc);
> count = s.info.print_insn(pc, &s.info);
> - fprintf(out, "\n");
> + fprintf_log(out, "\n");
> if (count < 0) {
> break;
> }
> diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx
> index 47d63d26db..01d9658aea 100644
> --- a/hmp-commands-info.hx
> +++ b/hmp-commands-info.hx
> @@ -262,6 +262,22 @@ ERST
> .params = "",
> .help = "show dynamic compiler info",
> },
> + {
> + .name = "tb-list",
> + .args_type = "number:i?,sortedby:s?",
> + .params = "[number sortedby]",
> + .help = "show a [number] translated blocks sorted by [sortedby]"
> + "sortedby opts: hotness hg spills",
> + .cmd = hmp_info_tblist,
> + },
> + {
> + .name = "tb",
> + .args_type = "id:i,flags:s?",
> + .params = "id [flag1,flag2,...]",
> + .help = "show information about one translated block by id."
> + "dump flags can be used to set dump code level: out_asm in_asm op",
> + .cmd = hmp_info_tb,
> + },
> #endif
>
> SRST
> diff --git a/include/exec/tb-stats.h b/include/exec/tb-stats.h
> index 30b788f7b2..f2a6b09da9 100644
> --- a/include/exec/tb-stats.h
> +++ b/include/exec/tb-stats.h
> @@ -36,8 +36,11 @@
> enum SortBy { SORT_BY_HOTNESS, SORT_BY_HG /* Host/Guest */, SORT_BY_SPILLS };
> enum TbstatsCmd { START, PAUSE, STOP, FILTER };
>
> +#define tbs_stats_enabled(tbs, JIT_STATS) \
> + (tbs && (tbs->stats_enabled & JIT_STATS))
> +
> #define tb_stats_enabled(tb, JIT_STATS) \
> - (tb && tb->tb_stats && (tb->tb_stats->stats_enabled & JIT_STATS))
> + (tb && tb->tb_stats && tbs_stats_enabled(tb->tb_stats, JIT_STATS))
>
> #define stat_per_translation(stat, name) \
> (stat->translations.total ? stat->name / stat->translations.total : 0)
> @@ -66,6 +69,8 @@ struct TBStatistics {
> struct {
> unsigned long normal;
> unsigned long atomic;
> + /* filled only when dumping x% cover set */
> + uint16_t coverage;
> } executions;
>
> /* JIT Stats - protected by lock */
> @@ -88,7 +93,6 @@ struct TBStatistics {
>
> struct {
> unsigned long total;
> - unsigned long uncached;
> unsigned long spanning;
> } translations;
>
> @@ -108,6 +112,9 @@ struct TBStatistics {
> uint64_t la;
> uint64_t code;
> } gen_times;
> +
> + /* HMP information - used for referring to previous search */
> + int display_id;
> };
>
> bool tb_stats_cmp(const void *ap, const void *bp);
> @@ -132,4 +139,26 @@ void do_hmp_tbstats_safe(CPUState *cpu, run_on_cpu_data icmd);
> */
> void tbstats_reset_tbs(void);
>
> +/**
> + * dump_tbs_info: report the hottest blocks
> + *
> + * @count: the limit of hotblocks
> + * @sort_by: property in which the dump will be sorted
> + * @use_monitor: redirect output to monitor
> + *
> + * Report the hottest blocks to either the log or monitor
> + */
> +void dump_tbs_info(int count, int sort_by, bool use_monitor);
> +
> +/**
> + * dump_tb_info: dump information about one TB
> + *
> + * @id: the display id of the block (from previous search)
> + * @mask: the temporary logging mask
> + * @Use_monitor: redirect output to monitor
> + *
> + * Re-run a translation of a block at addr for the purposes of debug output
> + */
> +void dump_tb_info(int id, int log_mask, bool use_monitor);
> +
> #endif
> diff --git a/include/monitor/hmp.h b/include/monitor/hmp.h
> index 2e7f141754..acdd6f1561 100644
> --- a/include/monitor/hmp.h
> +++ b/include/monitor/hmp.h
> @@ -182,5 +182,7 @@ void hmp_boot_set(Monitor *mon, const QDict *qdict);
> void hmp_info_mtree(Monitor *mon, const QDict *qdict);
> void hmp_info_cryptodev(Monitor *mon, const QDict *qdict);
> void hmp_tbstats(Monitor *mon, const QDict *qdict);
> +void hmp_info_tblist(Monitor *mon, const QDict *qdict);
> +void hmp_info_tb(Monitor *mon, const QDict *qdict);
>
> #endif
> diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
> index d47c9cd446..5d0afc56c7 100644
> --- a/include/qemu/log-for-trace.h
> +++ b/include/qemu/log-for-trace.h
> @@ -20,6 +20,9 @@
>
> /* Private global variable, don't use */
> extern int qemu_loglevel;
> +extern bool to_string;
> +
> +extern int32_t max_num_hot_tbs_to_dump;
>
> #define LOG_TRACE (1 << 15)
>
> @@ -30,6 +33,7 @@ static inline bool qemu_loglevel_mask(int mask)
> }
>
> /* main logging function */
> -void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
> +int G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
> +int G_GNUC_PRINTF(1, 0) qemu_vlog(const char *fmt, va_list va);
>
> #endif
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index 6f3b8091cd..26b33151f3 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -85,6 +85,8 @@ extern const QEMULogItem qemu_log_items[];
> bool qemu_set_log(int log_flags, Error **errp);
> bool qemu_set_log_filename(const char *filename, Error **errp);
> bool qemu_set_log_filename_flags(const char *name, int flags, Error **errp);
> +void qemu_log_to_monitor(bool enable);
> +void qemu_log_to_string(bool enable, GString *s);
> void qemu_set_dfilter_ranges(const char *ranges, Error **errp);
> bool qemu_log_in_addr_range(uint64_t addr);
> int qemu_str_to_log_mask(const char *str);
> diff --git a/util/log.c b/util/log.c
> index 7ae471d97c..6477eb5a5f 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -50,6 +50,8 @@ int qemu_loglevel;
> static bool log_per_thread;
> static GArray *debug_regions;
> int32_t max_num_hot_tbs_to_dump;
> +static bool to_monitor;
> +bool to_string;
>
> /* Returns true if qemu_log() will really write somewhere. */
> bool qemu_log_enabled(void)
> @@ -146,19 +148,6 @@ void qemu_log_unlock(FILE *logfile)
> }
> }
>
> -void qemu_log(const char *fmt, ...)
> -{
> - FILE *f = qemu_log_trylock();
> - if (f) {
> - va_list ap;
> -
> - va_start(ap, fmt);
> - vfprintf(f, fmt, ap);
> - va_end(ap);
> - qemu_log_unlock(f);
> - }
> -}
> -
> static void __attribute__((__constructor__)) startup(void)
> {
> qemu_mutex_init(&global_mutex);
> @@ -206,6 +195,55 @@ valid_filename_template(const char *filename, bool per_thread, Error **errp)
> return filename ? vft_strdup : vft_stderr;
> }
>
> +GString *string;
> +
> +int qemu_vlog(const char *fmt, va_list va)
> +{
> + int ret = 0;
> +
> + if (to_string && string) {
> + g_string_append_vprintf(string, fmt, va);
> + } else if (to_monitor) {
> + ret = qemu_vprintf(fmt, va);
> + } else {
> + FILE *f = qemu_log_trylock();
> + if (f) {
> + ret = vfprintf(f, fmt, va);
> + }
> + qemu_log_unlock(f);
> + }
> +
> + /* Don't pass back error results. */
> + if (ret < 0) {
> + ret = 0;
> + }
> + return ret;
> +}
> +
> +/* Return the number of characters emitted. */
> +int qemu_log(const char *fmt, ...)
> +{
> + int ret = 0;
> + va_list ap;
> +
> + va_start(ap, fmt);
> + ret = qemu_vlog(fmt, ap);
> + va_end(ap);
> +
> + return ret;
> +}
> +
> +void qemu_log_to_monitor(bool enable)
> +{
> + to_monitor = enable;
> +}
> +
> +void qemu_log_to_string(bool enable, GString *s)
> +{
> + to_string = enable;
> + string = s;
> +}
> +
> /* enable or disable low levels log */
> static bool qemu_set_log_internal(const char *filename, bool changed_name,
> int log_flags, Error **errp)
> @@ -523,6 +561,7 @@ int qemu_str_to_log_mask(const char *str)
> trace_enable_events((*tmp) + 6);
> mask |= LOG_TRACE;
> #endif
> +#ifdef CONFIG_TCG
> } else if (g_str_has_prefix(*tmp, "tb_stats")) {
> mask |= CPU_LOG_TB_STATS;
> set_default_tbstats_flag(TB_ALL_STATS);
> @@ -553,6 +592,7 @@ int qemu_str_to_log_mask(const char *str)
> }
> set_default_tbstats_flag(flags);
> }
> +#endif
> } else {
> for (item = qemu_log_items; item->mask != 0; item++) {
> if (g_str_equal(*tmp, item->name)) {
© 2016 - 2026 Red Hat, Inc.