[Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Alex Bennée]

Hi,

This series is a combination of general clean-ups to logging and
tracing and a RFC for extending the tracepoint API by the addition of
plugins. An example usage would be:

  ./aarch64-linux-user/qemu-aarch64 -d plugin,nochain -plugin file=trace/plugins/hotblocks.so,args=5 ./aarch64-linux-user/tests/sha1
  SHA1=15dd99a1991e0b3826fede3deffc1feba42278e6
  trace/plugins/hotblocks.so: collected 858d entries in the hash table
    pc: 0x00000000400260 (64004 hits) 4257 ns between returns
    pc: 0x00000000419280 (64004 hits) 4256 ns between returns
    pc: 0x00000000419290 (64003 hits) 4063 ns between returns
    pc: 0x000000004192d4 (64002 hits) 4063 ns between returns
    pc: 0x000000004192f0 (64002 hits) 4062 ns between returns

After reviewing Pavel's series I wondered if we could re-use the
trace-point API as potential hooks for a plugin API. Trace points
already exist as a series of interesting places in QEMU exposing
information that can be used for analysis. By re-using them we avoid
potential duplication of concerns. Adding new hook points becomes a
simple case of adding a new trace point.

This also allows us to simplify some of the facilities provided to the
plugins. I currently envision two types of plugin:

  Filter plugins

  These are plugins that sit at a trace point and return true/false to
  the trace code. This would short-circuit the trace from continuing,
  essentially filtering out unwanted information. The final data is still
  exported the usual way using trace APIs many output modes.

  Analysis plugins

  These are plugins that aggregate data in real-time to provide some
  sort of analysis as they go. They may or may not pass on the trace
  events to the other trace sub-systems. The example hotblocks plugin
  is such and example.

While the first set up plugins can re-use the existing trace
infrastructure to output information the second type needs a
reporting mechanism. As a result I have added a plugin_status()
function which can either report on the monitor or in linux-user be
called on program exit. In both cases the function simply returns a
string and leaves the details of where it gets output to QEMU itself.

=Further Work=

==Known Limitations==

Currently there is only one hook allowed per trace event. We could
make this more flexible or simply just error out if two plugins try
and hook to the same point. What are the expectations of running
multiple plugins hooking into the same point in QEMU?

==TCG Hooks==

Thanks to Lluís' work the trace API already splits up TCG events into
translation time and exec time events and provides the machinery for
hooking a trace helper into the translation stream. Currently that
helper is unconditionally added although perhaps we could expand the
call convention a little for TCG events to allow the translation time
event to filter out planting the execution time helper?

Any serious analysis tool should allow for us to track all memory
accesses so I think the guest_mem_before trace point should probably
be split into guest_mem_before_store and guest_mem_after_load. We
could go the whole hog and add potential trace points for start/end of
all memory operations.

I did start down this road but the code quickly got ugly when dealing
with our macrofied access functions. I plan to fish out the
de-macrofication of softmmu series I posted earlier this year:

  https://lists.gnu.org/archive/html/qemu-devel/2018-04/msg03403.html

And see if that can be applied to all our access functions.

===Instruction Tracing===

Pavel's series had a specific hook for instrumenting individual
instructions. I have not yet added it to this series but I think it be
done in a slightly cleaner way now we have the ability to insert TCG
ops into the instruction stream. If we add a tracepoint for post
instruction generation which passes a buffer with the instruction
translated and method to insert a helper before or after the
instruction. This would avoid exposing the cpu_ldst macros to the
plugins.

So what do people think? Could this be a viable way to extend QEMU
with plugins?

Alex.


Aaron Lindsay (1):
  trace: add linux-user plugin support

Alex Bennée (19):
  util/log: allow -dfilter to stack
  util/log: add qemu_dfilter_append_range()
  linux-user: add -dfilter progtext shortcut
  trace: enable the exec_tb trace events
  trace: keep a count of trace-point hits
  trace: show trace point counts in the monitor
  accel/tcg/cputlb: convert tlb_flush debugging into trace events
  accel/tcg/cputlb: convert remaining tlb_debug() to trace events
  trace: suppress log output of trace points
  qom/cpu: add a cpu_exit trace event
  trace: expose a plugin fn pointer in TraceEvent
  configure: expose a plugin to the trace-backends
  tracetool: generate plugin snippets
  trace: add infrastructure for building plugins
  hmp: expose status of plugins to the monitor
  linux-user: allow dumping of plugin status at end of run
  plugins: add an example hotblocks plugin
  plugins: add hotness summary to hotblocks
  plugin: add tlbflush stats plugin

Pavel Dovgalyuk (1):
  trace: add support for plugin infrastructure

 Makefile                            |   5 +-
 accel/tcg/cputlb.c                  |  99 +++++-----
 accel/tcg/trace-events              |  30 ++-
 configure                           |   6 +
 hmp-commands-info.hx                |  17 ++
 include/plugins/plugins.h           |  14 ++
 include/qemu/log.h                  |   2 +
 include/qemu/plugins.h              |  19 ++
 linux-user/exit.c                   |  12 ++
 linux-user/main.c                   |  31 ++-
 monitor.c                           |  19 +-
 qapi/trace.json                     |   3 +-
 qemu-options.hx                     |  10 +
 qom/cpu.c                           |   3 +
 qom/trace-events                    |   4 +
 scripts/tracetool/backend/plugin.py |  79 ++++++++
 scripts/tracetool/backend/simple.py |   2 +
 tests/test-logging.c                |  14 ++
 trace/Makefile.objs                 |  25 +++
 trace/control-internal.h            |   6 +
 trace/event-internal.h              |   4 +
 trace/plugins.c                     | 154 +++++++++++++++
 trace/plugins/Makefile.plugins      |  32 ++++
 trace/plugins/hotblocks/hotblocks.c | 100 ++++++++++
 trace/plugins/tlbflush/tlbflush.c   | 283 ++++++++++++++++++++++++++++
 trace/qmp.c                         |   1 +
 util/log.c                          |  34 +++-
 vl.c                                |  26 ++-
 28 files changed, 962 insertions(+), 72 deletions(-)
 create mode 100644 include/plugins/plugins.h
 create mode 100644 include/qemu/plugins.h
 create mode 100644 scripts/tracetool/backend/plugin.py
 create mode 100644 trace/plugins.c
 create mode 100644 trace/plugins/Makefile.plugins
 create mode 100644 trace/plugins/hotblocks/hotblocks.c
 create mode 100644 trace/plugins/tlbflush/tlbflush.c

-- 
2.17.1

[Qemu-devel] [RFC PATCH 01/21] util/log: allow -dfilter to stack

[Alex Bennée]

The original dfilter was patched to avoid a leak in the case of
multiple -dfilter ranges. There is no reason not to allow the user to
stack several dfilter options rather than push them all into one mega
line. We avoid the leak by simply only allocating the first time
around. As we are using a g_array it will automatically re-size as
needed.

The allocation is pushed to a helper as future patches will offer
additional ways to add to the dfilter.

We also add a helper qemu_reset_dfilter_ranges() so we can be explicit
in our unit tests.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 include/qemu/log.h   |  1 +
 tests/test-logging.c | 14 ++++++++++++++
 util/log.c           | 23 +++++++++++++++++------
 3 files changed, 32 insertions(+), 6 deletions(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index b097a6cae1..8ed932ec24 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -116,6 +116,7 @@ void qemu_set_log(int log_flags);
 void qemu_log_needs_buffers(void);
 void qemu_set_log_filename(const char *filename, Error **errp);
 void qemu_set_dfilter_ranges(const char *ranges, Error **errp);
+void qemu_reset_dfilter_ranges(void);
 bool qemu_log_in_addr_range(uint64_t addr);
 int qemu_str_to_log_mask(const char *str);
 
diff --git a/tests/test-logging.c b/tests/test-logging.c
index a12585f70a..fbddd70ebc 100644
--- a/tests/test-logging.c
+++ b/tests/test-logging.c
@@ -43,6 +43,8 @@ static void test_parse_range(void)
     g_assert(qemu_log_in_addr_range(0x10ff));
     g_assert_false(qemu_log_in_addr_range(0x1100));
 
+    qemu_reset_dfilter_ranges();
+
     qemu_set_dfilter_ranges("0x1000-0x100", &error_abort);
 
     g_assert_false(qemu_log_in_addr_range(0x1001));
@@ -50,6 +52,8 @@ static void test_parse_range(void)
     g_assert(qemu_log_in_addr_range(0x0f01));
     g_assert_false(qemu_log_in_addr_range(0x0f00));
 
+    qemu_reset_dfilter_ranges();
+
     qemu_set_dfilter_ranges("0x1000..0x1100", &error_abort);
 
     g_assert_false(qemu_log_in_addr_range(0xfff));
@@ -57,26 +61,36 @@ static void test_parse_range(void)
     g_assert(qemu_log_in_addr_range(0x1100));
     g_assert_false(qemu_log_in_addr_range(0x1101));
 
+    qemu_reset_dfilter_ranges();
+
     qemu_set_dfilter_ranges("0x1000..0x1000", &error_abort);
 
     g_assert_false(qemu_log_in_addr_range(0xfff));
     g_assert(qemu_log_in_addr_range(0x1000));
     g_assert_false(qemu_log_in_addr_range(0x1001));
 
+    qemu_reset_dfilter_ranges();
+
     qemu_set_dfilter_ranges("0x1000+0x100,0x2100-0x100,0x3000..0x3100",
                             &error_abort);
     g_assert(qemu_log_in_addr_range(0x1050));
     g_assert(qemu_log_in_addr_range(0x2050));
     g_assert(qemu_log_in_addr_range(0x3050));
 
+    qemu_reset_dfilter_ranges();
+
     qemu_set_dfilter_ranges("0xffffffffffffffff-1", &error_abort);
     g_assert(qemu_log_in_addr_range(UINT64_MAX));
     g_assert_false(qemu_log_in_addr_range(UINT64_MAX - 1));
 
+    qemu_reset_dfilter_ranges();
+
     qemu_set_dfilter_ranges("0..0xffffffffffffffff", &err);
     g_assert(qemu_log_in_addr_range(0));
     g_assert(qemu_log_in_addr_range(UINT64_MAX));
  
+    qemu_reset_dfilter_ranges();
+
     qemu_set_dfilter_ranges("2..1", &err);
     error_free_or_abort(&err);
 
diff --git a/util/log.c b/util/log.c
index c0dbbd4700..c6c197cbb3 100644
--- a/util/log.c
+++ b/util/log.c
@@ -149,19 +149,30 @@ bool qemu_log_in_addr_range(uint64_t addr)
     }
 }
 
