| Message ID | 20220204204335.1689602-25-alex.bennee@linaro.org |
|---|---|
| State | Superseded |
| Headers | show |
| Series | testing and plugins pre-PR | expand |
On 4/2/22 21:43, Alex Bennée wrote: > This adds simple instruction matching to the libinsn.so plugin which > is useful for examining the execution distance between instructions. > For example to track how often we flush in ARM due to TLB updates: > > -plugin ./tests/plugin/libinsn.so,match=tlbi > > which leads to output like this: > > 0xffffffc01019a918, 'tlbi vale1is, x1', 5702 hits, 31825 match hits, Δ+8112 since last match, 68859 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5703 hits, 56593 match hits, Δ+17712125 since last match, 33455 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5704 hits, 56594 match hits, Δ+12689 since last match, 33454 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5705 hits, 56595 match hits, Δ+12585 since last match, 33454 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5706 hits, 56596 match hits, Δ+10491 since last match, 33454 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5707 hits, 56597 match hits, Δ+4721 since last match, 33453 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5708 hits, 56598 match hits, Δ+10733 since last match, 33453 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5709 hits, 56599 match hits, Δ+61959 since last match, 33453 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5710 hits, 56600 match hits, Δ+55235 since last match, 33454 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5711 hits, 56601 match hits, Δ+54373 since last match, 33454 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5712 hits, 56602 match hits, Δ+2705 since last match, 33453 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5713 hits, 56603 match hits, Δ+17262 since last match, 33453 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5714 hits, 56604 match hits, Δ+17206 since last match, 33453 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5715 hits, 56605 match hits, Δ+28940 since last match, 33453 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5716 hits, 56606 match hits, Δ+7370 since last match, 33452 avg insns/match > 0xffffffc01019a918, 'tlbi vale1is, x1', 5717 hits, 56607 match hits, Δ+7066 since last match, 33452 avg insns/match > > showing we do some sort of TLBI invalidation every 33 thousand > instructions. > > Cc: Vasilev Oleg <vasilev.oleg@huawei.com> > Cc: Richard Henderson <richard.henderson@linaro.org> > Cc: Emilio Cota <cota@braap.org> > Signed-off-by: Alex Bennée <alex.bennee@linaro.org> > Message-Id: <20220124201608.604599-21-alex.bennee@linaro.org> > > --- > v2 > - quote disassembly > - try and improve formatting > --- > tests/plugin/insn.c | 89 ++++++++++++++++++++++++++++++++++++++++++++- > 1 file changed, 88 insertions(+), 1 deletion(-) > static void vcpu_tb_trans(qemu_plugin_id_t id, struct qemu_plugin_tb *tb) > { > size_t n = qemu_plugin_tb_n_insns(tb); > @@ -71,6 +118,29 @@ static void vcpu_tb_trans(qemu_plugin_id_t id, struct qemu_plugin_tb *tb) > unsigned long *cnt = &g_array_index(sizes, unsigned long, sz); > (*cnt)++; > } > + > + /* > + * If we are tracking certain instructions we will need more > + * information about the instruction which we also need to > + * save if there is a hit. > + */ > + if (matches) { > + char *insn_disas = qemu_plugin_insn_disas(insn); > + int j; > + for (j = 0; j < matches->len; j++) { > + Match *m = &g_array_index(matches, Match, j); > + if (g_str_has_prefix(insn_disas, m->match_string)) { > + Instruction *rec = g_new0(Instruction, 1); Maybe release matches and its Instruction entries in atexit? Otherwise, Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org> > + rec->disas = g_strdup(insn_disas); > + rec->vaddr = qemu_plugin_insn_vaddr(insn); > + rec->match = m; > + qemu_plugin_register_vcpu_insn_exec_cb( > + insn, vcpu_insn_matched_exec_before, > + QEMU_PLUGIN_CB_NO_REGS, rec); > + } > + } > + g_free(insn_disas); > + } > } > }
diff --git a/tests/plugin/insn.c b/tests/plugin/insn.c index d5a0a08cb4..cd5ea5d4ae 100644 --- a/tests/plugin/insn.c +++ b/tests/plugin/insn.c @@ -28,9 +28,25 @@ static uint64_t inline_insn_count; static bool do_inline; static bool do_size; -static bool do_frequency; static GArray *sizes; +typedef struct { + char *match_string; + uint64_t hits[MAX_CPUS]; + uint64_t last_hit[MAX_CPUS]; + uint64_t total_delta[MAX_CPUS]; + GPtrArray *history[MAX_CPUS]; +} Match; + +static GArray *matches; + +typedef struct { + Match *match; + uint64_t vaddr; + uint64_t hits; + char *disas; +} Instruction; + static void vcpu_insn_exec_before(unsigned int cpu_index, void *udata) { unsigned int i = cpu_index % MAX_CPUS; @@ -45,6 +61,37 @@ static void vcpu_insn_exec_before(unsigned int cpu_index, void *udata) c->insn_count++; } +static void vcpu_insn_matched_exec_before(unsigned int cpu_index, void *udata) +{ + unsigned int i = cpu_index % MAX_CPUS; + Instruction *insn = (Instruction *) udata; + Match *match = insn->match; + g_autoptr(GString) ts = g_string_new(""); + + insn->hits++; + g_string_append_printf(ts, "0x%" PRIx64 ", '%s', %"PRId64 " hits", + insn->vaddr, insn->disas, insn->hits); + + uint64_t icount = counts[i].insn_count; + uint64_t delta = icount - match->last_hit[i]; + + match->hits[i]++; + match->total_delta[i] += delta; + + g_string_append_printf(ts, + ", %"PRId64" match hits, " + "Δ+%"PRId64 " since last match," + " %"PRId64 " avg insns/match\n", + match->hits[i], delta, + match->total_delta[i] / match->hits[i]); + + match->last_hit[i] = icount; + + qemu_plugin_outs(ts->str); + + g_ptr_array_add(match->history[i], insn); +} + static void vcpu_tb_trans(qemu_plugin_id_t id, struct qemu_plugin_tb *tb) { size_t n = qemu_plugin_tb_n_insns(tb); @@ -71,6 +118,29 @@ static void vcpu_tb_trans(qemu_plugin_id_t id, struct qemu_plugin_tb *tb) unsigned long *cnt = &g_array_index(sizes, unsigned long, sz); (*cnt)++; } + + /* + * If we are tracking certain instructions we will need more + * information about the instruction which we also need to + * save if there is a hit. + */ + if (matches) { + char *insn_disas = qemu_plugin_insn_disas(insn); + int j; + for (j = 0; j < matches->len; j++) { + Match *m = &g_array_index(matches, Match, j); + if (g_str_has_prefix(insn_disas, m->match_string)) { + Instruction *rec = g_new0(Instruction, 1); + rec->disas = g_strdup(insn_disas); + rec->vaddr = qemu_plugin_insn_vaddr(insn); + rec->match = m; + qemu_plugin_register_vcpu_insn_exec_cb( + insn, vcpu_insn_matched_exec_before, + QEMU_PLUGIN_CB_NO_REGS, rec); + } + } + g_free(insn_disas); + } } } @@ -105,6 +175,21 @@ static void plugin_exit(qemu_plugin_id_t id, void *p) qemu_plugin_outs(out->str); } + +/* Add a match to the array of matches */ +static void parse_match(char *match) +{ + Match new_match = { .match_string = match }; + int i; + for (i = 0; i < MAX_CPUS; i++) { + new_match.history[i] = g_ptr_array_new(); + } + if (!matches) { + matches = g_array_new(false, true, sizeof(Match)); + } + g_array_append_val(matches, new_match); +} + QEMU_PLUGIN_EXPORT int qemu_plugin_install(qemu_plugin_id_t id, const qemu_info_t *info, int argc, char **argv) @@ -122,6 +207,8 @@ QEMU_PLUGIN_EXPORT int qemu_plugin_install(qemu_plugin_id_t id, fprintf(stderr, "boolean argument parsing failed: %s\n", opt); return -1; } + } else if (g_strcmp0(tokens[0], "match") == 0) { + parse_match(tokens[1]); } else { fprintf(stderr, "option parsing failed: %s\n", opt); return -1;
This adds simple instruction matching to the libinsn.so plugin which is useful for examining the execution distance between instructions. For example to track how often we flush in ARM due to TLB updates: -plugin ./tests/plugin/libinsn.so,match=tlbi which leads to output like this: 0xffffffc01019a918, 'tlbi vale1is, x1', 5702 hits, 31825 match hits, Δ+8112 since last match, 68859 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5703 hits, 56593 match hits, Δ+17712125 since last match, 33455 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5704 hits, 56594 match hits, Δ+12689 since last match, 33454 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5705 hits, 56595 match hits, Δ+12585 since last match, 33454 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5706 hits, 56596 match hits, Δ+10491 since last match, 33454 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5707 hits, 56597 match hits, Δ+4721 since last match, 33453 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5708 hits, 56598 match hits, Δ+10733 since last match, 33453 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5709 hits, 56599 match hits, Δ+61959 since last match, 33453 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5710 hits, 56600 match hits, Δ+55235 since last match, 33454 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5711 hits, 56601 match hits, Δ+54373 since last match, 33454 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5712 hits, 56602 match hits, Δ+2705 since last match, 33453 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5713 hits, 56603 match hits, Δ+17262 since last match, 33453 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5714 hits, 56604 match hits, Δ+17206 since last match, 33453 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5715 hits, 56605 match hits, Δ+28940 since last match, 33453 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5716 hits, 56606 match hits, Δ+7370 since last match, 33452 avg insns/match 0xffffffc01019a918, 'tlbi vale1is, x1', 5717 hits, 56607 match hits, Δ+7066 since last match, 33452 avg insns/match showing we do some sort of TLBI invalidation every 33 thousand instructions. Cc: Vasilev Oleg <vasilev.oleg@huawei.com> Cc: Richard Henderson <richard.henderson@linaro.org> Cc: Emilio Cota <cota@braap.org> Signed-off-by: Alex Bennée <alex.bennee@linaro.org> Message-Id: <20220124201608.604599-21-alex.bennee@linaro.org> --- v2 - quote disassembly - try and improve formatting --- tests/plugin/insn.c | 89 ++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 88 insertions(+), 1 deletion(-)