+static void maybe_allocate_dfilter(int size_hint)
+{
+    if (!debug_regions) {
+        debug_regions = g_array_sized_new(FALSE, FALSE,
+                                          sizeof(Range),
+                                          size_hint ? size_hint : 1);
+    }
+}
+
+/* This is only really used for testing, usually dfilter stacks */
+void qemu_reset_dfilter_ranges(void)
+{
+    GArray *old = debug_regions;
+    debug_regions = NULL;
+    g_array_free(old, TRUE);
+}
 
 void qemu_set_dfilter_ranges(const char *filter_spec, Error **errp)
 {
     gchar **ranges = g_strsplit(filter_spec, ",", 0);
     int i;
 
-    if (debug_regions) {
-        g_array_unref(debug_regions);
-        debug_regions = NULL;
-    }
+    maybe_allocate_dfilter(g_strv_length(ranges));
 
-    debug_regions = g_array_sized_new(FALSE, FALSE,
-                                      sizeof(Range), g_strv_length(ranges));
     for (i = 0; ranges[i]; i++) {
         const char *r = ranges[i];
         const char *range_op, *r2, *e;
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 01/21] util/log: allow -dfilter to stack

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> The original dfilter was patched to avoid a leak in the case of
> multiple -dfilter ranges. There is no reason not to allow the user to
> stack several dfilter options rather than push them all into one mega
> line. We avoid the leak by simply only allocating the first time
> around. As we are using a g_array it will automatically re-size as
> needed.
> 
> The allocation is pushed to a helper as future patches will offer
> additional ways to add to the dfilter.
> 
> We also add a helper qemu_reset_dfilter_ranges() so we can be explicit
> in our unit tests.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  include/qemu/log.h   |  1 +
>  tests/test-logging.c | 14 ++++++++++++++
>  util/log.c           | 23 +++++++++++++++++------
>  3 files changed, 32 insertions(+), 6 deletions(-)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>


r~

[Qemu-devel] [RFC PATCH 02/21] util/log: add qemu_dfilter_append_range()

[Alex Bennée]

This allows us to add to the dfilter range as we go.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 include/qemu/log.h | 1 +
 util/log.c         | 6 ++++++
 2 files changed, 7 insertions(+)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index 8ed932ec24..f915b5bd91 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -117,6 +117,7 @@ void qemu_log_needs_buffers(void);
 void qemu_set_log_filename(const char *filename, Error **errp);
 void qemu_set_dfilter_ranges(const char *ranges, Error **errp);
 void qemu_reset_dfilter_ranges(void);
+void qemu_append_dfilter_range(Range r, 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 c6c197cbb3..cc79a146d1 100644
--- a/util/log.c
+++ b/util/log.c
@@ -233,6 +233,12 @@ out:
     g_strfreev(ranges);
 }
 
+void qemu_append_dfilter_range(Range r, Error **errp)
+{
+    maybe_allocate_dfilter(1);
+    g_array_append_val(debug_regions, r);
+}
+
 /* fflush() the log file */
 void qemu_log_flush(void)
 {
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 02/21] util/log: add qemu_dfilter_append_range()

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> This allows us to add to the dfilter range as we go.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  include/qemu/log.h | 1 +
>  util/log.c         | 6 ++++++
>  2 files changed, 7 insertions(+)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>


r~

[Qemu-devel] [RFC PATCH 03/21] linux-user: add -dfilter progtext shortcut

[Alex Bennée]

When debugging you often don't care about the libraries but just the
code in the testcase. Rather than make the user build this by hand
offer a shortcut.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Laurent Vivier <laurent@vivier.eu>
---
 linux-user/main.c | 16 +++++++++++++++-
 1 file changed, 15 insertions(+), 1 deletion(-)

diff --git a/linux-user/main.c b/linux-user/main.c
index 923cbb753a..a68674d0de 100644
--- a/linux-user/main.c
+++ b/linux-user/main.c
@@ -28,6 +28,7 @@
 #include "qemu/config-file.h"
 #include "qemu/cutils.h"
 #include "qemu/help_option.h"
+#include "qemu/range.h"
 #include "cpu.h"
 #include "exec/exec-all.h"
 #include "tcg.h"
@@ -51,6 +52,8 @@ unsigned long mmap_min_addr;
 unsigned long guest_base;
 int have_guest_base;
 
+static bool dfilter_progtext;
+
 /*
  * When running 32-on-64 we should make sure we can fit all of the possible
  * guest address space into a contiguous chunk of virtual host memory.
@@ -222,6 +225,11 @@ static void handle_arg_log(const char *arg)
 
 static void handle_arg_dfilter(const char *arg)
 {
+    if (strcmp(arg, "progtext") == 0) {
+        dfilter_progtext = true;
+        return;
+    }
+
     qemu_set_dfilter_ranges(arg, NULL);
 }
 
@@ -423,7 +431,7 @@ static const struct qemu_argument arg_table[] = {
      "item[,...]", "enable logging of specified items "
      "(use '-d help' for a list of items)"},
     {"dfilter",    "QEMU_DFILTER",     true,  handle_arg_dfilter,
-     "range[,...]","filter logging based on address range"},
+     "range|progtext[,...]", "filter logging based on address range"},
     {"D",          "QEMU_LOG_FILENAME", true, handle_arg_log_filename,
      "logfile",     "write logs to 'logfile' (default stderr)"},
     {"p",          "QEMU_PAGESIZE",    true,  handle_arg_pagesize,
@@ -796,6 +804,12 @@ int main(int argc, char **argv, char **envp)
         qemu_log("auxv_start  0x" TARGET_ABI_FMT_lx "\n", info->saved_auxv);
     }
 
+    if (dfilter_progtext) {
+        Range r;
+        range_set_bounds(&r, info->start_code, info->end_code);
+        qemu_append_dfilter_range(r, NULL);
+    }
+
     target_set_brk(info->brk);
     syscall_init();
     signal_init();
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 03/21] linux-user: add -dfilter progtext shortcut

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> When debugging you often don't care about the libraries but just the
> code in the testcase. Rather than make the user build this by hand
> offer a shortcut.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> Reviewed-by: Laurent Vivier <laurent@vivier.eu>
> ---
>  linux-user/main.c | 16 +++++++++++++++-
>  1 file changed, 15 insertions(+), 1 deletion(-)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>


r~

[Qemu-devel] [RFC PATCH 04/21] trace: enable the exec_tb trace events

[Alex Bennée]

Our performance isn't so critical that we can't spare a simple flag
check when we exec a TB considering everything else we check in the
outer loop.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 accel/tcg/trace-events | 9 +++++----
 1 file changed, 5 insertions(+), 4 deletions(-)

diff --git a/accel/tcg/trace-events b/accel/tcg/trace-events
index c22ad60af7..618cc07738 100644
--- a/accel/tcg/trace-events
+++ b/accel/tcg/trace-events
@@ -1,10 +1,11 @@
 # Trace events for debugging and performance instrumentation
 
-# TCG related tracing (mostly disabled by default)
+# TCG related tracing (you still need -d nochain to get a full picture
+# as otherwise you'll only see the first TB executed in a chain)
 # cpu-exec.c
-disable exec_tb(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
-disable exec_tb_nocache(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
-disable exec_tb_exit(void *last_tb, unsigned int flags) "tb:%p flags=0x%x"
+exec_tb(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
+exec_tb_nocache(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
+exec_tb_exit(void *last_tb, unsigned int flags) "tb:%p flags=0x%x"
 
 # translate-all.c
 translate_block(void *tb, uintptr_t pc, uint8_t *tb_code) "tb:%p, pc:0x%"PRIxPTR", tb_code:%p"
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 04/21] trace: enable the exec_tb trace events

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> Our performance isn't so critical that we can't spare a simple flag
> check when we exec a TB considering everything else we check in the
> outer loop.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  accel/tcg/trace-events | 9 +++++----
>  1 file changed, 5 insertions(+), 4 deletions(-)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>


r~

Re: [Qemu-devel] [RFC PATCH 04/21] trace: enable the exec_tb trace events

[Emilio G. Cota]

On Fri, Oct 05, 2018 at 16:48:53 +0100, Alex Bennée wrote:
> Our performance isn't so critical that we can't spare a simple flag
> check when we exec a TB considering everything else we check in the
> outer loop.

[I know this is just done to illustrate how function names
in plugins can bind to tracing calls, but someone might
get confused by expecting more from "exec_tb" than it
actually does.]

This flag check costs nothing because "exec_tb" is
almost never called. The way it works right now, we
need -d nochain for "exec_tb" to actually generate
an event every time a TB executes.

IMO an eventual plugin API should let plugins decide whether
to subscribe to the execution of a particular TB, when
said TB is being translated, instead of providing
an all-or-nothing switch.

Thanks,

		E.

Re: [Qemu-devel] [RFC PATCH 04/21] trace: enable the exec_tb trace events

[Alex Bennée]

Emilio G. Cota <cota@braap.org> writes:

> On Fri, Oct 05, 2018 at 16:48:53 +0100, Alex Bennée wrote:
>> Our performance isn't so critical that we can't spare a simple flag
>> check when we exec a TB considering everything else we check in the
>> outer loop.
>
> [I know this is just done to illustrate how function names
> in plugins can bind to tracing calls, but someone might
> get confused by expecting more from "exec_tb" than it
> actually does.]
>
> This flag check costs nothing because "exec_tb" is
> almost never called. The way it works right now, we
> need -d nochain for "exec_tb" to actually generate
> an event every time a TB executes.

I'll reword the commit a bit.

> IMO an eventual plugin API should let plugins decide whether
> to subscribe to the execution of a particular TB, when
> said TB is being translated, instead of providing
> an all-or-nothing switch.

Well we will want pre/post instruction translation hooks which would be
the obvious place to add this. Using -d nochain is a useful enough hack
for now.

>
> Thanks,
>
> 		E.


--
Alex Bennée

[Qemu-devel] [RFC PATCH 05/21] trace: keep a count of trace-point hits

[Alex Bennée]

When working via the HMP to dynamically enable trace points it would
be useful to know if trace points are currently being hit. As the cost
is low we can simply increment a counter as we consider if we are
going to trace the event.

This cannot be precise as we don't take care to use atomic accesses
but it is usefully indicative.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 scripts/tracetool/backend/simple.py | 2 ++
 trace/event-internal.h              | 1 +
 2 files changed, 3 insertions(+)

diff --git a/scripts/tracetool/backend/simple.py b/scripts/tracetool/backend/simple.py
index c2fd1c24c4..eaa19a1032 100644
--- a/scripts/tracetool/backend/simple.py
+++ b/scripts/tracetool/backend/simple.py
@@ -81,6 +81,8 @@ def generate_c(event, group):
         cond = "trace_event_get_state(%s)" % event_id
 
     out('',
+        '    %(event_obj)s.count++;',
+        '',
         '    if (!%(cond)s) {',
         '        return;',
         '    }',
diff --git a/trace/event-internal.h b/trace/event-internal.h
index f63500b37e..8ab3a29941 100644
--- a/trace/event-internal.h
+++ b/trace/event-internal.h
@@ -37,6 +37,7 @@ typedef struct TraceEvent {
     const char * name;
     const bool sstate;
     uint16_t *dstate;
+    uint64_t count;
 } TraceEvent;
 
 void trace_event_set_state_dynamic_init(TraceEvent *ev, bool state);
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 05/21] trace: keep a count of trace-point hits

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> @@ -81,6 +81,8 @@ def generate_c(event, group):
>          cond = "trace_event_get_state(%s)" % event_id
>  
>      out('',
> +        '    %(event_obj)s.count++;',
> +        '',
>          '    if (!%(cond)s) {',
>          '        return;',
>          '    }',

Is it really "hit" if the condition isn't true?  And you'd want to document the
non-atomicity in a comment, lest it be "fixed" later.


r~

[Qemu-devel] [RFC PATCH 06/21] trace: show trace point counts in the monitor

[Alex Bennée]

Now we have counts for each trace point we can expose them in the
monitor when the user queries what trace points are available.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 monitor.c       | 5 +++--
 qapi/trace.json | 3 ++-
 trace/qmp.c     | 1 +
 3 files changed, 6 insertions(+), 3 deletions(-)

diff --git a/monitor.c b/monitor.c
index c4677b502b..d8229cd2b0 100644
--- a/monitor.c
+++ b/monitor.c
@@ -1421,9 +1421,10 @@ static void hmp_info_trace_events(Monitor *mon, const QDict *qdict)
     }
 
     for (elem = events; elem != NULL; elem = elem->next) {
-        monitor_printf(mon, "%s : state %u\n",
+        monitor_printf(mon, "%s : state %u count %" PRIu64 "\n",
                        elem->value->name,
-                       elem->value->state == TRACE_EVENT_STATE_ENABLED ? 1 : 0);
+                       elem->value->state == TRACE_EVENT_STATE_ENABLED ? 1 : 0,
+                       elem->value->count);
     }
     qapi_free_TraceEventInfoList(events);
 }
diff --git a/qapi/trace.json b/qapi/trace.json
index 799b254a18..b9184b0d18 100644
--- a/qapi/trace.json
+++ b/qapi/trace.json
@@ -33,6 +33,7 @@
 # @name: Event name.
 # @state: Tracing state.
 # @vcpu: Whether this is a per-vCPU event (since 2.7).
+# @count: Current hits on trace-point (since 3.1).
 #
 # An event is per-vCPU if it has the "vcpu" property in the "trace-events"
 # files.
@@ -40,7 +41,7 @@
 # Since: 2.2
 ##
 { 'struct': 'TraceEventInfo',
-  'data': {'name': 'str', 'state': 'TraceEventState', 'vcpu': 'bool'} }
+  'data': {'name': 'str', 'state': 'TraceEventState', 'vcpu': 'bool', 'count': 'int' } }
 
 ##
 # @trace-event-get-state:
diff --git a/trace/qmp.c b/trace/qmp.c
index ea99b00956..cce8198091 100644
--- a/trace/qmp.c
+++ b/trace/qmp.c
@@ -102,6 +102,7 @@ TraceEventInfoList *qmp_trace_event_get_state(const char *name,
         elem->value = g_new(TraceEventInfo, 1);
         elem->value->vcpu = is_vcpu;
         elem->value->name = g_strdup(trace_event_get_name(ev));
+        elem->value->count = ev->count;
 
         if (!trace_event_get_state_static(ev)) {
             elem->value->state = TRACE_EVENT_STATE_UNAVAILABLE;
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 06/21] trace: show trace point counts in the monitor

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> Now we have counts for each trace point we can expose them in the
> monitor when the user queries what trace points are available.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  monitor.c       | 5 +++--
>  qapi/trace.json | 3 ++-
>  trace/qmp.c     | 1 +
>  3 files changed, 6 insertions(+), 3 deletions(-)

I would have merged this with previous, but whatever.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org>


r~

Re: [Qemu-devel] [RFC PATCH 06/21] trace: show trace point counts in the monitor

[Markus Armbruster]

Alex Bennée <alex.bennee@linaro.org> writes:

> Now we have counts for each trace point we can expose them in the
> monitor when the user queries what trace points are available.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  monitor.c       | 5 +++--
>  qapi/trace.json | 3 ++-
>  trace/qmp.c     | 1 +
>  3 files changed, 6 insertions(+), 3 deletions(-)
>
> diff --git a/monitor.c b/monitor.c
> index c4677b502b..d8229cd2b0 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -1421,9 +1421,10 @@ static void hmp_info_trace_events(Monitor *mon, const QDict *qdict)
>      }
>  
>      for (elem = events; elem != NULL; elem = elem->next) {
> -        monitor_printf(mon, "%s : state %u\n",
> +        monitor_printf(mon, "%s : state %u count %" PRIu64 "\n",
>                         elem->value->name,
> -                       elem->value->state == TRACE_EVENT_STATE_ENABLED ? 1 : 0);
> +                       elem->value->state == TRACE_EVENT_STATE_ENABLED ? 1 : 0,
> +                       elem->value->count);
>      }
>      qapi_free_TraceEventInfoList(events);
>  }
> diff --git a/qapi/trace.json b/qapi/trace.json
> index 799b254a18..b9184b0d18 100644
> --- a/qapi/trace.json
> +++ b/qapi/trace.json
> @@ -33,6 +33,7 @@
>  # @name: Event name.
>  # @state: Tracing state.
>  # @vcpu: Whether this is a per-vCPU event (since 2.7).
> +# @count: Current hits on trace-point (since 3.1).

Suggest something like "Number of hits".

>  #
>  # An event is per-vCPU if it has the "vcpu" property in the "trace-events"
>  # files.
> @@ -40,7 +41,7 @@
>  # Since: 2.2
>  ##
>  { 'struct': 'TraceEventInfo',
> -  'data': {'name': 'str', 'state': 'TraceEventState', 'vcpu': 'bool'} }
> +  'data': {'name': 'str', 'state': 'TraceEventState', 'vcpu': 'bool', 'count': 'int' } }
>  
>  ##
>  # @trace-event-get-state:
> diff --git a/trace/qmp.c b/trace/qmp.c
> index ea99b00956..cce8198091 100644
> --- a/trace/qmp.c
> +++ b/trace/qmp.c
> @@ -102,6 +102,7 @@ TraceEventInfoList *qmp_trace_event_get_state(const char *name,
>          elem->value = g_new(TraceEventInfo, 1);
>          elem->value->vcpu = is_vcpu;
>          elem->value->name = g_strdup(trace_event_get_name(ev));
> +        elem->value->count = ev->count;

I suspect this converts from uint64_t to int64_t.  Change the type to
'uint64' in the QAPI schema?

>  
>          if (!trace_event_get_state_static(ev)) {
>              elem->value->state = TRACE_EVENT_STATE_UNAVAILABLE;

Re: [Qemu-devel] [RFC PATCH 06/21] trace: show trace point counts in the monitor

[Dr. David Alan Gilbert]

* Alex Bennée (alex.bennee@linaro.org) wrote:
> Now we have counts for each trace point we can expose them in the
> monitor when the user queries what trace points are available.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>

> ---
>  monitor.c       | 5 +++--
>  qapi/trace.json | 3 ++-
>  trace/qmp.c     | 1 +
>  3 files changed, 6 insertions(+), 3 deletions(-)
> 
> diff --git a/monitor.c b/monitor.c
> index c4677b502b..d8229cd2b0 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -1421,9 +1421,10 @@ static void hmp_info_trace_events(Monitor *mon, const QDict *qdict)
>      }
>  
>      for (elem = events; elem != NULL; elem = elem->next) {
> -        monitor_printf(mon, "%s : state %u\n",
> +        monitor_printf(mon, "%s : state %u count %" PRIu64 "\n",
>                         elem->value->name,
> -                       elem->value->state == TRACE_EVENT_STATE_ENABLED ? 1 : 0);
> +                       elem->value->state == TRACE_EVENT_STATE_ENABLED ? 1 : 0,
> +                       elem->value->count);
>      }
>      qapi_free_TraceEventInfoList(events);
>  }
> diff --git a/qapi/trace.json b/qapi/trace.json
> index 799b254a18..b9184b0d18 100644
> --- a/qapi/trace.json
> +++ b/qapi/trace.json
> @@ -33,6 +33,7 @@
>  # @name: Event name.
>  # @state: Tracing state.
>  # @vcpu: Whether this is a per-vCPU event (since 2.7).
> +# @count: Current hits on trace-point (since 3.1).
>  #
>  # An event is per-vCPU if it has the "vcpu" property in the "trace-events"
>  # files.
> @@ -40,7 +41,7 @@
>  # Since: 2.2
>  ##
>  { 'struct': 'TraceEventInfo',
> -  'data': {'name': 'str', 'state': 'TraceEventState', 'vcpu': 'bool'} }
> +  'data': {'name': 'str', 'state': 'TraceEventState', 'vcpu': 'bool', 'count': 'int' } }
>  
>  ##
>  # @trace-event-get-state:
> diff --git a/trace/qmp.c b/trace/qmp.c
> index ea99b00956..cce8198091 100644
> --- a/trace/qmp.c
> +++ b/trace/qmp.c
> @@ -102,6 +102,7 @@ TraceEventInfoList *qmp_trace_event_get_state(const char *name,
>          elem->value = g_new(TraceEventInfo, 1);
>          elem->value->vcpu = is_vcpu;
>          elem->value->name = g_strdup(trace_event_get_name(ev));
> +        elem->value->count = ev->count;
>  
>          if (!trace_event_get_state_static(ev)) {
>              elem->value->state = TRACE_EVENT_STATE_UNAVAILABLE;
> -- 
> 2.17.1
> 
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

[Qemu-devel] [RFC PATCH 07/21] accel/tcg/cputlb: convert tlb_flush debugging into trace events

[Alex Bennée]

Given the range of costs for various SoftMMU TLB operations from
deferring work for the currently running vCPU to bring the whole
emulated machine to a stop for synchronised updates simple counters
are less useful. Instead we log events via the trace infrastructure
and we can then post-process the data in a range of ways.

  tlb_flush_self - the vCPU flushed its own TLB
  tlb_flush_async_schedule - work was scheduled and the vCPU kicked
  tlb_flush_synced_schedule - exclusive work was scheduled on a vCPU
  tlb_flush_work - scheduled work was done
  tlb_flush_work_complete - scheduled work was completed

We can use the difference between the work being scheduled and
tlb_flush_work to calculate the latency introduced.

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

---
v2
  - add tlb_flush_work_completed
  - removed tlb_debugs at the same time
---
 accel/tcg/cputlb.c     | 72 ++++++++++++++++++++++++------------------
 accel/tcg/trace-events | 16 ++++++++++
 2 files changed, 58 insertions(+), 30 deletions(-)

diff --git a/accel/tcg/cputlb.c b/accel/tcg/cputlb.c
index f4702ce91f..f1d4f7da44 100644
--- a/accel/tcg/cputlb.c
+++ b/accel/tcg/cputlb.c
@@ -20,6 +20,7 @@
 #include "qemu/osdep.h"
 #include "qemu/main-loop.h"
 #include "cpu.h"
+#include "trace.h"
 #include "exec/exec-all.h"
 #include "exec/memory.h"
 #include "exec/address-spaces.h"
@@ -138,7 +139,9 @@ static void tlb_flush_nocheck(CPUState *cpu)
 
 static void tlb_flush_global_async_work(CPUState *cpu, run_on_cpu_data data)
 {
+    trace_tlb_flush_all_work(cpu->cpu_index);
     tlb_flush_nocheck(cpu);
+    trace_tlb_flush_work_complete(__LINE__, cpu->cpu_index);
 }
 
 void tlb_flush(CPUState *cpu)
@@ -146,17 +149,22 @@ void tlb_flush(CPUState *cpu)
     if (cpu->created && !qemu_cpu_is_self(cpu)) {
         if (atomic_mb_read(&cpu->pending_tlb_flush) != ALL_MMUIDX_BITS) {
             atomic_mb_set(&cpu->pending_tlb_flush, ALL_MMUIDX_BITS);
+            trace_tlb_flush_async_schedule(__LINE__, current_cpu ?
+                                           current_cpu->cpu_index :
+                                           cpu->cpu_index, cpu->cpu_index);
             async_run_on_cpu(cpu, tlb_flush_global_async_work,
                              RUN_ON_CPU_NULL);
         }
     } else {
-        tlb_flush_nocheck(cpu);
+        trace_tlb_flush_self(__LINE__, cpu->cpu_index);
+        tlb_flush_global_async_work(cpu, RUN_ON_CPU_NULL);
     }
 }
 
 void tlb_flush_all_cpus(CPUState *src_cpu)
 {
     const run_on_cpu_func fn = tlb_flush_global_async_work;
+    trace_tlb_flush_async_schedule(__LINE__, src_cpu->cpu_index, -1);
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_NULL);
     fn(src_cpu, RUN_ON_CPU_NULL);
 }
@@ -164,6 +172,7 @@ void tlb_flush_all_cpus(CPUState *src_cpu)
 void tlb_flush_all_cpus_synced(CPUState *src_cpu)
 {
     const run_on_cpu_func fn = tlb_flush_global_async_work;
+    trace_tlb_flush_synced_schedule(__LINE__, src_cpu->cpu_index, -1);
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_NULL);
     async_safe_run_on_cpu(src_cpu, fn, RUN_ON_CPU_NULL);
 }
@@ -174,15 +183,12 @@ static void tlb_flush_by_mmuidx_async_work(CPUState *cpu, run_on_cpu_data data)
     unsigned long mmu_idx_bitmask = data.host_int;
     int mmu_idx;
 
-    assert_cpu_is_self(cpu);
+    trace_tlb_flush_work(__LINE__, cpu->cpu_index, mmu_idx_bitmask);
 
-    tlb_debug("start: mmu_idx:0x%04lx\n", mmu_idx_bitmask);
+    assert_cpu_is_self(cpu);
 
     for (mmu_idx = 0; mmu_idx < NB_MMU_MODES; mmu_idx++) {
-
         if (test_bit(mmu_idx, &mmu_idx_bitmask)) {
-            tlb_debug("%d\n", mmu_idx);
-
             memset(env->tlb_table[mmu_idx], -1, sizeof(env->tlb_table[0]));
             memset(env->tlb_v_table[mmu_idx], -1, sizeof(env->tlb_v_table[0]));
         }
@@ -190,25 +196,26 @@ static void tlb_flush_by_mmuidx_async_work(CPUState *cpu, run_on_cpu_data data)
 
     cpu_tb_jmp_cache_clear(cpu);
 
-    tlb_debug("done\n");
+    trace_tlb_flush_work_complete(__LINE__, cpu->cpu_index);
 }
 
 void tlb_flush_by_mmuidx(CPUState *cpu, uint16_t idxmap)
 {
-    tlb_debug("mmu_idx: 0x%" PRIx16 "\n", idxmap);
-
     if (!qemu_cpu_is_self(cpu)) {
         uint16_t pending_flushes = idxmap;
         pending_flushes &= ~atomic_mb_read(&cpu->pending_tlb_flush);
 
         if (pending_flushes) {
-            tlb_debug("reduced mmu_idx: 0x%" PRIx16 "\n", pending_flushes);
+            trace_tlb_flush_async_schedule(__LINE__,
+                                           current_cpu->cpu_index,
+                                           cpu->cpu_index);
 
             atomic_or(&cpu->pending_tlb_flush, pending_flushes);
             async_run_on_cpu(cpu, tlb_flush_by_mmuidx_async_work,
                              RUN_ON_CPU_HOST_INT(pending_flushes));
         }
     } else {
+        trace_tlb_flush_self(__LINE__, cpu->cpu_index);
         tlb_flush_by_mmuidx_async_work(cpu,
                                        RUN_ON_CPU_HOST_INT(idxmap));
     }
@@ -218,7 +225,7 @@ void tlb_flush_by_mmuidx_all_cpus(CPUState *src_cpu, uint16_t idxmap)
 {
     const run_on_cpu_func fn = tlb_flush_by_mmuidx_async_work;
 
-    tlb_debug("mmu_idx: 0x%"PRIx16"\n", idxmap);
+    trace_tlb_flush_async_schedule(__LINE__, src_cpu->cpu_index, -1);
 
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_HOST_INT(idxmap));
     fn(src_cpu, RUN_ON_CPU_HOST_INT(idxmap));
@@ -229,7 +236,7 @@ void tlb_flush_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
 {
     const run_on_cpu_func fn = tlb_flush_by_mmuidx_async_work;
 
-    tlb_debug("mmu_idx: 0x%"PRIx16"\n", idxmap);
+    trace_tlb_flush_synced_schedule(__LINE__, src_cpu->cpu_index, -1);
 
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_HOST_INT(idxmap));
     async_safe_run_on_cpu(src_cpu, fn, RUN_ON_CPU_HOST_INT(idxmap));
@@ -268,14 +275,10 @@ static void tlb_flush_page_async_work(CPUState *cpu, run_on_cpu_data data)
 
     assert_cpu_is_self(cpu);
 
-    tlb_debug("page :" TARGET_FMT_lx "\n", addr);
+    trace_tlb_flush_work(__LINE__, cpu->cpu_index, addr);
 
     /* Check if we need to flush due to large pages.  */
     if ((addr & env->tlb_flush_mask) == env->tlb_flush_addr) {
-        tlb_debug("forcing full flush ("
-                  TARGET_FMT_lx "/" TARGET_FMT_lx ")\n",
-                  env->tlb_flush_addr, env->tlb_flush_mask);
-
         tlb_flush(cpu);
         return;
     }
@@ -288,16 +291,19 @@ static void tlb_flush_page_async_work(CPUState *cpu, run_on_cpu_data data)
     }
 
     tb_flush_jmp_cache(cpu, addr);
+
+    trace_tlb_flush_work_complete(__LINE__, cpu->cpu_index);
 }
 
 void tlb_flush_page(CPUState *cpu, target_ulong addr)
 {
-    tlb_debug("page :" TARGET_FMT_lx "\n", addr);
-
     if (!qemu_cpu_is_self(cpu)) {
+        trace_tlb_flush_async_schedule(__LINE__, current_cpu->cpu_index,
+                                       cpu->cpu_index);
         async_run_on_cpu(cpu, tlb_flush_page_async_work,
                          RUN_ON_CPU_TARGET_PTR(addr));
     } else {
+        trace_tlb_flush_self(__LINE__, cpu->cpu_index);
         tlb_flush_page_async_work(cpu, RUN_ON_CPU_TARGET_PTR(addr));
     }
 }
@@ -319,8 +325,7 @@ static void tlb_flush_page_by_mmuidx_async_work(CPUState *cpu,
 
     assert_cpu_is_self(cpu);
 
-    tlb_debug("page:%d addr:"TARGET_FMT_lx" mmu_idx:0x%lx\n",
-              page, addr, mmu_idx_bitmap);
+    trace_tlb_flush_work(__LINE__, cpu->cpu_index, addr_and_mmuidx);
 
     for (mmu_idx = 0; mmu_idx < NB_MMU_MODES; mmu_idx++) {
         if (test_bit(mmu_idx, &mmu_idx_bitmap)) {
@@ -330,6 +335,8 @@ static void tlb_flush_page_by_mmuidx_async_work(CPUState *cpu,
     }
 
     tb_flush_jmp_cache(cpu, addr);
+
+    trace_tlb_flush_work_complete(__LINE__, cpu->cpu_index);
 }
 
 static void tlb_check_page_and_flush_by_mmuidx_async_work(CPUState *cpu,
@@ -340,35 +347,36 @@ static void tlb_check_page_and_flush_by_mmuidx_async_work(CPUState *cpu,
     target_ulong addr = addr_and_mmuidx & TARGET_PAGE_MASK;
     unsigned long mmu_idx_bitmap = addr_and_mmuidx & ALL_MMUIDX_BITS;
 
-    tlb_debug("addr:"TARGET_FMT_lx" mmu_idx: %04lx\n", addr, mmu_idx_bitmap);
+    trace_tlb_flush_work(__LINE__, cpu->cpu_index, addr_and_mmuidx);
 
     /* Check if we need to flush due to large pages.  */
     if ((addr & env->tlb_flush_mask) == env->tlb_flush_addr) {
-        tlb_debug("forced full flush ("
-                  TARGET_FMT_lx "/" TARGET_FMT_lx ")\n",
-                  env->tlb_flush_addr, env->tlb_flush_mask);
-
+        trace_tlb_flush_self(__LINE__, cpu->cpu_index);
         tlb_flush_by_mmuidx_async_work(cpu,
                                        RUN_ON_CPU_HOST_INT(mmu_idx_bitmap));
     } else {
+        trace_tlb_flush_self(__LINE__, cpu->cpu_index);
         tlb_flush_page_by_mmuidx_async_work(cpu, data);
     }
+
+    trace_tlb_flush_work_complete(__LINE__, cpu->cpu_index);
 }
 
 void tlb_flush_page_by_mmuidx(CPUState *cpu, target_ulong addr, uint16_t idxmap)
 {
     target_ulong addr_and_mmu_idx;
 
-    tlb_debug("addr: "TARGET_FMT_lx" mmu_idx:%" PRIx16 "\n", addr, idxmap);
-
     /* This should already be page aligned */
     addr_and_mmu_idx = addr & TARGET_PAGE_MASK;
     addr_and_mmu_idx |= idxmap;
 
     if (!qemu_cpu_is_self(cpu)) {
+        trace_tlb_flush_async_schedule(__LINE__, current_cpu->cpu_index,
+                                       cpu->cpu_index);
         async_run_on_cpu(cpu, tlb_check_page_and_flush_by_mmuidx_async_work,
                          RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
     } else {
+        trace_tlb_flush_self(__LINE__, cpu->cpu_index);
         tlb_check_page_and_flush_by_mmuidx_async_work(
             cpu, RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
     }
@@ -380,7 +388,7 @@ void tlb_flush_page_by_mmuidx_all_cpus(CPUState *src_cpu, target_ulong addr,
     const run_on_cpu_func fn = tlb_check_page_and_flush_by_mmuidx_async_work;
     target_ulong addr_and_mmu_idx;
 
-    tlb_debug("addr: "TARGET_FMT_lx" mmu_idx:%"PRIx16"\n", addr, idxmap);
+    trace_tlb_flush_async_schedule(__LINE__, src_cpu->cpu_index, -1);
 
     /* This should already be page aligned */
     addr_and_mmu_idx = addr & TARGET_PAGE_MASK;
@@ -397,7 +405,7 @@ void tlb_flush_page_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
     const run_on_cpu_func fn = tlb_check_page_and_flush_by_mmuidx_async_work;
     target_ulong addr_and_mmu_idx;
 
-    tlb_debug("addr: "TARGET_FMT_lx" mmu_idx:%"PRIx16"\n", addr, idxmap);
+    trace_tlb_flush_synced_schedule(__LINE__, src_cpu->cpu_index, -1);
 
     /* This should already be page aligned */
     addr_and_mmu_idx = addr & TARGET_PAGE_MASK;
@@ -411,6 +419,8 @@ void tlb_flush_page_all_cpus(CPUState *src, target_ulong addr)
 {
     const run_on_cpu_func fn = tlb_flush_page_async_work;
 
+    trace_tlb_flush_async_schedule(__LINE__, src->cpu_index, -1);
+
     flush_all_helper(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
     fn(src, RUN_ON_CPU_TARGET_PTR(addr));
 }
@@ -420,6 +430,8 @@ void tlb_flush_page_all_cpus_synced(CPUState *src,
 {
     const run_on_cpu_func fn = tlb_flush_page_async_work;
 
+    trace_tlb_flush_synced_schedule(__LINE__, src->cpu_index, -1);
+
     flush_all_helper(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
     async_safe_run_on_cpu(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
 }
diff --git a/accel/tcg/trace-events b/accel/tcg/trace-events
index 618cc07738..0d2b1c47ac 100644
--- a/accel/tcg/trace-events
+++ b/accel/tcg/trace-events
@@ -1,5 +1,21 @@
 # Trace events for debugging and performance instrumentation
 
+# cputlb.c - SoftMMU TLB flushes
+#
+# There a numerous different functions for variations on flushing by
+# page/mmuidx and other critera. However we use common events and tag
+# them with the appropriate line number in cputlb.c
+#
+#   - setting to=-1 indicates work scheduled on all vCPUs
+#
+tlb_flush_self(int line, int vcpu) "cputlb.c:%d cpu %d"
+tlb_flush_async_schedule(int line, int from, int to) "cputlb.c:%d from_cpu=%d to_cpu=%d"
+tlb_flush_synced_schedule(int line, int from, int to) "cputlb.c:%d from_cpu=%d to_cpu=%d"
+# The following are the workers, usually running from a async work queue
+tlb_flush_all_work(int vcpu) "cpu %d"
+tlb_flush_work(int line, int vcpu, unsigned long data) "cputlb.c:%d cpu %d, %lux"
+tlb_flush_work_complete(int line, int vcpu) "cputlb.c:%d cpu %d"
+
 # TCG related tracing (you still need -d nochain to get a full picture
 # as otherwise you'll only see the first TB executed in a chain)
 # cpu-exec.c
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 07/21] accel/tcg/cputlb: convert tlb_flush debugging into trace events

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> +    trace_tlb_flush_all_work(cpu->cpu_index);
>      tlb_flush_nocheck(cpu);
> +    trace_tlb_flush_work_complete(__LINE__, cpu->cpu_index);

Why is __LINE__ an interesting argument to a trace function?


r~

Re: [Qemu-devel] [RFC PATCH 07/21] accel/tcg/cputlb: convert tlb_flush debugging into trace events

[Alex Bennée]

Richard Henderson <richard.henderson@linaro.org> writes:

> On 10/5/18 8:48 AM, Alex Bennée wrote:
>> +    trace_tlb_flush_all_work(cpu->cpu_index);
>>      tlb_flush_nocheck(cpu);
>> +    trace_tlb_flush_work_complete(__LINE__, cpu->cpu_index);
>
> Why is __LINE__ an interesting argument to a trace function?

Yeah - I wanted a unique key for each flush but that wasn't an opaque
char ptr to a __FUNC__. I guess I should just go ahead and have a type
enum? Can such a thing be exported via trace-events easily though?

--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH 07/21] accel/tcg/cputlb: convert tlb_flush debugging into trace events

[Richard Henderson]

On 10/15/18 11:23 AM, Alex Bennée wrote:
> 
> Richard Henderson <richard.henderson@linaro.org> writes:
> 
>> On 10/5/18 8:48 AM, Alex Bennée wrote:
>>> +    trace_tlb_flush_all_work(cpu->cpu_index);
>>>      tlb_flush_nocheck(cpu);
>>> +    trace_tlb_flush_work_complete(__LINE__, cpu->cpu_index);
>>
>> Why is __LINE__ an interesting argument to a trace function?
> 
> Yeah - I wanted a unique key for each flush but that wasn't an opaque
> char ptr to a __FUNC__. I guess I should just go ahead and have a type
> enum? Can such a thing be exported via trace-events easily though?

I don't think so, at the moment.  I dunno what's best really.


r~

[Qemu-devel] [RFC PATCH 08/21] accel/tcg/cputlb: convert remaining tlb_debug() to trace events

[Alex Bennée]

The last remaining user of tlb_debug() is the set page code. We can
convert this to a trace event and remove associated logging machinery.
The DEBUG_TLB define remains to enable self-check code when debugging.

To avoid overly long lines in trace events I've split the event into
tlb_set_page and tlb_set_page_attrs.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 accel/tcg/cputlb.c     | 27 +++++----------------------
 accel/tcg/trace-events |  5 +++++
 2 files changed, 10 insertions(+), 22 deletions(-)

diff --git a/accel/tcg/cputlb.c b/accel/tcg/cputlb.c
index f1d4f7da44..abdc4c5d25 100644
--- a/accel/tcg/cputlb.c
+++ b/accel/tcg/cputlb.c
@@ -34,31 +34,16 @@
 #include "exec/helper-proto.h"
 #include "qemu/atomic.h"
 
-/* DEBUG defines, enable DEBUG_TLB_LOG to log to the CPU_LOG_MMU target */
+/* DEBUG_TLB turns on internal self-checks, actions are logged via
+ * trace-events */
 /* #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)
-
 #define assert_cpu_is_self(this_cpu) do {                         \
         if (DEBUG_TLB_GATE) {                                     \
             g_assert(!cpu->created || qemu_cpu_is_self(cpu));     \
@@ -124,7 +109,6 @@ static void tlb_flush_nocheck(CPUState *cpu)
 
     assert_cpu_is_self(cpu);
     atomic_set(&env->tlb_flush_count, env->tlb_flush_count + 1);
-    tlb_debug("(count: %zu)\n", tlb_flush_count());
 
     memset(env->tlb_table, -1, sizeof(env->tlb_table));
     memset(env->tlb_v_table, -1, sizeof(env->tlb_v_table));
@@ -629,6 +613,9 @@ void tlb_set_page_with_attrs(CPUState *cpu, target_ulong vaddr,
 
     assert_cpu_is_self(cpu);
 
+    trace_tlb_set_page(cpu->cpu_index, vaddr, paddr);
+    trace_tlb_set_page_attrs(*(unsigned int *) &attrs, prot, mmu_idx, size);
+
     if (size < TARGET_PAGE_SIZE) {
         sz = TARGET_PAGE_SIZE;
     } else {
@@ -644,10 +631,6 @@ void tlb_set_page_with_attrs(CPUState *cpu, target_ulong vaddr,
                                                 &xlat, &sz, attrs, &prot);
     assert(sz >= TARGET_PAGE_SIZE);
 
-    tlb_debug("vaddr=" TARGET_FMT_lx " paddr=0x" TARGET_FMT_plx
-              " prot=%x idx=%d\n",
-              vaddr, paddr, prot, mmu_idx);
-
     address = vaddr_page;
     if (size < TARGET_PAGE_SIZE) {
         /*
diff --git a/accel/tcg/trace-events b/accel/tcg/trace-events
index 0d2b1c47ac..82705632f2 100644
--- a/accel/tcg/trace-events
+++ b/accel/tcg/trace-events
@@ -15,6 +15,11 @@ tlb_flush_synced_schedule(int line, int from, int to) "cputlb.c:%d from_cpu=%d t
 tlb_flush_all_work(int vcpu) "cpu %d"
 tlb_flush_work(int line, int vcpu, unsigned long data) "cputlb.c:%d cpu %d, %lux"
 tlb_flush_work_complete(int line, int vcpu) "cputlb.c:%d cpu %d"
+#
+# TLB entries
+#
+tlb_set_page(int vcpu, unsigned long vaddr, unsigned long paddr) "cpu:%d vaddr:0x%lx paddr:0x%lx"
+tlb_set_page_attrs(unsigned int attrs, int prot, int mmu_idx, int size) "attrs:0x%x prot:0x%x mmu_idx:%d size:%d"
 
 # TCG related tracing (you still need -d nochain to get a full picture
 # as otherwise you'll only see the first TB executed in a chain)
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 08/21] accel/tcg/cputlb: convert remaining tlb_debug() to trace events

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> To avoid overly long lines in trace events I've split the event into
> tlb_set_page and tlb_set_page_attrs.

I don't think this split is a good idea.  It allows data from different threads
to be interleaved.


r~

Re: [Qemu-devel] [RFC PATCH 08/21] accel/tcg/cputlb: convert remaining tlb_debug() to trace events

[Alex Bennée]

Richard Henderson <richard.henderson@linaro.org> writes:

> On 10/5/18 8:48 AM, Alex Bennée wrote:
>> To avoid overly long lines in trace events I've split the event into
>> tlb_set_page and tlb_set_page_attrs.
>
> I don't think this split is a good idea.  It allows data from different threads
> to be interleaved.

Won't we soon have a lock serialising this?

It was mainly to shut-up checkpatch because the trace-events don't seem
to do multi-line.

--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH 08/21] accel/tcg/cputlb: convert remaining tlb_debug() to trace events

[Richard Henderson]

On 10/15/18 11:17 AM, Alex Bennée wrote:
> 
> Richard Henderson <richard.henderson@linaro.org> writes:
> 
>> On 10/5/18 8:48 AM, Alex Bennée wrote:
>>> To avoid overly long lines in trace events I've split the event into
>>> tlb_set_page and tlb_set_page_attrs.
>>
>> I don't think this split is a good idea.  It allows data from different threads
>> to be interleaved.
> 
> Won't we soon have a lock serialising this?

For each individual trace entry, surely.
If you split the trace in two, you leave a race in the middle.

> It was mainly to shut-up checkpatch because the trace-events don't seem
> to do multi-line.

I would just ignore that.


r~

[Qemu-devel] [RFC PATCH 09/21] trace: suppress log output of trace points

[Alex Bennée]

When multiple tracers are enabled and you want to save to binary we
shouldn't assume the user also wants to spam the log. They can always
override it manually if they want.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 util/log.c |  3 ---
 vl.c       | 18 ++++++++++++++++--
 2 files changed, 16 insertions(+), 5 deletions(-)

diff --git a/util/log.c b/util/log.c
index cc79a146d1..5759bf571f 100644
--- a/util/log.c
+++ b/util/log.c
@@ -56,9 +56,6 @@ static bool log_uses_own_buffers;
 void qemu_set_log(int log_flags)
 {
     qemu_loglevel = log_flags;
-#ifdef CONFIG_TRACE_LOG
-    qemu_loglevel |= LOG_TRACE;
-#endif
     if (!qemu_logfile &&
         (is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
         if (logfilename) {
diff --git a/vl.c b/vl.c
index a867c9c4d9..795e025445 100644
--- a/vl.c
+++ b/vl.c
@@ -2908,6 +2908,7 @@ int main(int argc, char **argv, char **envp)
     Error *err = NULL;
     bool list_data_dirs = false;
     char *dir, **dirs;
+    int maybe_log_trace = 0;
     typedef struct BlockdevOptions_queue {
         BlockdevOptions *bdo;
         Location loc;
@@ -3985,6 +3986,19 @@ int main(int argc, char **argv, char **envp)
     }
     trace_init_file(trace_file);
 
+#if defined(CONFIG_TRACE_SIMPLE) && defined(CONFIG_TRACE_LOG)
+    /* If the user has both log and simple tracing enabled but hasn't
+     * defined a binary trace file ensure we enable the right logging
+     * flags.
+     */
+    if (!trace_file) {
+        maybe_log_trace = LOG_TRACE;
+    }
+#elif defined CONFIG_TRACE_LOG
+    /* with just CONFIG_TRACE_LOG we enable unconditionally */
+    maybe_log_trace = LOG_TRACE;
+#endif
+
     /* Open the logfile at this point and set the log mask if necessary.
      */
     if (log_file) {
@@ -3998,9 +4012,9 @@ int main(int argc, char **argv, char **envp)
             qemu_print_log_usage(stdout);
             exit(1);
         }
-        qemu_set_log(mask);
+        qemu_set_log(mask | maybe_log_trace);
     } else {
-        qemu_set_log(0);
+        qemu_set_log(maybe_log_trace);
     }
 
     /* add configured firmware directories */
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 09/21] trace: suppress log output of trace points

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> When multiple tracers are enabled and you want to save to binary we
> shouldn't assume the user also wants to spam the log. They can always
> override it manually if they want.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  util/log.c |  3 ---
>  vl.c       | 18 ++++++++++++++++--
>  2 files changed, 16 insertions(+), 5 deletions(-)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>

r~

[Qemu-devel] [RFC PATCH 10/21] qom/cpu: add a cpu_exit trace event

[Alex Bennée]

This is useful for tracing cpu_exit events where we signal the CPU to
come back to the main loop.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 qom/cpu.c        | 3 +++
 qom/trace-events | 4 ++++
 2 files changed, 7 insertions(+)

diff --git a/qom/cpu.c b/qom/cpu.c
index 92599f3541..5a77ff6acd 100644
--- a/qom/cpu.c
+++ b/qom/cpu.c
@@ -19,6 +19,7 @@
  */
 
 #include "qemu/osdep.h"
+#include "trace.h"
 #include "qapi/error.h"
 #include "qemu-common.h"
 #include "qom/cpu.h"
@@ -111,6 +112,8 @@ void cpu_reset_interrupt(CPUState *cpu, int mask)
 
 void cpu_exit(CPUState *cpu)
 {
+    trace_cpu_exit(cpu, cpu->cpu_index);
+
     atomic_set(&cpu->exit_request, 1);
     /* Ensure cpu_exec will see the exit request after TCG has exited.  */
     smp_wmb();
diff --git a/qom/trace-events b/qom/trace-events
index 5d86fbf019..1162dd86fe 100644
--- a/qom/trace-events
+++ b/qom/trace-events
@@ -1,5 +1,9 @@
 # See docs/devel/tracing.txt for syntax documentation.
 
+# qom/cpu.c
+# cpu_exit events
+cpu_exit(void *cpu, int id) "cpu:%p id:%d"
+
 # qom/object.c
 object_dynamic_cast_assert(const char *type, const char *target, const char *file, int line, const char *func) "%s->%s (%s:%d:%s)"
 object_class_dynamic_cast_assert(const char *type, const char *target, const char *file, int line, const char *func) "%s->%s (%s:%d:%s)"
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 10/21] qom/cpu: add a cpu_exit trace event

[Richard Henderson]

On 10/5/18 8:48 AM, Alex Bennée wrote:
> This is useful for tracing cpu_exit events where we signal the CPU to
> come back to the main loop.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  qom/cpu.c        | 3 +++
>  qom/trace-events | 4 ++++
>  2 files changed, 7 insertions(+)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>


r~

[Qemu-devel] [RFC PATCH 11/21] trace: expose a plugin fn pointer in TraceEvent

[Alex Bennée]

We'll need somewhere to stash this later. It's up to the generated
code to do the funky casting to what it really is.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 trace/control-internal.h | 6 ++++++
 trace/event-internal.h   | 3 +++
 2 files changed, 9 insertions(+)

diff --git a/trace/control-internal.h b/trace/control-internal.h
index c7fbe2d3bf..d734576948 100644
--- a/trace/control-internal.h
+++ b/trace/control-internal.h
@@ -80,6 +80,12 @@ static inline bool trace_event_get_vcpu_state_dynamic(CPUState *vcpu,
     return trace_event_get_vcpu_state_dynamic_by_vcpu_id(vcpu, vcpu_id);
 }
 
+#ifdef CONFIG_TRACE_PLUGIN
+static inline uintptr_t trace_event_get_plugin(TraceEvent *ev)
+{
+    return ev->plugin;
+}
+#endif
 
 void trace_event_register_group(TraceEvent **events);
 
diff --git a/trace/event-internal.h b/trace/event-internal.h
index 8ab3a29941..3895ee9883 100644
--- a/trace/event-internal.h
+++ b/trace/event-internal.h
@@ -38,6 +38,9 @@ typedef struct TraceEvent {
     const bool sstate;
     uint16_t *dstate;
     uint64_t count;
+#ifdef CONFIG_TRACE_PLUGIN
+    uintptr_t plugin;
+#endif
 } TraceEvent;
 
 void trace_event_set_state_dynamic_init(TraceEvent *ev, bool state);
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 11/21] trace: expose a plugin fn pointer in TraceEvent

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> We'll need somewhere to stash this later. It's up to the generated
> code to do the funky casting to what it really is.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  trace/control-internal.h | 6 ++++++
>  trace/event-internal.h   | 3 +++
>  2 files changed, 9 insertions(+)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>

r~

[Qemu-devel] [RFC PATCH 12/21] configure: expose a plugin to the trace-backends

[Alex Bennée]

We also enable gmodule support for use with plugins.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 configure | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/configure b/configure
index f3d4b799a5..87d71bbdcd 100755
--- a/configure
+++ b/configure
@@ -3513,6 +3513,9 @@ glib_modules=gthread-2.0
 if test "$modules" = yes; then
     glib_modules="$glib_modules gmodule-export-2.0"
 fi
+if have_backend "plugin"; then
+    glib_modules="$glib_modules gmodule-2.0"
+fi
 
 # This workaround is required due to a bug in pkg-config file for glib as it
 # doesn't define GLIB_STATIC_COMPILATION for pkg-config --static
@@ -6793,6 +6796,9 @@ if have_backend "syslog"; then
     feature_not_found "syslog(trace backend)" "syslog not available"
   fi
 fi
+if have_backend "plugin"; then
+  echo "CONFIG_TRACE_PLUGIN=y" >> $config_host_mak
+fi
 echo "CONFIG_TRACE_FILE=$trace_file" >> $config_host_mak
 
 if test "$rdma" = "yes" ; then
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 12/21] configure: expose a plugin to the trace-backends

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> We also enable gmodule support for use with plugins.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  configure | 6 ++++++
>  1 file changed, 6 insertions(+)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>

r~

[Qemu-devel] [RFC PATCH 13/21] tracetool: generate plugin snippets

[Alex Bennée]

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 scripts/tracetool/backend/plugin.py | 79 +++++++++++++++++++++++++++++
 1 file changed, 79 insertions(+)
 create mode 100644 scripts/tracetool/backend/plugin.py

diff --git a/scripts/tracetool/backend/plugin.py b/scripts/tracetool/backend/plugin.py
new file mode 100644
index 0000000000..d96b2df00a
--- /dev/null
+++ b/scripts/tracetool/backend/plugin.py
@@ -0,0 +1,79 @@
+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+
+"""
+Plugin backend.
+"""
+
+__author__     = "Alex Bennée <alex.bennee@linaro.org>"
+__copyright__  = "Copyright 2018, Alex Bennée <alex.bennee@linaro.org>"
+__license__    = "GPL version 2 or (at your option) any later version"
+
+__maintainer__ = "Alex Bennée"
+__email__      = "alex.bennee@linaro.org"
+
+
+from tracetool import out
+
+
+PUBLIC = True
+
+
+def generate_h_begin(events, group):
+    for event in events:
+        # prototype for plugin event
+        out('bool _plugin_%(api)s(%(args)s);',
+            api=event.api(),
+            args=event.args)
+        # prototype for plugin fn
+        out("typedef bool (* _plugin_%(api)s_fn)(%(args)s);",
+            api=event.api(),
+            args=event.args)
+
+
+def generate_h(event, group):
+    out('    if (!_plugin_%(api)s(%(args)s)) {',
+        '        return;',
+        '    };',
+        api=event.api(),
+        args=", ".join(event.args.names()))
+
+def generate_c_begin(events, group):
+    out('#include "qemu/osdep.h"',
+        '#include "trace/control.h"',
+        '')
+
+def generate_c(event, group):
+    out('bool _plugin_%(api)s(%(args)s)',
+        '{',
+        api=event.api(),
+        args=event.args)
+
+    event_id = 'TRACE_' + event.name.upper()
+    cond = "trace_event_get_state(%s)" % event_id
+
+    # Forst the pre-amble, bail early if the event is not enabled and
+    # if it is but no plugin is enabled let the reset of the events proceed.
+
+    out('',
+        '    if (!%(cond)s) {',
+        '        return false;',
+        '    }',
+        '',
+        '    uintptr_t fp = trace_event_get_plugin(&_%(event)s_EVENT);',
+        '    if (!fp) {',
+        '        return true;',
+        '    }',
+        '',
+        cond=cond,
+        event=event_id)
+
+    # We need to construct cast to the correct fn pointer to now call the plugin
+
+    out('',
+        '    _plugin_%(api)s_fn plug_fn = (_plugin_%(api)s_fn) fp;',
+        '    return plug_fn(%(names)s);',
+        '}',
+        '',
+        api=event.api(),
+        names=", ".join(event.args.names()))
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 13/21] tracetool: generate plugin snippets

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> +def generate_h_begin(events, group):
> +    for event in events:
> +        # prototype for plugin event
> +        out('bool _plugin_%(api)s(%(args)s);',
> +            api=event.api(),
> +            args=event.args)
> +        # prototype for plugin fn
> +        out("typedef bool (* _plugin_%(api)s_fn)(%(args)s);",
> +            api=event.api(),
> +            args=event.args)

Do you really want the _fn typedef to be a pointer?
Not doing that would allow declarations like

  _plugin_apis_fn _plugin_apis;


> +def generate_h(event, group):
> +    out('    if (!_plugin_%(api)s(%(args)s)) {',
> +        '        return;',
> +        '    };',

Extra ;

> +    # Forst the pre-amble, bail early if the event is not enabled and

First.

> +    # if it is but no plugin is enabled let the reset of the events proceed.
> +
> +    out('',
> +        '    if (!%(cond)s) {',
> +        '        return false;',
> +        '    }',
> +        '',
> +        '    uintptr_t fp = trace_event_get_plugin(&_%(event)s_EVENT);',

Declaration in the middle of a block.
Which, honestly, we should just allow via -std=gnu99 or gnu01.
But until then...

> +    out('',
> +        '    _plugin_%(api)s_fn plug_fn = (_plugin_%(api)s_fn) fp;',

Likewise.


r~

[Qemu-devel] [RFC PATCH 14/21] trace: add support for plugin infrastructure

[Alex Bennée]

From: Pavel Dovgalyuk <Pavel.Dovgaluk@ispras.ru>

This patch adds support for dynamically loaded plugins. Every plugin
is a dynamic library with a set of optional exported functions that
will be called from QEMU.

Signed-off-by: Pavel Dovgalyuk <Pavel.Dovgaluk@ispras.ru>
[AJB: moved to using trace point API]
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

---
ajb
  - moved to tracepoint interface (bind_to_tracepoints)
  - now in trace/ and include/plugins/
---
 include/plugins/plugins.h |  14 ++++
 include/qemu/plugins.h    |  18 +++++
 qemu-options.hx           |  10 +++
 trace/Makefile.objs       |   1 +
 trace/plugins.c           | 139 ++++++++++++++++++++++++++++++++++++++
 vl.c                      |   8 +++
 6 files changed, 190 insertions(+)
 create mode 100644 include/plugins/plugins.h
 create mode 100644 include/qemu/plugins.h
 create mode 100644 trace/plugins.c

diff --git a/include/plugins/plugins.h b/include/plugins/plugins.h
new file mode 100644
index 0000000000..54ac53cb32
--- /dev/null
+++ b/include/plugins/plugins.h
@@ -0,0 +1,14 @@
+#ifndef PLUGINS_INTERFACE_H
+#define PLUGINS_INTERFACE_H
+
+#include <stdbool.h>
+#include <stdio.h>
+
+/* Mandatory Plugin interfaces */
+
+bool plugin_init(const char *args);
+char *plugin_status(void);
+
+/* Other optional hooks are defined by available trace-points */
+
+#endif /* PLUGINS_INTERFACE_H */
diff --git a/include/qemu/plugins.h b/include/qemu/plugins.h
new file mode 100644
index 0000000000..c86bb7ae67
--- /dev/null
+++ b/include/qemu/plugins.h
@@ -0,0 +1,18 @@
+#ifndef PLUGINS_H
+#define PLUGINS_H
+
+#ifdef CONFIG_TRACE_PLUGIN
+
+void qemu_plugin_parse_cmd_args(const char *optarg);
+void qemu_plugin_load(const char *filename, const char *args);
+void qemu_plugins_init(void);
+
+#else
+
+static inline void qemu_plugin_parse_cmd_args(const char *optarg) { }
+static inline void qemu_plugin_load(const char *filename, const char *args) { }
+static inline void qemu_plugins_init(void) { }
+
+#endif
+
+#endif /* PLUGINS_H */
diff --git a/qemu-options.hx b/qemu-options.hx
index f139459e80..87206dd79f 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3892,6 +3892,16 @@ STEXI
 Enable synchronization profiling.
 ETEXI
 
+#ifdef CONFIG_TRACE_PLUGIN
+DEF("plugin", HAS_ARG, QEMU_OPTION_plugin, \
+           "-plugin file=<file>[,args=<args>] load <dso> plugin with <args>\n", QEMU_ARCH_ALL)
+STEXI
+@item -plugin file=@var{file}[,args=@var{args}]
+@findex -plugin
+Load @var{file} plugin passing @var{args} arguments.
+ETEXI
+#endif
+
 STEXI
 @end table
 ETEXI
diff --git a/trace/Makefile.objs b/trace/Makefile.objs
index afd571c3ec..4977f654a5 100644
--- a/trace/Makefile.objs
+++ b/trace/Makefile.objs
@@ -54,6 +54,7 @@ $(obj)/generated-tcg-tracers.h-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/
 
 util-obj-$(CONFIG_TRACE_SIMPLE) += simple.o
 util-obj-$(CONFIG_TRACE_FTRACE) += ftrace.o
+util-obj-$(CONFIG_TRACE_PLUGIN) += plugins.o
 util-obj-y += control.o
 target-obj-y += control-target.o
 util-obj-y += qmp.o
diff --git a/trace/plugins.c b/trace/plugins.c
new file mode 100644
index 0000000000..25aec2ff70
--- /dev/null
+++ b/trace/plugins.c
@@ -0,0 +1,139 @@
+/*
+ * Plugin Support
+ *
+ *
+ * Copyright (c) 2018 Pavel Dovgalyuk <Pavel.Dovgaluk@ispras.ru>
+ * Copyright (c) 2018 Alex Bennée <alex.bennee@linaro.org>
+ *
+ * SPDX-License-Identifier: GPL-2.0-or-later
+ */
+
+#include "qemu/osdep.h"
+#include <gmodule.h>
+#include "qemu-common.h"
+#include "qemu/error-report.h"
+#include "qemu/plugins.h"
+#include "qemu/queue.h"
+#include "qemu/option.h"
+#include "trace/control.h"
+
+typedef bool (*PluginInitFunc)(const char *);
+typedef char * (*PluginStatusFunc)(void);
+
+typedef struct QemuPluginInfo {
+    const char *filename;
+    const char *args;
+    GModule *g_module;
+
+    PluginInitFunc init;
+    PluginStatusFunc status;
+
+    GPtrArray *events;
+
+    QLIST_ENTRY(QemuPluginInfo) next;
+} QemuPluginInfo;
+
+static QLIST_HEAD(, QemuPluginInfo) qemu_plugins
+                                = QLIST_HEAD_INITIALIZER(qemu_plugins);
+
+static QemuOptsList qemu_plugin_opts = {
+    .name = "plugin",
+    .head = QTAILQ_HEAD_INITIALIZER(qemu_plugin_opts.head),
+    .desc = {
+        {
+            .name = "file",
+            .type = QEMU_OPT_STRING,
+        },{
+            .name = "args",
+            .type = QEMU_OPT_STRING,
+        },
+        { /* end of list */ }
+    },
+};
+
+void qemu_plugin_parse_cmd_args(const char *optarg)
+{
+    QemuOpts *opts = qemu_opts_parse_noisily(&qemu_plugin_opts, optarg, false);
+    qemu_plugin_load(qemu_opt_get(opts, "file"),
+                     qemu_opt_get(opts, "args"));
+}
+
+static int bind_to_tracepoints(GModule *g_module, GPtrArray *events)
+{
+    int count = 0;
+    TraceEventIter iter;
+    TraceEvent *ev;
+
+    trace_event_iter_init(&iter, "*");
+    while ((ev = trace_event_iter_next(&iter)) != NULL) {
+        const char *name = trace_event_get_name(ev);
+        gpointer fn;
+
+        if (g_module_symbol(g_module, name, &fn)) {
+            ev->plugin = (uintptr_t) fn;
+            trace_event_set_state_dynamic(ev, true);
+            count++;
+        }
+    }
+
+    return count;
+}
+
+void qemu_plugin_load(const char *filename, const char *args)
+{
+    GModule *g_module;
+    QemuPluginInfo *info = NULL;
+    if (!filename) {
+        error_report("plugin name was not specified");
+        return;
+    }
+    g_module = g_module_open(filename,
+        G_MODULE_BIND_LAZY | G_MODULE_BIND_LOCAL);
+    if (!g_module) {
+        error_report("can't load plugin '%s'", filename);
+        return;
+    }
+    info = g_new0(QemuPluginInfo, 1);
+    info->filename = g_strdup(filename);
+    info->g_module = g_module;
+
+    if (!g_module_symbol(g_module, "plugin_init",
+                         (gpointer *) &info->init)) {
+        error_report("all plugins must provide a plugin_init hook");
+        return;
+    }
+
+    if (!g_module_symbol(g_module, "plugin_status",
+                         (gpointer *) &info->status)) {
+        error_report("all plugins must provide a plugin_status hook");
+        return;
+    }
+
+    /* OK we can now see how many events might have bindings */
+    info->events = g_ptr_array_new();
+
+    if (bind_to_tracepoints(g_module, info->events) < 0) {
+        error_report("failed to bind any events");
+        return;
+    }
+
+    /* Save the args, we will initialise later on once everything is
+       set up */
+    if (args) {
+        info->args = g_strdup(args);
+    }
+
+    QLIST_INSERT_HEAD(&qemu_plugins, info, next);
+
+    return;
+}
+
+void qemu_plugins_init(void)
+{
+    QemuPluginInfo *info;
+    QLIST_FOREACH(info, &qemu_plugins, next) {
+        if (info->init) {
+            info->init(info->args);
+        }
+    }
+}
diff --git a/vl.c b/vl.c
index 795e025445..b46ef5032f 100644
--- a/vl.c
+++ b/vl.c
@@ -130,6 +130,7 @@ int main(int argc, char **argv)
 #include "qapi/qapi-commands-run-state.h"
 #include "qapi/qmp/qerror.h"
 #include "sysemu/iothread.h"
+#include "qemu/plugins.h"
 
 #define MAX_VIRTIO_CONSOLES 1
 
@@ -3884,6 +3885,11 @@ int main(int argc, char **argv, char **envp)
             case QEMU_OPTION_enable_sync_profile:
                 qsp_enable();
                 break;
+#ifdef CONFIG_TRACE_PLUGIN
+            case QEMU_OPTION_plugin:
+                qemu_plugin_parse_cmd_args(optarg);
+                break;
+#endif
             case QEMU_OPTION_nouserconfig:
                 /* Nothing to be parsed here. Especially, do not error out below. */
                 break;
@@ -4449,6 +4455,8 @@ int main(int argc, char **argv, char **envp)
     }
     parse_numa_opts(current_machine);
 
+    qemu_plugins_init();
+
     /* do monitor/qmp handling at preconfig state if requested */
     main_loop();
 
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 14/21] trace: add support for plugin infrastructure

[Emilio G. Cota]

On Fri, Oct 05, 2018 at 16:49:03 +0100, Alex Bennée wrote:
(snip)
> +static int bind_to_tracepoints(GModule *g_module, GPtrArray *events)
> +{
> +    int count = 0;
> +    TraceEventIter iter;
> +    TraceEvent *ev;
> +
> +    trace_event_iter_init(&iter, "*");
> +    while ((ev = trace_event_iter_next(&iter)) != NULL) {
> +        const char *name = trace_event_get_name(ev);
> +        gpointer fn;
> +
> +        if (g_module_symbol(g_module, name, &fn)) {
> +            ev->plugin = (uintptr_t) fn;
> +            trace_event_set_state_dynamic(ev, true);
> +            count++;
> +        }
> +    }

I'd rather have subscription functions exposed to the
plugins via an API, so that
- Plugins can turn on and off subscriptions to callbacks
  as they see fit, instead of "being called from
  the very beginning, and then disable forever"
- We can have compile-time failures when doing something
  wrong with callback names :-)

Thanks,

		E.

Re: [Qemu-devel] [RFC PATCH 14/21] trace: add support for plugin infrastructure

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> +    g_module = g_module_open(filename,
> +        G_MODULE_BIND_LAZY | G_MODULE_BIND_LOCAL);

Do you really want lazy binding?  It means that if a symbol is missing you
won't see it here at load time.

Otherwise,
Reviewed-by: Richard Henderson <richard.henderson@linaro.org>

r~

[Qemu-devel] [RFC PATCH 15/21] trace: add linux-user plugin support

[Alex Bennée]

From: Aaron Lindsay <aclindsa@gmail.com>

Signed-off-by: Aaron Lindsay <aclindsa@gmail.com>
[AJB: ifdeffery]
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 linux-user/main.c | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/linux-user/main.c b/linux-user/main.c
index a68674d0de..9fbb827fe0 100644
--- a/linux-user/main.c
+++ b/linux-user/main.c
@@ -38,6 +38,7 @@
 #include "trace/control.h"
 #include "target_elf.h"
 #include "cpu_loop-common.h"
+#include "qemu/plugins.h"
 
 char *exec_path;
 
@@ -393,6 +394,13 @@ static void handle_arg_trace(const char *arg)
     trace_file = trace_opt_parse(arg);
 }
 
+#ifdef CONFIG_TRACE_PLUGIN
+static void handle_arg_plugin(const char *arg)
+{
+    qemu_plugin_parse_cmd_args(arg);
+}
+#endif
+
 struct qemu_argument {
     const char *argv;
     const char *env;
@@ -444,6 +452,10 @@ static const struct qemu_argument arg_table[] = {
      "",           "Seed for pseudo-random number generator"},
     {"trace",      "QEMU_TRACE",       true,  handle_arg_trace,
      "",           "[[enable=]<pattern>][,events=<file>][,file=<file>]"},
+#ifdef CONFIG_TRACE_PLUGIN
+    {"plugin",     "QEMU_PLUGIN",      true,  handle_arg_plugin,
+     "",           "file=<plugin_so>[,args=<args>]"},
+#endif
     {"version",    "QEMU_VERSION",     false, handle_arg_version,
      "",           "display version information and exit"},
     {NULL, NULL, false, NULL, NULL, NULL}
@@ -830,6 +842,9 @@ int main(int argc, char **argv, char **envp)
         }
         gdb_handlesig(cpu, 0);
     }
+
+    qemu_plugins_init();
+
     cpu_loop(env);
     /* never exits */
     return 0;
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 15/21] trace: add linux-user plugin support

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> From: Aaron Lindsay <aclindsa@gmail.com>
> 
> Signed-off-by: Aaron Lindsay <aclindsa@gmail.com>
> [AJB: ifdeffery]
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  linux-user/main.c | 15 +++++++++++++++
>  1 file changed, 15 insertions(+)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>

r~

[Qemu-devel] [RFC PATCH 16/21] trace: add infrastructure for building plugins

[Alex Bennée]

This allows us to build any bundled plugins in the source tree.
Out-of-tree builds can call Makefile.plugins to build in their own
source tree:

  make -f $(QEMU_PATH)/trace/plugins/Makefile.plugins QEMU_SRC=$(QEMU_PATH)

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 Makefile                       |  5 ++++-
 trace/Makefile.objs            | 24 ++++++++++++++++++++++++
 trace/plugins/Makefile.plugins | 32 ++++++++++++++++++++++++++++++++
 3 files changed, 60 insertions(+), 1 deletion(-)
 create mode 100644 trace/plugins/Makefile.plugins

diff --git a/Makefile b/Makefile
index 1144d6e3ba..e04d1c5124 100644
--- a/Makefile
+++ b/Makefile
@@ -438,7 +438,7 @@ dummy := $(call unnest-vars,, \
 
 include $(SRC_PATH)/tests/Makefile.include
 
-all: $(DOCS) $(TOOLS) $(HELPERS-y) recurse-all modules
+all: $(DOCS) $(TOOLS) $(HELPERS-y) recurse-all modules plugins
 
 qemu-version.h: FORCE
 	$(call quiet-command, \
@@ -1091,6 +1091,9 @@ help:
 	@echo  '  all             - Build all'
 ifdef CONFIG_MODULES
 	@echo  '  modules         - Build all modules'
+endif
+ifdef CONFIG_TRACE_PLUGIN
+	@echo  '  plugins         - Build all plugins'
 endif
 	@echo  '  dir/file.o      - Build specified target only'
 	@echo  '  install         - Install QEMU, documentation and tools'
diff --git a/trace/Makefile.objs b/trace/Makefile.objs
index 4977f654a5..4f62022595 100644
--- a/trace/Makefile.objs
+++ b/trace/Makefile.objs
@@ -58,3 +58,27 @@ util-obj-$(CONFIG_TRACE_PLUGIN) += plugins.o
 util-obj-y += control.o
 target-obj-y += control-target.o
 util-obj-y += qmp.o
+
+######################################################################
+# Plugins
+ifdef CONFIG_TRACE_PLUGIN
+
+PLUGINS=$(dir $(wildcard $(SRC_PATH)/trace/plugins/*/.))
+
+.PHONY: plugins $(PLUGINS)
+
+plugins: $(PLUGINS)
+	$(info built all plugins $(PLUGINS))
+
+$(PLUGINS):
+	$(call quiet-command, 							\
+	   (cd $@ && $(MAKE) -f $(SRC_PATH)/trace/plugins/Makefile.plugins 	\
+				QEMU_SRC=$(SRC_PATH) 				\
+				BUILD_DIR=$(BUILD_DIR)/trace/plugins), 		\
+	"PLUGIN","in $@")
+
+else
+
+plugins:
+
+endif
diff --git a/trace/plugins/Makefile.plugins b/trace/plugins/Makefile.plugins
new file mode 100644
index 0000000000..0056d91c74
--- /dev/null
+++ b/trace/plugins/Makefile.plugins
@@ -0,0 +1,32 @@
+# -*- Mode: makefile -*-
+#
+# QEMU plugins
+#
+# This Makefile is used to build plugins for QEMU. Unlike the rest of
+# the object files we build we don't have visibility of QEMU's
+# internals. When called from the main makefile we build plugins into
+# BUILD_DIR/plugins otherwise where ever the Makefile was called from.
+# QEMU_SRC
+#
+
+BUILD_DIR ?= $(CURDIR)
+CC ?= cc
+
+ifndef QEMU_SRC
+$(error need to define QEMU_SRC for the build)
+endif
+
+GLIB_CFLAGS = $(shell pkg-config --cflags glib-2.0)
+CFLAGS = -I$(QEMU_SRC)/include/plugins $(GLIB_CFLAGS) -fno-PIE -fPIC -O3 -g
+LDFLAGS = $(shell pkg-config --libs glib-2.0) -shared
+
+SRC = $(wildcard *.c)
+PLUGINS = $(addprefix $(BUILD_DIR)/,$(SRC:.c=.so))
+
+$(BUILD_DIR)/%.so: %.c
+	$(CC) $(CFLAGS) $(LDFLAGS) -o $@ $<
+
+all: $(PLUGINS)
+
+clean:
+	rm -f $(PLUGIN_SO) $(PLUGIN_OBJ)
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 16/21] trace: add infrastructure for building plugins

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> +GLIB_CFLAGS = $(shell pkg-config --cflags glib-2.0)
> +CFLAGS = -I$(QEMU_SRC)/include/plugins $(GLIB_CFLAGS) -fno-PIE -fPIC -O3 -g
> +LDFLAGS = $(shell pkg-config --libs glib-2.0) -shared

I'm not keen on defaulting to -O3.
I'd prefer if we passed up the flags from top-level, but I know you're also
trying to support out-of-tree builds.

Perhaps

CFLAGS ?= -O2 -g
QEMU_CFLAGS = $(CFLAGS) $(GLIB_CFLAGS) -I$(QEMU_SRC)/... -fno-PIE -fPIC

> +SRC = $(wildcard *.c)
> +PLUGINS = $(addprefix $(BUILD_DIR)/,$(SRC:.c=.so))
> +
> +$(BUILD_DIR)/%.so: %.c
> +	$(CC) $(CFLAGS) $(LDFLAGS) -o $@ $<
> +
> +all: $(PLUGINS)

Do you really want one plugin per source file rather than one plugin per
directory?  I think the latter makes more sense...

And of course you know the second thing people are going to want is to write
these plugins in C++...


r~

Re: [Qemu-devel] [RFC PATCH 16/21] trace: add infrastructure for building plugins

[Alex Bennée]

Richard Henderson <richard.henderson@linaro.org> writes:

> On 10/5/18 8:49 AM, Alex Bennée wrote:
>> +GLIB_CFLAGS = $(shell pkg-config --cflags glib-2.0)
>> +CFLAGS = -I$(QEMU_SRC)/include/plugins $(GLIB_CFLAGS) -fno-PIE -fPIC -O3 -g
>> +LDFLAGS = $(shell pkg-config --libs glib-2.0) -shared
>
> I'm not keen on defaulting to -O3.

Fair enough... I'll drop it down if not set...

> I'd prefer if we passed up the flags from top-level, but I know you're also
> trying to support out-of-tree builds.
>
> Perhaps
>
> CFLAGS ?= -O2 -g
> QEMU_CFLAGS = $(CFLAGS) $(GLIB_CFLAGS) -I$(QEMU_SRC)/... -fno-PIE -fPIC
>
>> +SRC = $(wildcard *.c)
>> +PLUGINS = $(addprefix $(BUILD_DIR)/,$(SRC:.c=.so))
>> +
>> +$(BUILD_DIR)/%.so: %.c
>> +	$(CC) $(CFLAGS) $(LDFLAGS) -o $@ $<
>> +
>> +all: $(PLUGINS)
>
> Do you really want one plugin per source file rather than one plugin per
> directory?  I think the latter makes more sense...
>
> And of course you know the second thing people are going to want is to write
> these plugins in C++...
>
>
> r~


--
Alex Bennée

[Qemu-devel] [RFC PATCH 17/21] hmp: expose status of plugins to the monitor

[Alex Bennée]

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 hmp-commands-info.hx   | 17 +++++++++++++++++
 include/qemu/plugins.h |  1 +
 monitor.c              | 14 ++++++++++++++
 trace/plugins.c        | 15 +++++++++++++++
 4 files changed, 47 insertions(+)

diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx
index cbee8b944d..e245a852ae 100644
--- a/hmp-commands-info.hx
+++ b/hmp-commands-info.hx
@@ -683,6 +683,23 @@ STEXI
 Show available trace-events & their state.
 ETEXI
 
+#if defined(CONFIG_TRACE_PLUGIN)
+    {
+        .name       = "trace-plugins",
+        .args_type  = "name:s?",
+        .params     = "[name]",
+        .help       = "show available plugins and any extra info "
+                      "(name: plugin name pattern)",
+        .cmd = hmp_info_trace_plugins,
+    },
+
+STEXI
+@item info trace-plugins
+@findex info trace-plugins
+Show available trace-plugins & their state.
+ETEXI
+#endif
+
     {
         .name       = "tpm",
         .args_type  = "",
diff --git a/include/qemu/plugins.h b/include/qemu/plugins.h
index c86bb7ae67..44f2ec8c98 100644
--- a/include/qemu/plugins.h
+++ b/include/qemu/plugins.h
@@ -6,6 +6,7 @@
 void qemu_plugin_parse_cmd_args(const char *optarg);
 void qemu_plugin_load(const char *filename, const char *args);
 void qemu_plugins_init(void);
+GString *qemu_plugin_status(const char *name);
 
 #else
 
diff --git a/monitor.c b/monitor.c
index d8229cd2b0..0d0de9ece7 100644
--- a/monitor.c
+++ b/monitor.c
@@ -67,6 +67,9 @@
 #ifdef CONFIG_TRACE_SIMPLE
 #include "trace/simple.h"
 #endif
+#ifdef CONFIG_TRACE_PLUGIN
+#include "qemu/plugins.h"
+#endif
 #include "exec/memory.h"
 #include "exec/exec-all.h"
 #include "qemu/log.h"
@@ -1429,6 +1432,17 @@ static void hmp_info_trace_events(Monitor *mon, const QDict *qdict)
     qapi_free_TraceEventInfoList(events);
 }
 
+#ifdef CONFIG_TRACE_PLUGIN
+static void hmp_info_trace_plugins(Monitor *mon, const QDict *qdict)
+{
+    const char *name = qdict_get_try_str(qdict, "name");
+    GString *status = qemu_plugin_status(name);
+
+    monitor_printf(mon, "%s", status->str);
+    g_string_free(status, true);
+}
+#endif
+
 void qmp_client_migrate_info(const char *protocol, const char *hostname,
                              bool has_port, int64_t port,
                              bool has_tls_port, int64_t tls_port,
diff --git a/trace/plugins.c b/trace/plugins.c
index 25aec2ff70..05630b02e6 100644
--- a/trace/plugins.c
+++ b/trace/plugins.c
@@ -58,6 +58,21 @@ void qemu_plugin_parse_cmd_args(const char *optarg)
                      qemu_opt_get(opts, "args"));
 }
 
+GString *qemu_plugin_status(const char *name)
+{
+    QemuPluginInfo *info;
+    GString *status = g_string_new("");
+
+    QLIST_FOREACH(info, &qemu_plugins, next) {
+        if (info->status) {
+            char *pstatus = info->status();
+            g_string_append_printf(status, "%s: %s\n", info->filename, pstatus);
+            g_free(pstatus);
+        }
+    }
+    return status;
+}
+
 static int bind_to_tracepoints(GModule *g_module, GPtrArray *events)
 {
     int count = 0;
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 17/21] hmp: expose status of plugins to the monitor

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  hmp-commands-info.hx   | 17 +++++++++++++++++
>  include/qemu/plugins.h |  1 +
>  monitor.c              | 14 ++++++++++++++
>  trace/plugins.c        | 15 +++++++++++++++
>  4 files changed, 47 insertions(+)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>

r~

Re: [Qemu-devel] [RFC PATCH 17/21] hmp: expose status of plugins to the monitor

[Dr. David Alan Gilbert]

* Alex Bennée (alex.bennee@linaro.org) wrote:
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  hmp-commands-info.hx   | 17 +++++++++++++++++
>  include/qemu/plugins.h |  1 +
>  monitor.c              | 14 ++++++++++++++
>  trace/plugins.c        | 15 +++++++++++++++
>  4 files changed, 47 insertions(+)

I'm OK with this; although it's worth thinking about whether this should
be available via qmp, but it is just for debug/tracing.


Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>


> diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx
> index cbee8b944d..e245a852ae 100644
> --- a/hmp-commands-info.hx
> +++ b/hmp-commands-info.hx
> @@ -683,6 +683,23 @@ STEXI
>  Show available trace-events & their state.
>  ETEXI

> +#if defined(CONFIG_TRACE_PLUGIN)
> +    {
> +        .name       = "trace-plugins",
> +        .args_type  = "name:s?",
> +        .params     = "[name]",
> +        .help       = "show available plugins and any extra info "
> +                      "(name: plugin name pattern)",
> +        .cmd = hmp_info_trace_plugins,
> +    },
> +
> +STEXI
> +@item info trace-plugins
> +@findex info trace-plugins
> +Show available trace-plugins & their state.
> +ETEXI
> +#endif
> +
>      {
>          .name       = "tpm",
>          .args_type  = "",
> diff --git a/include/qemu/plugins.h b/include/qemu/plugins.h
> index c86bb7ae67..44f2ec8c98 100644
> --- a/include/qemu/plugins.h
> +++ b/include/qemu/plugins.h
> @@ -6,6 +6,7 @@
>  void qemu_plugin_parse_cmd_args(const char *optarg);
>  void qemu_plugin_load(const char *filename, const char *args);
>  void qemu_plugins_init(void);
> +GString *qemu_plugin_status(const char *name);
>  
>  #else
>  
> diff --git a/monitor.c b/monitor.c
> index d8229cd2b0..0d0de9ece7 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -67,6 +67,9 @@
>  #ifdef CONFIG_TRACE_SIMPLE
>  #include "trace/simple.h"
>  #endif
> +#ifdef CONFIG_TRACE_PLUGIN
> +#include "qemu/plugins.h"
> +#endif
>  #include "exec/memory.h"
>  #include "exec/exec-all.h"
>  #include "qemu/log.h"
> @@ -1429,6 +1432,17 @@ static void hmp_info_trace_events(Monitor *mon, const QDict *qdict)
>      qapi_free_TraceEventInfoList(events);
>  }
>  
> +#ifdef CONFIG_TRACE_PLUGIN
> +static void hmp_info_trace_plugins(Monitor *mon, const QDict *qdict)
> +{
> +    const char *name = qdict_get_try_str(qdict, "name");
> +    GString *status = qemu_plugin_status(name);
> +
> +    monitor_printf(mon, "%s", status->str);
> +    g_string_free(status, true);
> +}
> +#endif
> +
>  void qmp_client_migrate_info(const char *protocol, const char *hostname,
>                               bool has_port, int64_t port,
>                               bool has_tls_port, int64_t tls_port,
> diff --git a/trace/plugins.c b/trace/plugins.c
> index 25aec2ff70..05630b02e6 100644
> --- a/trace/plugins.c
> +++ b/trace/plugins.c
> @@ -58,6 +58,21 @@ void qemu_plugin_parse_cmd_args(const char *optarg)
>                       qemu_opt_get(opts, "args"));
>  }
>  
> +GString *qemu_plugin_status(const char *name)
> +{
> +    QemuPluginInfo *info;
> +    GString *status = g_string_new("");
> +
> +    QLIST_FOREACH(info, &qemu_plugins, next) {
> +        if (info->status) {
> +            char *pstatus = info->status();
> +            g_string_append_printf(status, "%s: %s\n", info->filename, pstatus);
> +            g_free(pstatus);
> +        }
> +    }
> +    return status;
> +}
> +
>  static int bind_to_tracepoints(GModule *g_module, GPtrArray *events)
>  {
>      int count = 0;
> -- 
> 2.17.1
> 
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: [Qemu-devel] [RFC PATCH 17/21] hmp: expose status of plugins to the monitor

[Markus Armbruster]

"Dr. David Alan Gilbert" <dgilbert@redhat.com> writes:

> * Alex Bennée (alex.bennee@linaro.org) wrote:
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> ---
>>  hmp-commands-info.hx   | 17 +++++++++++++++++
>>  include/qemu/plugins.h |  1 +
>>  monitor.c              | 14 ++++++++++++++
>>  trace/plugins.c        | 15 +++++++++++++++
>>  4 files changed, 47 insertions(+)
>
> I'm OK with this; although it's worth thinking about whether this should
> be available via qmp, but it is just for debug/tracing.

Standard operating procedure for adding HMP commands without a QMP
equivalent: have the commit message explain why the QMP equivalent isn't
useful.

> Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>

[Qemu-devel] [RFC PATCH 18/21] linux-user: allow dumping of plugin status at end of run

[Alex Bennée]

As we don't have a monitor in linux-user mode we need some way of
exporting our data to the world. We introduce a new -d option (plugin)
which turns on the existing LOG_TRACE flag which qemu_plugin_status()
will dump output to before we finally exit.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 linux-user/exit.c | 12 ++++++++++++
 util/log.c        |  2 ++
 2 files changed, 14 insertions(+)

diff --git a/linux-user/exit.c b/linux-user/exit.c
index 14e94e28fa..2f9e016207 100644
--- a/linux-user/exit.c
+++ b/linux-user/exit.c
@@ -17,12 +17,23 @@
  *  along with this program; if not, see <http://www.gnu.org/licenses/>.
  */
 #include "qemu/osdep.h"
+#include "qemu/plugins.h"
 #include "qemu.h"
 
 #ifdef CONFIG_GCOV
 extern void __gcov_dump(void);
 #endif
 
+static void plugin_report(void)
+{
+#ifdef CONFIG_TRACE_PLUGIN
+    GString *plugin_report = qemu_plugin_status("");
+    qemu_log_mask(LOG_TRACE, "%s", plugin_report->str);
+    g_string_free(plugin_report, true);
+#endif
+}
+
+
 void preexit_cleanup(CPUArchState *env, int code)
 {
 #ifdef TARGET_GPROF
@@ -31,5 +42,6 @@ void preexit_cleanup(CPUArchState *env, int code)
 #ifdef CONFIG_GCOV
         __gcov_dump();
 #endif
+        plugin_report();
         gdb_exit(env, code);
 }
diff --git a/util/log.c b/util/log.c
index 5759bf571f..d4423277e0 100644
--- a/util/log.c
+++ b/util/log.c
@@ -288,6 +288,8 @@ const QEMULogItem qemu_log_items[] = {
     { CPU_LOG_TB_NOCHAIN, "nochain",
       "do not chain compiled TBs so that \"exec\" and \"cpu\" show\n"
       "complete traces" },
+    { LOG_TRACE, "plugin",
+      "show summary plugin information at end of run." },
     { 0, NULL, NULL },
 };
 
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 18/21] linux-user: allow dumping of plugin status at end of run

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> As we don't have a monitor in linux-user mode we need some way of
> exporting our data to the world. We introduce a new -d option (plugin)
> which turns on the existing LOG_TRACE flag which qemu_plugin_status()
> will dump output to before we finally exit.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  linux-user/exit.c | 12 ++++++++++++
>  util/log.c        |  2 ++
>  2 files changed, 14 insertions(+)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>

r~

[Qemu-devel] [RFC PATCH 19/21] plugins: add an example hotblocks plugin

[Alex Bennée]

This plugin attempts to track hotblocks by total execution count and
average time to return to block. It is intended to be lower impact
than saving a long log file and post-processing it.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 trace/plugins/hotblocks/hotblocks.c | 69 +++++++++++++++++++++++++++++
 1 file changed, 69 insertions(+)
 create mode 100644 trace/plugins/hotblocks/hotblocks.c

diff --git a/trace/plugins/hotblocks/hotblocks.c b/trace/plugins/hotblocks/hotblocks.c
new file mode 100644
index 0000000000..e9166ad1a5
--- /dev/null
+++ b/trace/plugins/hotblocks/hotblocks.c
@@ -0,0 +1,69 @@
+/*
+ * Execution Hotblocks Plugin
+ *
+ * Copyright (c) 2018
+ * Written by Alex Bennée <alex.bennee@linaro.org>
+ *
+ * This code is licensed under the GNU GPL v2.
+ */
+
+#include <stdint.h>
+#include <stdio.h>
+#include <glib.h>
+#include <time.h>
+#include "plugins.h"
+
+/* Plugins need to take care of their own locking */
+GMutex lock;
+GHashTable *hotblocks;
+
+typedef struct {
+    uintptr_t pc;
+    unsigned int hits;
+    struct timespec last;
+    unsigned long total_time;
+} ExecCount;
+
+bool plugin_init(const char *args)
+{
+    hotblocks = g_hash_table_new(NULL, g_direct_equal);
+    return true;
+}
+
+char *plugin_status(void)
+{
+    GString *report = g_string_new("We have ");
+    char *r;
+    g_mutex_lock(&lock);
+    g_string_append_printf(report, "%ud entries in the hash table\n",
+                           g_hash_table_size(hotblocks));
+    g_mutex_unlock(&lock);
+    r = report->str;
+    g_string_free(report, FALSE);
+    return r;
+}
+
+bool exec_tb(void *tb, uintptr_t pc)
+{
+    ExecCount *cnt;
+    struct timespec current;
+    clock_gettime(CLOCK_MONOTONIC, &current);
+
+    g_mutex_lock(&lock);
+    cnt = (ExecCount *) g_hash_table_lookup(hotblocks, (gconstpointer) pc);
+    if (cnt) {
+        cnt->hits++;
+        cnt->total_time += current.tv_nsec - cnt->last.tv_nsec;
+        cnt->last = current;
+    } else {
+        cnt = g_new0(ExecCount, 1);
+        cnt->pc = pc;
+        cnt->last = current;
+        cnt->hits = 1;
+        g_hash_table_insert(hotblocks, (gpointer) pc, (gpointer) cnt);
+    }
+    g_mutex_unlock(&lock);
+
+    /* As we are collecting up samples no reason to continue tracing */
+    return false;
+}
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 19/21] plugins: add an example hotblocks plugin

[Pavel Dovgalyuk]

I guess this one is too tcg-dependent.
It count TB's, but breaking code into TBs may depend on many things,
like breakpoints, record/replay, ...

I mean that this measuring approach may be used only in some specific
cases, and not ok as an example.

Pavel Dovgalyuk

> -----Original Message-----
> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> Sent: Friday, October 05, 2018 6:49 PM
> To: qemu-devel@nongnu.org
> Cc: Pavel.Dovgaluk@ispras.ru; vilanova@ac.upc.edu; cota@braap.org; Alex Bennée; Stefan
> Hajnoczi
> Subject: [RFC PATCH 19/21] plugins: add an example hotblocks plugin
> 
> This plugin attempts to track hotblocks by total execution count and
> average time to return to block. It is intended to be lower impact
> than saving a long log file and post-processing it.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  trace/plugins/hotblocks/hotblocks.c | 69 +++++++++++++++++++++++++++++
>  1 file changed, 69 insertions(+)
>  create mode 100644 trace/plugins/hotblocks/hotblocks.c
> 
> diff --git a/trace/plugins/hotblocks/hotblocks.c b/trace/plugins/hotblocks/hotblocks.c
> new file mode 100644
> index 0000000000..e9166ad1a5
> --- /dev/null
> +++ b/trace/plugins/hotblocks/hotblocks.c
> @@ -0,0 +1,69 @@
> +/*
> + * Execution Hotblocks Plugin
> + *
> + * Copyright (c) 2018
> + * Written by Alex Bennée <alex.bennee@linaro.org>
> + *
> + * This code is licensed under the GNU GPL v2.
> + */
> +
> +#include <stdint.h>
> +#include <stdio.h>
> +#include <glib.h>
> +#include <time.h>
> +#include "plugins.h"
> +
> +/* Plugins need to take care of their own locking */
> +GMutex lock;
> +GHashTable *hotblocks;
> +
> +typedef struct {
> +    uintptr_t pc;
> +    unsigned int hits;
> +    struct timespec last;
> +    unsigned long total_time;
> +} ExecCount;
> +
> +bool plugin_init(const char *args)
> +{
> +    hotblocks = g_hash_table_new(NULL, g_direct_equal);
> +    return true;
> +}
> +
> +char *plugin_status(void)
> +{
> +    GString *report = g_string_new("We have ");
> +    char *r;
> +    g_mutex_lock(&lock);
> +    g_string_append_printf(report, "%ud entries in the hash table\n",
> +                           g_hash_table_size(hotblocks));
> +    g_mutex_unlock(&lock);
> +    r = report->str;
> +    g_string_free(report, FALSE);
> +    return r;
> +}
> +
> +bool exec_tb(void *tb, uintptr_t pc)
> +{
> +    ExecCount *cnt;
> +    struct timespec current;
> +    clock_gettime(CLOCK_MONOTONIC, &current);
> +
> +    g_mutex_lock(&lock);
> +    cnt = (ExecCount *) g_hash_table_lookup(hotblocks, (gconstpointer) pc);
> +    if (cnt) {
> +        cnt->hits++;
> +        cnt->total_time += current.tv_nsec - cnt->last.tv_nsec;
> +        cnt->last = current;
> +    } else {
> +        cnt = g_new0(ExecCount, 1);
> +        cnt->pc = pc;
> +        cnt->last = current;
> +        cnt->hits = 1;
> +        g_hash_table_insert(hotblocks, (gpointer) pc, (gpointer) cnt);
> +    }
> +    g_mutex_unlock(&lock);
> +
> +    /* As we are collecting up samples no reason to continue tracing */
> +    return false;
> +}
> --
> 2.17.1

Re: [Qemu-devel] [RFC PATCH 19/21] plugins: add an example hotblocks plugin

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

> I guess this one is too tcg-dependent.
> It count TB's, but breaking code into TBs may depend on many things,
> like breakpoints, record/replay, ...
>
> I mean that this measuring approach may be used only in some specific
> cases, and not ok as an example.

You are right it involves a degree of knowledge of how the TCG works
although it doesn't look inside the internals to do it - you do have to
specify -d nochain to get useful numbers.

I used this as an example in lieu of defining tracepoints in the main
translation loop. They would be better there as it would be unambiguous
what the behaviour would be. That said I think a translation block start
as well as pre/post instruction translation points would be useful as
block level granularity will be good enough for a number of use cases.

>
> Pavel Dovgalyuk
>
>> -----Original Message-----
>> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> Sent: Friday, October 05, 2018 6:49 PM
>> To: qemu-devel@nongnu.org
>> Cc: Pavel.Dovgaluk@ispras.ru; vilanova@ac.upc.edu; cota@braap.org; Alex Bennée; Stefan
>> Hajnoczi
>> Subject: [RFC PATCH 19/21] plugins: add an example hotblocks plugin
>>
>> This plugin attempts to track hotblocks by total execution count and
>> average time to return to block. It is intended to be lower impact
>> than saving a long log file and post-processing it.
>>
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> ---
>>  trace/plugins/hotblocks/hotblocks.c | 69 +++++++++++++++++++++++++++++
>>  1 file changed, 69 insertions(+)
>>  create mode 100644 trace/plugins/hotblocks/hotblocks.c
>>
>> diff --git a/trace/plugins/hotblocks/hotblocks.c b/trace/plugins/hotblocks/hotblocks.c
>> new file mode 100644
>> index 0000000000..e9166ad1a5
>> --- /dev/null
>> +++ b/trace/plugins/hotblocks/hotblocks.c
>> @@ -0,0 +1,69 @@
>> +/*
>> + * Execution Hotblocks Plugin
>> + *
>> + * Copyright (c) 2018
>> + * Written by Alex Bennée <alex.bennee@linaro.org>
>> + *
>> + * This code is licensed under the GNU GPL v2.
>> + */
>> +
>> +#include <stdint.h>
>> +#include <stdio.h>
>> +#include <glib.h>
>> +#include <time.h>
>> +#include "plugins.h"
>> +
>> +/* Plugins need to take care of their own locking */
>> +GMutex lock;
>> +GHashTable *hotblocks;
>> +
>> +typedef struct {
>> +    uintptr_t pc;
>> +    unsigned int hits;
>> +    struct timespec last;
>> +    unsigned long total_time;
>> +} ExecCount;
>> +
>> +bool plugin_init(const char *args)
>> +{
>> +    hotblocks = g_hash_table_new(NULL, g_direct_equal);
>> +    return true;
>> +}
>> +
>> +char *plugin_status(void)
>> +{
>> +    GString *report = g_string_new("We have ");
>> +    char *r;
>> +    g_mutex_lock(&lock);
>> +    g_string_append_printf(report, "%ud entries in the hash table\n",
>> +                           g_hash_table_size(hotblocks));
>> +    g_mutex_unlock(&lock);
>> +    r = report->str;
>> +    g_string_free(report, FALSE);
>> +    return r;
>> +}
>> +
>> +bool exec_tb(void *tb, uintptr_t pc)
>> +{
>> +    ExecCount *cnt;
>> +    struct timespec current;
>> +    clock_gettime(CLOCK_MONOTONIC, &current);
>> +
>> +    g_mutex_lock(&lock);
>> +    cnt = (ExecCount *) g_hash_table_lookup(hotblocks, (gconstpointer) pc);
>> +    if (cnt) {
>> +        cnt->hits++;
>> +        cnt->total_time += current.tv_nsec - cnt->last.tv_nsec;
>> +        cnt->last = current;
>> +    } else {
>> +        cnt = g_new0(ExecCount, 1);
>> +        cnt->pc = pc;
>> +        cnt->last = current;
>> +        cnt->hits = 1;
>> +        g_hash_table_insert(hotblocks, (gpointer) pc, (gpointer) cnt);
>> +    }
>> +    g_mutex_unlock(&lock);
>> +
>> +    /* As we are collecting up samples no reason to continue tracing */
>> +    return false;
>> +}
>> --
>> 2.17.1


--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH 19/21] plugins: add an example hotblocks plugin

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> +char *plugin_status(void)
> +{
> +    GString *report = g_string_new("We have ");
> +    char *r;
> +    g_mutex_lock(&lock);
> +    g_string_append_printf(report, "%ud entries in the hash table\n",
> +                           g_hash_table_size(hotblocks));
> +    g_mutex_unlock(&lock);
> +    r = report->str;
> +    g_string_free(report, FALSE);
> +    return r;
> +}

You're not reporting the entries themselves?
Also, are you sure you don't want to just return the GString?


r~

Re: [Qemu-devel] [RFC PATCH 19/21] plugins: add an example hotblocks plugin

[Alex Bennée]

Richard Henderson <richard.henderson@linaro.org> writes:

> On 10/5/18 8:49 AM, Alex Bennée wrote:
>> +char *plugin_status(void)
>> +{
>> +    GString *report = g_string_new("We have ");
>> +    char *r;
>> +    g_mutex_lock(&lock);
>> +    g_string_append_printf(report, "%ud entries in the hash table\n",
>> +                           g_hash_table_size(hotblocks));
>> +    g_mutex_unlock(&lock);
>> +    r = report->str;
>> +    g_string_free(report, FALSE);
>> +    return r;
>> +}
>
> You're not reporting the entries themselves?
> Also, are you sure you don't want to just return the GString?

I considered it. I wondered if exposing a glib dependency to the plugins
was fair game? It would make things simpler and QEMU could even allocate
it for the plugin.

>
>
> r~


--
Alex Bennée

[Qemu-devel] [RFC PATCH 20/21] plugins: add hotness summary to hotblocks

[Alex Bennée]

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 trace/plugins/hotblocks/hotblocks.c | 33 ++++++++++++++++++++++++++++-
 1 file changed, 32 insertions(+), 1 deletion(-)

diff --git a/trace/plugins/hotblocks/hotblocks.c b/trace/plugins/hotblocks/hotblocks.c
index e9166ad1a5..d2333ad866 100644
--- a/trace/plugins/hotblocks/hotblocks.c
+++ b/trace/plugins/hotblocks/hotblocks.c
@@ -11,11 +11,13 @@
 #include <stdio.h>
 #include <glib.h>
 #include <time.h>
+#include <inttypes.h>
 #include "plugins.h"
 
 /* Plugins need to take care of their own locking */
 GMutex lock;
 GHashTable *hotblocks;
+guint64 limit = 20;
 
 typedef struct {
     uintptr_t pc;
@@ -24,20 +26,49 @@ typedef struct {
     unsigned long total_time;
 } ExecCount;
 
+static gint cmp_hits(gconstpointer a, gconstpointer b)
+{
+    ExecCount *ea = (ExecCount *) a;
+    ExecCount *eb = (ExecCount *) b;
+    return ea->hits > eb->hits ? -1 : 1;
+}
+
 bool plugin_init(const char *args)
 {
+    guint64 count = g_ascii_strtoull(args, NULL, 10);
+    if (count > 0) {
+        limit = count;
+    }
+
     hotblocks = g_hash_table_new(NULL, g_direct_equal);
     return true;
 }
 
 char *plugin_status(void)
 {
-    GString *report = g_string_new("We have ");
+    GString *report = g_string_new("collected ");
+    GList *counts, *it;
     char *r;
+    int i;
+
     g_mutex_lock(&lock);
     g_string_append_printf(report, "%ud entries in the hash table\n",
                            g_hash_table_size(hotblocks));
+    counts = g_hash_table_get_values(hotblocks);
+    it = g_list_sort(counts, cmp_hits);
+
+    for (i = 0; i < limit && it->next; i++, it = it->next) {
+        ExecCount *rec = (ExecCount *) it->data;
+        g_string_append_printf(report,
+                               "  pc: %#016" PRIxPTR
+                               " (%d hits)"
+                               " %lu ns between returns\n",
+                               rec->pc, rec->hits,
+                               rec->total_time / rec->hits);
+    }
+
     g_mutex_unlock(&lock);
+    g_list_free(it);
     r = report->str;
     g_string_free(report, FALSE);
     return r;
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 20/21] plugins: add hotness summary to hotblocks

[Richard Henderson]

On 10/5/18 8:49 AM, Alex Bennée wrote:
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  trace/plugins/hotblocks/hotblocks.c | 33 ++++++++++++++++++++++++++++-
>  1 file changed, 32 insertions(+), 1 deletion(-)

Oh, haha.  Ignore the first half of my comment for the previous patch.


r~

[Qemu-devel] [RFC PATCH 21/21] plugin: add tlbflush stats plugin

[Alex Bennée]

This plugin attempts to give an idea of how long it take QEMU to
process the various types of TLB flush operation. Although this is
generally of interest to QEMU developers the plugin is only using the
trace point information to work this out. For example launching a
system emulation with -plugin file=./trace/plugins/tlbflush.so allows
the following to be reported on the monitor:

  (qemu) info trace-plugins
  ./trace/plugins/tlbflush.so: tlbflush report:
  cpu 0 101244 self events: avg time 103, max 18313
  cpu 0 2 async events: avg time 14076146, max 27536460
  cpu 0 122328 synced events: avg time 5441, max 29080526
  cpu 0 162671 work events: avg time 5380, max 47305
  cpu 1 101742 self events: avg time 110, max 29708
  cpu 1 2 async events: avg time 14112140, max 27573506
  cpu 1 122669 synced events: avg time 5762, max 1175419
  cpu 1 163401 work events: avg time 5427, max 942563
  cpu 2 116726 self events: avg time 107, max 18277
  cpu 2 2 async events: avg time 14126146, max 27615150
  cpu 2 120119 synced events: avg time 6318, max 928542
  cpu 2 177175 work events: avg time 5772, max 699626
  cpu 3 94551 self events: avg time 107, max 23313
  cpu 3 1 async events: avg time 27947822, max 27947822
  cpu 3 123203 synced events: avg time 7877, max 3913260
  cpu 3 156481 work events: avg time 5126, max 54107

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 trace/plugins/tlbflush/tlbflush.c | 283 ++++++++++++++++++++++++++++++
 1 file changed, 283 insertions(+)
 create mode 100644 trace/plugins/tlbflush/tlbflush.c

diff --git a/trace/plugins/tlbflush/tlbflush.c b/trace/plugins/tlbflush/tlbflush.c
new file mode 100644
index 0000000000..0e6ab82978
--- /dev/null
+++ b/trace/plugins/tlbflush/tlbflush.c
@@ -0,0 +1,283 @@
+/*
+ * Execution Hotblocks Plugin
+ *
+ * Copyright (c) 2018
+ * Written by Alex Bennée <alex.bennee@linaro.org>
+ *
+ * This code is licensed under the GNU GPL v2.
+ */
+
+#include <stdint.h>
+#include <stdio.h>
+#include <glib.h>
+#include <time.h>
+#include <inttypes.h>
+#include "plugins.h"
+
+#define MAX_CPU  16
+
+#ifndef __ATOMIC_RELAXED
+#error "this plugin relies on atomics"
+#endif
+
+/*
+ * We are not going to try and track coalesced requests so the
+ * measurement will start from the point of the first request and be
+ * cleared from the first work complete.
+ */
+
+typedef enum FlushType { SELF, ASYNC, SYNCED } FlushType;
+
+typedef struct {
+    unsigned long count;
+    unsigned long total;
+    unsigned long max;
+} EventCounts;
+
+typedef struct {
+    struct timespec start;
+    FlushType type;
+
+    EventCounts self;
+    EventCounts async;
+    EventCounts synced;
+    EventCounts work;
+} TLBStats;
+
+static TLBStats stats[MAX_CPU];
+
+bool plugin_init(const char *args)
+{
+    return true;
+}
+
+static void add_stats(GString *report, int cpu, char *name, EventCounts *event)
+{
+    if (event->count) {
+        g_string_append_printf(report,
+                               "cpu %d %ld %s events: avg time %lu, max %lu\n",
+                               cpu, event->count, name,
+                               event->total / event->count, event->max);
+    }
+}
+
+char *plugin_status(void)
+{
+    GString *report = g_string_new("tlbflush report:\n");
+    char *r;
+    int i;
+
+    for (i = 0; i < MAX_CPU; i++) {
+        TLBStats *cpu_stats = &stats[i];
+
+        add_stats(report, i, "self", &cpu_stats->self);
+        add_stats(report, i, "async", &cpu_stats->async);
+        add_stats(report, i, "synced", &cpu_stats->synced);
+        add_stats(report, i, "work", &cpu_stats->work);
+    }
+
+    r = report->str;
+    g_string_free(report, FALSE);
+    return r;
+}
+
+
+/*
+ * Maybe start an event. This is imprecise as we don't catch all
+ * events. We will skip events when:
+ *   - we already started for an event that hasn't completed
+ *   - events that happen to start when tv_nsec == 0
+ */
+static bool maybe_start_timer(TLBStats *cpu, struct timespec now)
+{
+    struct timespec zero = { 0, 0 };
+    bool started;
+
+    started = __atomic_compare_exchange_n(&cpu->start.tv_nsec,
+                                          &zero.tv_nsec,
+                                          now.tv_nsec, false,
+                                          __ATOMIC_SEQ_CST, __ATOMIC_SEQ_CST);
+    if (started) {
+        __atomic_store_n(&cpu->start.tv_sec, now.tv_sec, __ATOMIC_SEQ_CST);
+    }
+
+    return started;
+}
+
+bool tlb_flush_self(int line, int vcpu)
+{
+    struct timespec current;
+    TLBStats *this = &stats[vcpu];
+
+    clock_gettime(CLOCK_MONOTONIC, &current);
+
+    if (maybe_start_timer(this, current)) {
+        this->type = SELF;
+    }
+
+    return false;
+}
+
+static void start_one_cpu(TLBStats *cpu, FlushType type, struct timespec now)
+{
+    if (maybe_start_timer(cpu, now)) {
+        cpu->type = type;
+    }
+}
+
+bool tlb_flush_async_schedule(int line, int from, int to)
+{
+    struct timespec current;
+    TLBStats *this;
+
+    clock_gettime(CLOCK_MONOTONIC, &current);
+
+    if (to < 0) {
+        int i;
+        for (i = 0; i < MAX_CPU; i++) {
+            if (i != from) {
+                this = &stats[i];
+                start_one_cpu(this, ASYNC, current);
+            }
+        }
+    } else {
+        this = &stats[to];
+        start_one_cpu(this, ASYNC, current);
+    }
+}
+
+bool tlb_flush_synced_schedule(int line, int from, int to)
+{
+    struct timespec current;
+    TLBStats *this;
+
+    clock_gettime(CLOCK_MONOTONIC, &current);
+
+    if (to < 0) {
+        int i;
+        for (i = 0; i < MAX_CPU; i++) {
+            if (i != from) {
+                this = &stats[i];
+                start_one_cpu(this, SYNCED, current);
+            }
+        }
+    } else {
+        this = &stats[to];
+        start_one_cpu(this, SYNCED, current);
+    }
+}
+
+
+static EventCounts *get_counts(FlushType type, TLBStats *stats)
+{
+    switch (type) {
+    case SELF:
+        return &stats->self;
+    case ASYNC:
+        return &stats->async;
+    case SYNCED:
+        return &stats->synced;
+    }
+}
+
+/* return elapsed ns */
+static unsigned long get_elapsed(struct timespec start, struct timespec end)
+{
+    struct timespec temp;
+
+    if ((end.tv_nsec - start.tv_nsec) < 0) {
+        temp.tv_sec = end.tv_sec - start.tv_sec - 1;
+        temp.tv_nsec = 1000000000 + end.tv_nsec - start.tv_nsec;
+    } else {
+        temp.tv_sec = end.tv_sec - start.tv_sec;
+        temp.tv_nsec = end.tv_nsec - start.tv_nsec;
+    }
+
+    return (temp.tv_sec * 1000000000) + temp.tv_nsec;
+}
+
+/* Record the duration of a single event based on when it started */
+static struct timespec record_event(struct timespec start, EventCounts *event)
+{
+    struct timespec current;
+    unsigned long elapsed ;
+
+    clock_gettime(CLOCK_MONOTONIC, &current);
+    elapsed = get_elapsed(start, current);
+    event->count++;
+    event->total += elapsed;
+    if (elapsed > event->max) {
+        event->max = elapsed;
+    }
+
+    return current;
+}
+
+/* Update the timer for work. As we are re-reading in the same thread
+ * we don't need to be totally sequential - it doesn't matter if the
+ * outer thread reads this or zero.
+ */
+static void update_timer(TLBStats *cpu, struct timespec new_time)
+{
+    /* we are using 0 to indicate no current event */
+    if (new_time.tv_nsec == 0) {
+        new_time.tv_nsec = 1;
+    }
+    __atomic_store_n(&cpu->start.tv_sec, new_time.tv_sec, __ATOMIC_RELAXED);
+    __atomic_store_n(&cpu->start.tv_nsec, new_time.tv_nsec, __ATOMIC_RELAXED);
+}
+
+/* ??? Maybe we should drop the start of work trace points but create
+ * a new one for processing and queued work ??? */
+
+bool tlb_flush_all_work(int vcpu)
+{
+    struct timespec start;
+    TLBStats *this = &stats[vcpu];
+
+    start.tv_nsec = __atomic_load_n(&this->start.tv_nsec, __ATOMIC_SEQ_CST);
+    start.tv_sec = __atomic_load_n(&this->start.tv_sec, __ATOMIC_SEQ_CST);
+
+    if (start.tv_nsec) {
+        EventCounts *event = get_counts(this->type, this);
+        struct timespec start_work = record_event(start, event);
+        update_timer(this, start_work);
+    }
+
+    return false;
+}
+
+bool tlb_flush_work(int line, int vcpu, unsigned long data)
+{
+    struct timespec start;
+    TLBStats *this = &stats[vcpu];
+
+    start.tv_nsec = __atomic_load_n(&this->start.tv_nsec, __ATOMIC_SEQ_CST);
+    start.tv_sec = __atomic_load_n(&this->start.tv_sec, __ATOMIC_SEQ_CST);
+
+    if (start.tv_nsec) {
+        EventCounts *event = get_counts(this->type, this);
+        struct timespec start_work = record_event(start, event);
+        update_timer(this, start_work);
+    }
+
+    return false;
+}
+
+bool tlb_flush_work_complete(int line, int vcpu)
+{
+    struct timespec start;
+    TLBStats *this = &stats[vcpu];
+
+    start.tv_sec = __atomic_load_n(&this->start.tv_sec, __ATOMIC_RELAXED);
+    start.tv_nsec = __atomic_load_n(&this->start.tv_nsec, __ATOMIC_RELAXED);
+
+    if (start.tv_nsec) {
+        EventCounts *event = &this->work;
+        record_event(start, event);
+        /* reset for next event */
+        __atomic_store_n(&this->start.tv_nsec, 0, __ATOMIC_SEQ_CST);
+    }
+
+    return false;
+}
-- 
2.17.1

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Emilio G. Cota]

On Fri, Oct 05, 2018 at 16:48:49 +0100, Alex Bennée wrote:
(snip)
> ==Known Limitations==
> 
> Currently there is only one hook allowed per trace event. We could
> make this more flexible or simply just error out if two plugins try
> and hook to the same point. What are the expectations of running
> multiple plugins hooking into the same point in QEMU?

It's very common. All popular instrumentation tools (e.g. PANDA,
DynamoRIO, Pin) support multiple plugins.

> ==TCG Hooks==
> 
> Thanks to Lluís' work the trace API already splits up TCG events into
> translation time and exec time events and provides the machinery for
> hooking a trace helper into the translation stream. Currently that
> helper is unconditionally added although perhaps we could expand the
> call convention a little for TCG events to allow the translation time
> event to filter out planting the execution time helper?

A TCG helper is suboptimal for these kind of events, e.g. instruction/TB/
mem callbacks, because (1) these events happen *very* often, and
(2) a helper then has to iterate over a list of callbacks (assuming
we support multiple plugins). That is, one TCG helper call,
plus cache misses for the callback pointers, plus function calls
to call the callbacks. That adds up to 2x average slowdown
for SPEC06int, instead of 1.5x slowdown when embedding the
callbacks directly into the generated code. Yes, you have to
flush the code when unsubscribing from the event, but that cost
is amortized by the savings you get when the callbacks occur,
which are way more frequent.

Besides performance, to provide a pleasant plugin experience we need
something better than the current tracing callbacks.

> ===Instruction Tracing===
> 
> Pavel's series had a specific hook for instrumenting individual
> instructions. I have not yet added it to this series but I think it be
> done in a slightly cleaner way now we have the ability to insert TCG
> ops into the instruction stream.

I thought Peter explicitly disallowed TCG generation from plugins.
Also, IIRC others also mentioned that exposing QEMU internals
(e.g. "struct TranslationBlock", or "struct CPUState") to plugins
was not on the table.

> If we add a tracepoint for post
> instruction generation which passes a buffer with the instruction
> translated and method to insert a helper before or after the
> instruction. This would avoid exposing the cpu_ldst macros to the
> plugins.

Again, for performance you'd avoid the tracepoint (i.e. calling
a helper to call another function) and embed directly the
callback from TCG. Same thing applies to TB's.

> So what do people think? Could this be a viable way to extend QEMU
> with plugins?

For frequent events such as the ones mentioned above, I am
not sure plugins can be efficiently implemented under
tracing. For others (e.g. cpu_init events), sure, they could.
But still, differently from tracers, plugins can come and go
anytime, so I am not convinced that merging the two features
is a good idea.

Thanks,

		Emilio

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Alex Bennée]

Emilio G. Cota <cota@braap.org> writes:

> On Fri, Oct 05, 2018 at 16:48:49 +0100, Alex Bennée wrote:
> (snip)
>> ==Known Limitations==
>>
>> Currently there is only one hook allowed per trace event. We could
>> make this more flexible or simply just error out if two plugins try
>> and hook to the same point. What are the expectations of running
>> multiple plugins hooking into the same point in QEMU?
>
> It's very common. All popular instrumentation tools (e.g. PANDA,
> DynamoRIO, Pin) support multiple plugins.

Fair enough.

>
>> ==TCG Hooks==
>>
>> Thanks to Lluís' work the trace API already splits up TCG events into
>> translation time and exec time events and provides the machinery for
>> hooking a trace helper into the translation stream. Currently that
>> helper is unconditionally added although perhaps we could expand the
>> call convention a little for TCG events to allow the translation time
>> event to filter out planting the execution time helper?
>
> A TCG helper is suboptimal for these kind of events, e.g. instruction/TB/
> mem callbacks, because (1) these events happen *very* often, and
> (2) a helper then has to iterate over a list of callbacks (assuming
> we support multiple plugins). That is, one TCG helper call,
> plus cache misses for the callback pointers, plus function calls
> to call the callbacks. That adds up to 2x average slowdown
> for SPEC06int, instead of 1.5x slowdown when embedding the
> callbacks directly into the generated code. Yes, you have to
> flush the code when unsubscribing from the event, but that cost
> is amortized by the savings you get when the callbacks occur,
> which are way more frequent.

What would you want instead of a TCG helper? But certainly being able be
selective about which instances of each trace point are instrumented
will be valuable.

> Besides performance, to provide a pleasant plugin experience we need
> something better than the current tracing callbacks.

What I hope to avoid in re-using trace points is having a whole bunch of
a additional hook points just for plugins. However nothing stops us
adding more tracepoints at more useful places for instrumentation. We
could also do it on a whitelist basis similar to the way the tcg events
are marked.

>
>> ===Instruction Tracing===
>>
>> Pavel's series had a specific hook for instrumenting individual
>> instructions. I have not yet added it to this series but I think it be
>> done in a slightly cleaner way now we have the ability to insert TCG
>> ops into the instruction stream.
>
> I thought Peter explicitly disallowed TCG generation from plugins.
> Also, IIRC others also mentioned that exposing QEMU internals
> (e.g. "struct TranslationBlock", or "struct CPUState") to plugins
> was not on the table.

We definitely want to avoid plugin controlled code generation but the
tcg tracepoint mechanism is transparent to the plugin itself. I think
the pointers should really be treated as anonymous handles rather than
windows into QEMU's internals. Arguably some of the tracepoints should
be exporting more useful numbers (I used cpu->cpu_index in the TLB trace
points) but I don't know if we can change existing trace point
definitions to clean that up.

Again if we whitelist tracepoints for plugins we can be more careful
about the data exported.

>
>> If we add a tracepoint for post
>> instruction generation which passes a buffer with the instruction
>> translated and method to insert a helper before or after the
>> instruction. This would avoid exposing the cpu_ldst macros to the
>> plugins.
>
> Again, for performance you'd avoid the tracepoint (i.e. calling
> a helper to call another function) and embed directly the
> callback from TCG. Same thing applies to TB's.

OK I see what you mean. I think that is doable although it might take a
bit more tcg plumbing.

>
>> So what do people think? Could this be a viable way to extend QEMU
>> with plugins?
>
> For frequent events such as the ones mentioned above, I am
> not sure plugins can be efficiently implemented under
> tracing.

I assume some form of helper-per-instrumented-event/insn is still going
to be needed though? We are not considering some sort of EBF craziness?

> For others (e.g. cpu_init events), sure, they could.
> But still, differently from tracers, plugins can come and go
> anytime, so I am not convinced that merging the two features
> is a good idea.

I don't think we have to mirror tracepoints and plugin points but I'm in
favour of sharing the general mechanism and tooling rather than having a
whole separate set of hooks. We certainly don't want anything like:

          trace_exec_tb(tb, pc);
          plugin_exec_tb(tb, pc);

scattered throughout the code where the two do align.

>
> Thanks,
>
> 		Emilio


--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Philippe Mathieu-Daudé]

Hi Alex,

On 08/10/2018 12:28, Alex Bennée wrote:
> 
> Emilio G. Cota <cota@braap.org> writes:
> 
>> On Fri, Oct 05, 2018 at 16:48:49 +0100, Alex Bennée wrote:
>> (snip)
>>> ==Known Limitations==
>>>
>>> Currently there is only one hook allowed per trace event. We could
>>> make this more flexible or simply just error out if two plugins try
>>> and hook to the same point. What are the expectations of running
>>> multiple plugins hooking into the same point in QEMU?
>>
>> It's very common. All popular instrumentation tools (e.g. PANDA,
>> DynamoRIO, Pin) support multiple plugins.
> 
> Fair enough.
> 
>>
>>> ==TCG Hooks==
>>>
>>> Thanks to Lluís' work the trace API already splits up TCG events into
>>> translation time and exec time events and provides the machinery for
>>> hooking a trace helper into the translation stream. Currently that
>>> helper is unconditionally added although perhaps we could expand the
>>> call convention a little for TCG events to allow the translation time
>>> event to filter out planting the execution time helper?
>>
>> A TCG helper is suboptimal for these kind of events, e.g. instruction/TB/
>> mem callbacks, because (1) these events happen *very* often, and
>> (2) a helper then has to iterate over a list of callbacks (assuming
>> we support multiple plugins). That is, one TCG helper call,
>> plus cache misses for the callback pointers, plus function calls
>> to call the callbacks. That adds up to 2x average slowdown
>> for SPEC06int, instead of 1.5x slowdown when embedding the
>> callbacks directly into the generated code. Yes, you have to
>> flush the code when unsubscribing from the event, but that cost
>> is amortized by the savings you get when the callbacks occur,
>> which are way more frequent.
> 
> What would you want instead of a TCG helper? But certainly being able be
> selective about which instances of each trace point are instrumented
> will be valuable.
> 
>> Besides performance, to provide a pleasant plugin experience we need
>> something better than the current tracing callbacks.
> 
> What I hope to avoid in re-using trace points is having a whole bunch of
> a additional hook points just for plugins. However nothing stops us
> adding more tracepoints at more useful places for instrumentation. We
> could also do it on a whitelist basis similar to the way the tcg events
> are marked.
> 
>>
>>> ===Instruction Tracing===
>>>
>>> Pavel's series had a specific hook for instrumenting individual
>>> instructions. I have not yet added it to this series but I think it be
>>> done in a slightly cleaner way now we have the ability to insert TCG
>>> ops into the instruction stream.
>>
>> I thought Peter explicitly disallowed TCG generation from plugins.
>> Also, IIRC others also mentioned that exposing QEMU internals
>> (e.g. "struct TranslationBlock", or "struct CPUState") to plugins
>> was not on the table.
> 
> We definitely want to avoid plugin controlled code generation but the
> tcg tracepoint mechanism is transparent to the plugin itself. I think
> the pointers should really be treated as anonymous handles rather than
> windows into QEMU's internals. Arguably some of the tracepoints should
> be exporting more useful numbers (I used cpu->cpu_index in the TLB trace
> points) but I don't know if we can change existing trace point
> definitions to clean that up.
> 
> Again if we whitelist tracepoints for plugins we can be more careful
> about the data exported.
> 
>>
>>> If we add a tracepoint for post
>>> instruction generation which passes a buffer with the instruction
>>> translated and method to insert a helper before or after the
>>> instruction. This would avoid exposing the cpu_ldst macros to the
>>> plugins.
>>
>> Again, for performance you'd avoid the tracepoint (i.e. calling
>> a helper to call another function) and embed directly the
>> callback from TCG. Same thing applies to TB's.
> 
> OK I see what you mean. I think that is doable although it might take a
> bit more tcg plumbing.
> 
>>
>>> So what do people think? Could this be a viable way to extend QEMU
>>> with plugins?
>>
>> For frequent events such as the ones mentioned above, I am
>> not sure plugins can be efficiently implemented under
>> tracing.
> 
> I assume some form of helper-per-instrumented-event/insn is still going
> to be needed though? We are not considering some sort of EBF craziness?
> 
>> For others (e.g. cpu_init events), sure, they could.
>> But still, differently from tracers, plugins can come and go
>> anytime, so I am not convinced that merging the two features
>> is a good idea.
> 
> I don't think we have to mirror tracepoints and plugin points but I'm in
> favour of sharing the general mechanism and tooling rather than having a
> whole separate set of hooks. We certainly don't want anything like:
> 
>           trace_exec_tb(tb, pc);
>           plugin_exec_tb(tb, pc);
> 
> scattered throughout the code where the two do align.

What about turning the tracepoints into the default instrumentation
plugin? (the first of Emilio's list of plugins).

>>
>> Thanks,
>>
>> 		Emilio
> 
> 
> --
> Alex Bennée
> 

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Emilio G. Cota]

On Mon, Oct 08, 2018 at 11:28:38 +0100, Alex Bennée wrote:
> Emilio G. Cota <cota@braap.org> writes:
> > Again, for performance you'd avoid the tracepoint (i.e. calling
> > a helper to call another function) and embed directly the
> > callback from TCG. Same thing applies to TB's.
> 
> OK I see what you mean. I think that is doable although it might take a
> bit more tcg plumbing.

I have patches to do it, it's not complicated.

> >> So what do people think? Could this be a viable way to extend QEMU
> >> with plugins?
> >
> > For frequent events such as the ones mentioned above, I am
> > not sure plugins can be efficiently implemented under
> > tracing.
> 
> I assume some form of helper-per-instrumented-event/insn is still going
> to be needed though? We are not considering some sort of EBF craziness?

Helper, yes. But one that points directly to plugin code.

> > For others (e.g. cpu_init events), sure, they could.
> > But still, differently from tracers, plugins can come and go
> > anytime, so I am not convinced that merging the two features
> > is a good idea.
> 
> I don't think we have to mirror tracepoints and plugin points but I'm in
> favour of sharing the general mechanism and tooling rather than having a
> whole separate set of hooks. We certainly don't want anything like:
> 
>           trace_exec_tb(tb, pc);
>           plugin_exec_tb(tb, pc);
> 
> scattered throughout the code where the two do align.

We could have something like

	plugin_trace_exec_tb(tb, pc);

that would expand to the two lines above. Or similar.

So I agree with you that in some cases the "trace points"
for both tracing and plugin might be the same, perhaps
identical. But that doesn't necessarily mean that making
plugins a subset of tracing is a good idea.

I think sharing my plugin implementation will help the
discussion. I'll share it as soon as I can (my QEMU plate
is full already trying to merge a couple of other features
first).

Thanks,

		Emilio

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Alex Bennée]

Emilio G. Cota <cota@braap.org> writes:

> On Mon, Oct 08, 2018 at 11:28:38 +0100, Alex Bennée wrote:
>> Emilio G. Cota <cota@braap.org> writes:
>> > Again, for performance you'd avoid the tracepoint (i.e. calling
>> > a helper to call another function) and embed directly the
>> > callback from TCG. Same thing applies to TB's.
>>
>> OK I see what you mean. I think that is doable although it might take a
>> bit more tcg plumbing.
>
> I have patches to do it, it's not complicated.

Right that would be useful.

>
>> >> So what do people think? Could this be a viable way to extend QEMU
>> >> with plugins?
>> >
>> > For frequent events such as the ones mentioned above, I am
>> > not sure plugins can be efficiently implemented under
>> > tracing.
>>
>> I assume some form of helper-per-instrumented-event/insn is still going
>> to be needed though? We are not considering some sort of EBF craziness?
>
> Helper, yes. But one that points directly to plugin code.

It would be nice if the logic the inserts the trace helper vs a direct
call could be shared. I guess I'd have to see the implementation to see
how ugly it gets.

>
>> > For others (e.g. cpu_init events), sure, they could.
>> > But still, differently from tracers, plugins can come and go
>> > anytime, so I am not convinced that merging the two features
>> > is a good idea.
>>
>> I don't think we have to mirror tracepoints and plugin points but I'm in
>> favour of sharing the general mechanism and tooling rather than having a
>> whole separate set of hooks. We certainly don't want anything like:
>>
>>           trace_exec_tb(tb, pc);
>>           plugin_exec_tb(tb, pc);
>>
>> scattered throughout the code where the two do align.
>
> We could have something like
>
> 	plugin_trace_exec_tb(tb, pc);
>
> that would expand to the two lines above. Or similar.
>
> So I agree with you that in some cases the "trace points"
> for both tracing and plugin might be the same, perhaps
> identical. But that doesn't necessarily mean that making
> plugins a subset of tracing is a good idea.

But we can avoid having plugin-points and trace-events duplicating stuff
as well? I guess you want to avoid having the generated code fragments
for plugins?

The other nice property was avoiding re-duplicating output logic for
"filter" style operations. However I didn't actually included such an
example in the series. I was pondering a QEMU powered PLT/library call
tracer to demonstrate that sort of thing.

> I think sharing my plugin implementation will help the
> discussion. I'll share it as soon as I can (my QEMU plate
> is full already trying to merge a couple of other features
> first).

Sounds good.

>
> Thanks,
>
> 		Emilio


--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Pavel Dovgalyuk]

> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> Any serious analysis tool should allow for us to track all memory
> accesses so I think the guest_mem_before trace point should probably
> be split into guest_mem_before_store and guest_mem_after_load. We
> could go the whole hog and add potential trace points for start/end of
> all memory operations.

I wanted to ask about memory tracing and found this one.
Is it possible to use tracepoints for capturing all memory accesses?
In our implementation we insert helpers before and after tcg read/write operations.

Pavel Dovgalyuk

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> Any serious analysis tool should allow for us to track all memory
>> accesses so I think the guest_mem_before trace point should probably
>> be split into guest_mem_before_store and guest_mem_after_load. We
>> could go the whole hog and add potential trace points for start/end of
>> all memory operations.
>
> I wanted to ask about memory tracing and found this one.
> Is it possible to use tracepoints for capturing all memory accesses?
> In our implementation we insert helpers before and after tcg
> read/write operations.

The current tracepoint isn't enough but yes I think we could. The first
thing I need to do is de-macrofy the atomic helpers a little just to
make it a bit simpler to add the before/after tracepoints.

>
> Pavel Dovgalyuk


--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Pavel Dovgalyuk]

> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> 
> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> >> Any serious analysis tool should allow for us to track all memory
> >> accesses so I think the guest_mem_before trace point should probably
> >> be split into guest_mem_before_store and guest_mem_after_load. We
> >> could go the whole hog and add potential trace points for start/end of
> >> all memory operations.
> >
> > I wanted to ask about memory tracing and found this one.
> > Is it possible to use tracepoints for capturing all memory accesses?
> > In our implementation we insert helpers before and after tcg
> > read/write operations.
> 
> The current tracepoint isn't enough but yes I think we could. The first
> thing I need to do is de-macrofy the atomic helpers a little just to
> make it a bit simpler to add the before/after tracepoints.

But memory accesses can use 'fast path' without the helpers.
Thus you still need inserting the new helper for that case.

Pavel Dovgalyuk

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>>
>> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> >> Any serious analysis tool should allow for us to track all memory
>> >> accesses so I think the guest_mem_before trace point should probably
>> >> be split into guest_mem_before_store and guest_mem_after_load. We
>> >> could go the whole hog and add potential trace points for start/end of
>> >> all memory operations.
>> >
>> > I wanted to ask about memory tracing and found this one.
>> > Is it possible to use tracepoints for capturing all memory accesses?
>> > In our implementation we insert helpers before and after tcg
>> > read/write operations.
>>
>> The current tracepoint isn't enough but yes I think we could. The first
>> thing I need to do is de-macrofy the atomic helpers a little just to
>> make it a bit simpler to add the before/after tracepoints.
>
> But memory accesses can use 'fast path' without the helpers.
> Thus you still need inserting the new helper for that case.

trace_guest_mem_before_tcg in tcg-op.c already does this but currently
only before operations. That's why I want to split it and pass the
load/store value register values into the helpers.

>
> Pavel Dovgalyuk


--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Pavel Dovgalyuk]

> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> 
> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> >>
> >> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> >> >> Any serious analysis tool should allow for us to track all memory
> >> >> accesses so I think the guest_mem_before trace point should probably
> >> >> be split into guest_mem_before_store and guest_mem_after_load. We
> >> >> could go the whole hog and add potential trace points for start/end of
> >> >> all memory operations.
> >> >
> >> > I wanted to ask about memory tracing and found this one.
> >> > Is it possible to use tracepoints for capturing all memory accesses?
> >> > In our implementation we insert helpers before and after tcg
> >> > read/write operations.
> >>
> >> The current tracepoint isn't enough but yes I think we could. The first
> >> thing I need to do is de-macrofy the atomic helpers a little just to
> >> make it a bit simpler to add the before/after tracepoints.
> >
> > But memory accesses can use 'fast path' without the helpers.
> > Thus you still need inserting the new helper for that case.
> 
> trace_guest_mem_before_tcg in tcg-op.c already does this but currently
> only before operations. That's why I want to split it and pass the
> load/store value register values into the helpers.

One more question about your trace points.
In case of using trace point on every instruction execution, we may need
accessing vCPU registers (including the flags). Are they valid in such cases?
I'm asking, because at least i386 translation optimizes writebacks.

Pavel Dovgalyuk

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>>
>> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> >> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> >>
>> >> >> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> >> >> Any serious analysis tool should allow for us to track all memory
>> >> >> accesses so I think the guest_mem_before trace point should probably
>> >> >> be split into guest_mem_before_store and guest_mem_after_load. We
>> >> >> could go the whole hog and add potential trace points for start/end of
>> >> >> all memory operations.
>> >> >
>> >> > I wanted to ask about memory tracing and found this one.
>> >> > Is it possible to use tracepoints for capturing all memory accesses?
>> >> > In our implementation we insert helpers before and after tcg
>> >> > read/write operations.
>> >>
>> >> The current tracepoint isn't enough but yes I think we could. The first
>> >> thing I need to do is de-macrofy the atomic helpers a little just to
>> >> make it a bit simpler to add the before/after tracepoints.
>> >
>> > But memory accesses can use 'fast path' without the helpers.
>> > Thus you still need inserting the new helper for that case.
>>
>> trace_guest_mem_before_tcg in tcg-op.c already does this but currently
>> only before operations. That's why I want to split it and pass the
>> load/store value register values into the helpers.
>
> One more question about your trace points.
> In case of using trace point on every instruction execution, we may need
> accessing vCPU registers (including the flags). Are they valid in such
> cases?

They are probably valid but the tricky bit will be doing it in a way
that doesn't expose the internals of the TCG. Maybe we could exploit the
GDB interface for this or come up with a named referencex API.

> I'm asking, because at least i386 translation optimizes writebacks.

How so? I have to admit the i386 translation code is the most opaque to
me but I wouldn't have thought changing the semantics of the guests
load/store operations would be a sensible idea.

Of course now you mention it my thoughts about memory tracing have been
influenced by nice clean RISCy load/store architectures where it's rare
to have calculation ops working directly with memory.

>
> Pavel Dovgalyuk


--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Pavel Dovgalyuk]

> From: Alex Bennée [mailto:alex.bennee@linaro.org]
> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
> > One more question about your trace points.
> > In case of using trace point on every instruction execution, we may need
> > accessing vCPU registers (including the flags). Are they valid in such
> > cases?
> 
> They are probably valid but the tricky bit will be doing it in a way
> that doesn't expose the internals of the TCG. Maybe we could exploit the
> GDB interface for this or come up with a named referencex API.
> 
> > I'm asking, because at least i386 translation optimizes writebacks.
> 
> How so? I have to admit the i386 translation code is the most opaque to
> me but I wouldn't have thought changing the semantics of the guests
> load/store operations would be a sensible idea.

Writeback to the registers (say EFLAGS), not to the memory.

Pavel Dovgalyuk

Re: [Qemu-devel] [RFC PATCH 00/21] Trace updates and plugin RFC

[Alex Bennée]

Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:

>> From: Alex Bennée [mailto:alex.bennee@linaro.org]
>> Pavel Dovgalyuk <dovgaluk@ispras.ru> writes:
>> > One more question about your trace points.
>> > In case of using trace point on every instruction execution, we may need
>> > accessing vCPU registers (including the flags). Are they valid in such
>> > cases?
>>
>> They are probably valid but the tricky bit will be doing it in a way
>> that doesn't expose the internals of the TCG. Maybe we could exploit the
>> GDB interface for this or come up with a named referencex API.
>>
>> > I'm asking, because at least i386 translation optimizes writebacks.
>>
>> How so? I have to admit the i386 translation code is the most opaque to
>> me but I wouldn't have thought changing the semantics of the guests
>> load/store operations would be a sensible idea.
>
> Writeback to the registers (say EFLAGS), not to the memory.

Ahh lazy evaluation of (status) flags. Well having dug around gdbstub it
looks like we may get that wrong in for eflags anyway.

I think what is probably required is:

  - a hook in TranslatorOps, resolve_all?
  - an interface to named things registered with tcg_global_mem_new_*

And a way for the plugin to assert that any register accessed via this
is consistent at the point in the runtime the plugin hook is called.

I wonder what other front ends might have this sort of lazy/partial evaluation?

--
Alex Bennée