Trace updates and plugin RFC
cover Trace updates and plugin RFC
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 returnsAfter 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
Signature · 1 line
2.17.1
RFC PATCH 1/21 util/log: allow -dfilter to stack
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.
--- include/qemu/log.h | 1 + tests/test-logging.c | 14 ++++++++++++++ util/log.c | 23 +++++++++++++++++------ 3 files changed, 32 insertions(+), 6 deletions(-)
include/qemu/log.h +1 -0
@@ -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);
tests/test-logging.c +14 -0
@@ -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);
util/log.c +17 -6
@@ -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;
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 01/21] util/log: allow -dfilter to stack
Quoted 13 lines · 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_arrayit 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.
Quoted 6 lines
Signed-off-by Alex Bennée <[email protected]>--- include/qemu/log.h | 1 + tests/test-logging.c | 14 ++++++++++++++ util/log.c | 23 +++++++++++++++++------ 3 files changed, 32 insertions(+), 6 deletions(-)
r~
RFC PATCH 2/21 util/log: add qemu_dfilter_append_range()
In reply to Alex BennéeThis allows us to add to the dfilter range as we go.
--- include/qemu/log.h | 1 + util/log.c | 6 ++++++ 2 files changed, 7 insertions(+)
include/qemu/log.h +1 -0
@@ -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);
util/log.c +6 -0
@@ -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 ) {
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 02/21] util/log: add qemu_dfilter_append_range()
Quoted 7 lines · Alex Bennée
This allows us to add to the dfilter range as we go.
Signed-off-by Alex Bennée <[email protected]>--- include/qemu/log.h | 1 + util/log.c | 6 ++++++ 2 files changed, 7 insertions(+)
r~
RFC PATCH 3/21 linux-user: add -dfilter progtext shortcut
In reply to Alex BennéeWhen 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.
--- linux-user/main.c | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-)
linux-user/main.c +15 -1
@@ -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 ();
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 03/21] linux-user: add -dfilter progtext shortcut
Quoted 9 lines · 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 <[email protected]>Reviewed-by Laurent Vivier <[email protected]>--- linux-user/main.c | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-)
r~
RFC PATCH 4/21 trace: enable the exec_tb trace events
In reply to Alex BennéeOur 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.
--- accel/tcg/trace-events | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-)
accel/tcg/trace-events +5 -4
@@ -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"
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 04/21] trace: enable the exec_tb trace events
Quoted 8 lines · 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 <[email protected]>--- accel/tcg/trace-events | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-)
r~
Re: [Qemu-devel] [RFC PATCH 04/21] trace: enable the exec_tb trace events
In reply to Alex BennéeQuoted 3 lines · 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.
[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
Quoted 10 lines · Emilio G. Cota
Quoted 3 lines · 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.
[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.]
Quoted 4 lines
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.
Quoted 4 lines
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.
Quoted 4 lines
Thanks,
E.
--
Alex Bennée
RFC PATCH 5/21 trace: keep a count of trace-point hits
In reply to Alex BennéeWhen 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.
--- scripts/tracetool/backend/simple.py | 2 ++ trace/event-internal.h | 1 + 2 files changed, 3 insertions(+)
scripts/tracetool/backend/simple.py +2 -0
@@ -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;', ' }',
trace/event-internal.h +1 -0
@@ -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);
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 05/21] trace: keep a count of trace-point hits
scripts/tracetool/backend/simple.py def generate_c(event, group): · line 88
Quoted 9 lines · Alex Bennée
scripts/tracetool/backend/simple.py +2
-0@@ -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~
RFC PATCH 6/21 trace: show trace point counts in the monitor
In reply to Alex BennéeNow we have counts for each trace point we can expose them in the monitor when the user queries what trace points are available.
--- monitor.c | 5 +++-- qapi/trace.json | 3 ++- trace/qmp.c | 1 + 3 files changed, 6 insertions(+), 3 deletions(-)
monitor.c +3 -2
@@ -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); }
qapi/trace.json +2 -1
@@ -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:
trace/qmp.c +1 -0
@@ -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 ;
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 06/21] trace: show trace point counts in the monitor
Quoted 9 lines · 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 <[email protected]>--- 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.
r~
Re: [Qemu-devel] [RFC PATCH 06/21] trace: show trace point counts in the monitor
In reply to Alex BennéeQuoted 32 lines · 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 <[email protected]>--- monitor.c | 5 +++-- qapi/trace.json | 3 ++- trace/qmp.c | 1 + 3 files changed, 6 insertions(+), 3 deletions(-)monitor.c +3
-2@@ -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); }qapi/trace.json +0
-0
qapi/trace.json line 36
Quoted 4 lines
qapi/trace.json +1
-0@@ -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".
Quoted 17 lines
qapi/trace.json +1
-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:trace/qmp.c +0
-0
trace/qmp.c TraceEventInfoList *qmp_trace_event_get_state(const char *name, · line 105
Quoted 4 lines
trace/qmp.c +1
-0@@ -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?
Quoted 3 lines
trace/qmp.c +0
-0if (!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
In reply to Alex BennéeQuoted 4 lines · * Alex Bennée ([email protected]) 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 <[email protected]>
Quoted 59 lines
--- monitor.c | 5 +++-- qapi/trace.json | 3 ++- trace/qmp.c | 1 + 3 files changed, 6 insertions(+), 3 deletions(-)monitor.c +3
-2@@ -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); }qapi/trace.json +2
-1@@ -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:trace/qmp.c +1
-0@@ -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 ;Signature · 1 line
2.17.1
--
Dr. David Alan Gilbert / [email protected] / Manchester, UK
RFC PATCH 7/21 accel/tcg/cputlb: convert tlb_flush debugging into trace events
In reply to Alex BennéeGiven 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.
---
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(-)
accel/tcg/cputlb.c +42 -30
@@ -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)); }
accel/tcg/trace-events +16 -0
@@ -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
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 07/21] accel/tcg/cputlb: convert tlb_flush debugging into trace events
accel/tcg/cputlb.c static void tlb_flush_nocheck(CPUState *cpu) · line 144
Quoted 3 lines · Alex Bennée
accel/tcg/cputlb.c +2
-0+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
Quoted 6 lines · Richard Henderson
accel/tcg/cputlb.c static void tlb_flush_nocheck(CPUState *cpu) · line 144
Quoted 3 lines · Alex Bennée
accel/tcg/cputlb.c +2
-0+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
Quoted 8 lines · Alex Bennée
Quoted 5 lines · Richard Henderson
Quoted 3 lines · Alex Bennée
accel/tcg/cputlb.c +2
-0+trace_tlb_flush_all_work (cpu->cpu_index);tlb_flush_nocheck (cpu); +trace_tlb_flush_work_complete (__LINE__, cpu->cpu_index);
Quoted 5 lines
Quoted 1 line
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~
RFC PATCH 8/21 accel/tcg/cputlb: convert remaining tlb_debug() to trace events
In reply to Alex BennéeThe 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.
--- accel/tcg/cputlb.c | 27 +++++---------------------- accel/tcg/trace-events | 5 +++++ 2 files changed, 10 insertions(+), 22 deletions(-)
accel/tcg/cputlb.c +5 -22
@@ -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 ) {/*
accel/tcg/trace-events +5 -0
@@ -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)
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 08/21] accel/tcg/cputlb: convert remaining tlb_debug() to trace events
Quoted 2 lines · Alex Bennée
To avoid overly long lines in trace events I've split the event into
tlb_set_pageandtlb_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
Quoted 6 lines · Richard Henderson
Quoted 2 lines · Alex Bennée
To avoid overly long lines in trace events I've split the event into
tlb_set_pageandtlb_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
Quoted 11 lines · Alex Bennée
Quoted 6 lines · Richard Henderson
Quoted 2 lines · Alex Bennée
To avoid overly long lines in trace events I've split the event into
tlb_set_pageandtlb_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.
Quoted 2 lines
It was mainly to shut-up checkpatch because the trace-events don't seem to do multi-line.
I would just ignore that.
r~
RFC PATCH 9/21 trace: suppress log output of trace points
In reply to Alex BennéeWhen 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.
--- util/log.c | 3 --- vl.c | 18 ++++++++++++++++-- 2 files changed, 16 insertions(+), 5 deletions(-)
util/log.c +0 -3
@@ -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) {
vl.c +16 -2
@@ -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 definedCONFIG_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 */
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 09/21] trace: suppress log output of trace points
Quoted 9 lines · 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 <[email protected]>--- util/log.c | 3 --- vl.c | 18 ++++++++++++++++-- 2 files changed, 16 insertions(+), 5 deletions(-)
r~
RFC PATCH 10/21 qom/cpu: add a cpu_exit trace event
In reply to Alex BennéeThis is useful for tracing cpu_exit events where we signal the CPU to come back to the main loop.
--- qom/cpu.c | 3 +++ qom/trace-events | 4 ++++ 2 files changed, 7 insertions(+)
qom/cpu.c +3 -0
@@ -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 ();
qom/trace-events +4 -0
@@ -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)"
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 10/21] qom/cpu: add a cpu_exit trace event
Quoted 8 lines · Alex Bennée
This is useful for tracing
cpu_exitevents where we signal the CPU to come back to the main loop.Signed-off-by Alex Bennée <[email protected]>--- qom/cpu.c | 3 +++ qom/trace-events | 4 ++++ 2 files changed, 7 insertions(+)
r~
RFC PATCH 11/21 trace: expose a plugin fn pointer in TraceEvent
In reply to Alex BennéeWe'll need somewhere to stash this later. It's up to the generated code to do the funky casting to what it really is.
--- trace/control-internal.h | 6 ++++++ trace/event-internal.h | 3 +++ 2 files changed, 9 insertions(+)
trace/control-internal.h +6 -0
@@ -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);
trace/event-internal.h +3 -0
@@ -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);
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 11/21] trace: expose a plugin fn pointer in TraceEvent
Quoted 8 lines · 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 <[email protected]>--- trace/control-internal.h | 6 ++++++ trace/event-internal.h | 3 +++ 2 files changed, 9 insertions(+)
r~
RFC PATCH 12/21 configure: expose a plugin to the trace-backends
In reply to Alex BennéeWe also enable gmodule support for use with plugins.
--- configure | 6 ++++++ 1 file changed, 6 insertions(+)
configure +6 -0
@@ -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
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 12/21] configure: expose a plugin to the trace-backends
Quoted 6 lines · Alex Bennée
We also enable gmodule support for use with plugins.
Signed-off-by Alex Bennée <[email protected]>--- configure | 6 ++++++ 1 file changed, 6 insertions(+)
r~
RFC PATCH 13/21 tracetool: generate plugin snippets
In reply to Alex Bennée--- scripts/tracetool/backend/plugin.py | 79 +++++++++++++++++++++++++++++ 1 file changed, 79 insertions(+) create mode 100644 scripts/tracetool/backend/plugin.py
scripts/tracetool/backend/plugin.py new file +79 -0
@@ -0,0 +1,79 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- + +""" +Plugin backend. +""" + +__author__ = "Alex Bennée <[email protected]>" +__copyright__ = "Copyright 2018, Alex Bennée <[email protected]>" +__license__ = "GPL version 2 or (at your option) any later version" + +__maintainer__ = "Alex Bennée" +__email__ = "[email protected]" + + +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()))
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 13/21] tracetool: generate plugin snippets
scripts/tracetool/backend/plugin.py line 31
Quoted 10 lines · Alex Bennée
scripts/tracetool/backend/plugin.py new file +10
-0+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;
scripts/tracetool/backend/plugin.py line 37
Quoted 4 lines
scripts/tracetool/backend/plugin.py new file +4
-0+def generate_h(event, group): + out(' if (!_plugin_%(api)s(%(args)s)) {', + ' return;', + ' };',
Extra ;
Quoted 1 line
+ # Forst the pre-amble, bail early if the event is not enabled and
First.
scripts/tracetool/backend/plugin.py line 63
Quoted 8 lines
scripts/tracetool/backend/plugin.py new file +8
-0+ # 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...
Review
Quoted 2 lines
(quoted diff) +2
-0+ out('', + ' _plugin_%(api)s_fn plug_fn = (_plugin_%(api)s_fn) fp;',
Likewise.
r~
RFC PATCH 14/21 trace: add support for plugin infrastructure
In reply to Alex BennéeFrom: Pavel Dovgalyuk <[email protected]>
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.
---
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
include/plugins/plugins.h new file +14 -0
@@ -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 */
include/qemu/plugins.h new file +18 -0
@@ -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 */
qemu-options.hx +10 -0
@@ -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
trace/Makefile.objs +1 -0
@@ -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
trace/plugins.c new file +139 -0
139 lines not on this page · raw message
vl.c +8 -0
@@ -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 ();
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 14/21] trace: add support for plugin infrastructure
On Fri, Oct 05, 2018 at 16:49:03 +0100, Alex Bennée wrote:
(snip)
Quoted 7 lines
trace/plugins.c new file +7
-0+static int bind_to_tracepoints (GModule *g_module,GPtrArray *events) +{ +int count =0 ; +TraceEventIter iter; +TraceEvent *ev; + +trace_event_iter_init (&iter,"*" );
trace/plugins.c line 77
Quoted 10 lines
trace/plugins.c new file +10
-0+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
In reply to Alex Bennéetrace/plugins.c line 91
Quoted 2 lines · Alex Bennée
trace/plugins.c new file +2
-0+ 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,
r~
RFC PATCH 15/21 trace: add linux-user plugin support
In reply to Alex BennéeFrom: Aaron Lindsay <[email protected]>
--- linux-user/main.c | 15 +++++++++++++++ 1 file changed, 15 insertions(+)
linux-user/main.c +15 -0
@@ -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 ;
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 15/21] trace: add linux-user plugin support
Quoted 8 lines · Alex Bennée
From: Aaron Lindsay <[email protected]>
Signed-off-by Aaron Lindsay <[email protected]>[AJB: ifdeffery]Signed-off-by Alex Bennée <[email protected]>--- linux-user/main.c | 15 +++++++++++++++ 1 file changed, 15 insertions(+)
r~
RFC PATCH 16/21 trace: add infrastructure for building plugins
In reply to Alex BennéeThis 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)
--- 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
Makefile +4 -1
@@ -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'
trace/Makefile.objs +24 -0
@@ -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
trace/plugins/Makefile.plugins new file +32 -0
@@ -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)
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 16/21] trace: add infrastructure for building plugins
trace/plugins/Makefile.plugins line 21
Quoted 3 lines · Alex Bennée
trace/plugins/Makefile.plugins new file +3
-0+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 -gQEMU_CFLAGS = $(CFLAGS) $(GLIB_CFLAGS) -I$(QEMU_SRC)/... -fno-PIE -fPIC
trace/plugins/Makefile.plugins line 29
Quoted 7 lines
trace/plugins/Makefile.plugins new file +7
-0+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
Quoted 6 lines · Richard Henderson
trace/plugins/Makefile.plugins line 21
Quoted 3 lines · Alex Bennée
trace/plugins/Makefile.plugins new file +3
-0+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) -sharedI'm not keen on defaulting to -O3.
Fair enough... I'll drop it down if not set...
Quoted 19 lines
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 -fPICtrace/plugins/Makefile.plugins line 29
Quoted 7 lines
trace/plugins/Makefile.plugins new file +7
-0+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...
Quoted 5 lines
And of course you know the second thing people are going to want is to write these plugins in C++...
r~
--
Alex Bennée
RFC PATCH 17/21 hmp: expose status of plugins to the monitor
In reply to Alex Bennée--- hmp-commands-info.hx | 17 +++++++++++++++++ include/qemu/plugins.h | 1 + monitor.c | 14 ++++++++++++++ trace/plugins.c | 15 +++++++++++++++ 4 files changed, 47 insertions(+)
hmp-commands-info.hx +17 -0
@@ -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 = "",
include/qemu/plugins.h +1 -0
@@ -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
monitor.c +14 -0
@@ -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,
trace/plugins.c +15 -0
@@ -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 ;
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 17/21] hmp: expose status of plugins to the monitor
Quoted 7 lines · Alex Bennée
Signed-off-by Alex Bennée <[email protected]>--- hmp-commands-info.hx | 17 +++++++++++++++++ include/qemu/plugins.h | 1 + monitor.c | 14 ++++++++++++++ trace/plugins.c | 15 +++++++++++++++ 4 files changed, 47 insertions(+)
r~
Re: [Qemu-devel] [RFC PATCH 17/21] hmp: expose status of plugins to the monitor
In reply to Alex BennéeQuoted 7 lines · * Alex Bennée ([email protected]) wrote:
Signed-off-by Alex Bennée <[email protected]>--- 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.
Quoted 101 lines
hmp-commands-info.hx +17
-0@@ -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 = "",include/qemu/plugins.h +1
-0@@ -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 monitor.c +14
-0@@ -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,trace/plugins.c +15
-0@@ -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 ;Signature · 1 line
2.17.1
--
Dr. David Alan Gilbert / [email protected] / Manchester, UK
Re: [Qemu-devel] [RFC PATCH 17/21] hmp: expose status of plugins to the monitor
Quoted 11 lines · Dr. David Alan Gilbert
Quoted 7 lines · * Alex Bennée ([email protected]) wrote:
Signed-off-by Alex Bennée <[email protected]>--- 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.
Quoted 1 line
Reviewed-by Dr. David Alan Gilbert <[email protected]>
RFC PATCH 18/21 linux-user: allow dumping of plugin status at end of run
In reply to Alex BennéeAs 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.
--- linux-user/exit.c | 12 ++++++++++++ util/log.c | 2 ++ 2 files changed, 14 insertions(+)
linux-user/exit.c +12 -0
@@ -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); }
util/log.c +2 -0
@@ -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 }, };
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 18/21] linux-user: allow dumping of plugin status at end of run
Quoted 10 lines · 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_TRACEflag whichqemu_plugin_status()will dump output to before we finally exit.Signed-off-by Alex Bennée <[email protected]>--- linux-user/exit.c | 12 ++++++++++++ util/log.c | 2 ++ 2 files changed, 14 insertions(+)
r~
RFC PATCH 19/21 plugins: add an example hotblocks plugin
In reply to Alex BennéeThis 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.
--- trace/plugins/hotblocks/hotblocks.c | 69 +++++++++++++++++++++++++++++ 1 file changed, 69 insertions(+) create mode 100644 trace/plugins/hotblocks/hotblocks.c
trace/plugins/hotblocks/hotblocks.c new file +69 -0
@@ -0,0 +1,69 @@ +/* +* Execution Hotblocks Plugin +* +* Copyright (c) 2018 +* Written by Alex Bennée <[email protected]> +* +* 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 , ¤t); + +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; +}
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 19/21] plugins: add an example hotblocks plugin
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
Quoted 95 lines
-----Original Message-----
From: Alex Bennée [mailto:[email protected]]
Sent: Friday, October 05, 2018 6:49 PM
To: [email protected]
Cc: [email protected]; [email protected]; [email protected]; Alex Bennée; Stefan Hajnoczi
Subject: [RFC PATCH 19/21] plugins: add an example hotblocks pluginThis 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 <[email protected]>--- trace/plugins/hotblocks/hotblocks.c | 69 +++++++++++++++++++++++++++++ 1 file changed, 69 insertions(+) create mode 100644 trace/plugins/hotblocks/hotblocks.ctrace/plugins/hotblocks/hotblocks.c new file +69
-1@@ -0,0 +1,69 @@ +/* +* Execution Hotblocks Plugin +* +* Copyright (c) 2018 +* Written by Alex Bennée <[email protected]> +* +* 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 , ¤t); + +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
Quoted 6 lines · 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.
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.
Quoted 90 lines
Pavel Dovgalyuk
Quoted 87 lines
-----Original Message-----
From: Alex Bennée [mailto:[email protected]]
Sent: Friday, October 05, 2018 6:49 PM
To: [email protected]
Cc: [email protected]; [email protected]; [email protected]; Alex Bennée; Stefan Hajnoczi
Subject: [RFC PATCH 19/21] plugins: add an example hotblocks pluginThis 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 <[email protected]>--- trace/plugins/hotblocks/hotblocks.c | 69 +++++++++++++++++++++++++++++ 1 file changed, 69 insertions(+) create mode 100644 trace/plugins/hotblocks/hotblocks.ctrace/plugins/hotblocks/hotblocks.c new file +63
-0@@ -0,0 +1,69 @@ +/* +* Execution Hotblocks Plugin +* +* Copyright (c) 2018 +* Written by Alex Bennée <[email protected]> +* +* 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 , ¤t); + +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);
Quoted 8 lines
Quoted 8 lines
trace/plugins/hotblocks/hotblocks.c new file +6
-1+ } +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
In reply to Alex Bennéetrace/plugins/hotblocks/hotblocks.c line 44
Quoted 12 lines · Alex Bennée
trace/plugins/hotblocks/hotblocks.c new file +12
-0+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
Quoted 16 lines · Richard Henderson
trace/plugins/hotblocks/hotblocks.c line 44
Quoted 12 lines · Alex Bennée
trace/plugins/hotblocks/hotblocks.c new file +12
-0+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.
Quoted 3 lines
r~
--
Alex Bennée
RFC PATCH 20/21 plugins: add hotness summary to hotblocks
In reply to Alex Bennée--- trace/plugins/hotblocks/hotblocks.c | 33 ++++++++++++++++++++++++++++- 1 file changed, 32 insertions(+), 1 deletion(-)
trace/plugins/hotblocks/hotblocks.c +32 -1
@@ -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;
Signature · 1 line
2.17.1
Re: [Qemu-devel] [RFC PATCH 20/21] plugins: add hotness summary to hotblocks
Quoted 4 lines · Alex Bennée
Signed-off-by Alex Bennée <[email protected]>--- 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~
RFC PATCH 21/21 plugin: add tlbflush stats plugin
In reply to Alex BennéeThis 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
--- trace/plugins/tlbflush/tlbflush.c | 283 ++++++++++++++++++++++++++++++ 1 file changed, 283 insertions(+) create mode 100644 trace/plugins/tlbflush/tlbflush.c
trace/plugins/tlbflush/tlbflush.c new file +283 -0
@@ -0,0 +1,283 @@ +/* +* Execution Hotblocks Plugin +* +* Copyright (c) 2018 +* Written by Alex Bennée <[email protected]> +* +* 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 , ¤t); + +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 , ¤t); + +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 , ¤t); + +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 , ¤t); + 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; +}
Signature · 1 line
2.17.1
On Fri, Oct 05, 2018 at 16:48:49 +0100, Alex Bennée wrote:
(snip)
Quoted 6 lines
==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.
Quoted 8 lines
==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.
Quoted 6 lines
===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.
Quoted 5 lines
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 thecpu_ldstmacros 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.
Quoted 2 lines
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
Quoted 11 lines · Emilio G. Cota
On Fri, Oct 05, 2018 at 16:48:49 +0100, Alex Bennée wrote:
(snip)Quoted 6 lines
==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.
Quoted 10 lines
Quoted 9 lines
==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?
Quoted 11 lines
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.
Quoted 2 lines
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.
Quoted 8 lines
Quoted 7 lines
===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.
Quoted 4 lines
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.
Quoted 10 lines
Quoted 6 lines
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 thecpu_ldstmacros 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.
Quoted 7 lines
Quoted 3 lines
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?
Quoted 4 lines
For others (e.g.
cpu_initevents), 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.
Quoted 4 lines
Thanks,
Emilio
--
Alex Bennée
Hi Alex,
Quoted 106 lines · Alex Bennée
Quoted 11 lines · Emilio G. Cota
On Fri, Oct 05, 2018 at 16:48:49 +0100, Alex Bennée wrote:
(snip)Quoted 6 lines
==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.
Quoted 10 lines
Quoted 9 lines
==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?
Quoted 11 lines
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.
Quoted 2 lines
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.
Quoted 8 lines
Quoted 7 lines
===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.
Quoted 4 lines
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_indexin 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.
Quoted 10 lines
Quoted 6 lines
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 thecpu_ldstmacros 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.
Quoted 7 lines
Quoted 3 lines
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?
Quoted 4 lines
For others (e.g.
cpu_initevents), 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.
Quoted 8 lines
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).
Quoted 9 lines
Quoted 4 lines
Thanks,
Emilio
--
Alex Bennée
Quoted 7 lines · Alex Bennée
Quoted 3 lines · Emilio G. Cota
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.
Quoted 9 lines
Quoted 6 lines
Quoted 2 lines
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.
Quoted 5 lines
Quoted 4 lines
For others (e.g.
cpu_initevents), 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.
Quoted 8 lines
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
Quoted 10 lines · Emilio G. Cota
Quoted 7 lines · Alex Bennée
Quoted 3 lines · Emilio G. Cota
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.
Quoted 4 lines
Quoted 4 lines
Quoted 4 lines
Quoted 3 lines
So what do people think? Could this be a viable way to extend QEMU with plugins?
Quoted 8 lines
Quoted 6 lines
Quoted 3 lines
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.
Quoted 17 lines
Quoted 6 lines
Quoted 5 lines
For others (e.g.
cpu_initevents), 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.Quoted 8 lines
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
Quoted 8 lines
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.
Quoted 4 lines
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.
Quoted 4 lines
Thanks,
Emilio
--
Alex Bennée
Quoted 6 lines
From: Alex Bennée [mailto:[email protected]]
Any serious analysis tool should allow for us to track all memory accesses so I think theguest_mem_beforetrace point should probably be split intoguest_mem_before_storeandguest_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
Quoted 11 lines · Pavel Dovgalyuk
Quoted 6 lines
From: Alex Bennée [mailto:[email protected]]
Any serious analysis tool should allow for us to track all memory accesses so I think theguest_mem_beforetrace point should probably be split intoguest_mem_before_storeandguest_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.
Quoted 2 lines
Pavel Dovgalyuk
--
Alex Bennée
Quoted 10 lines
From: Alex Bennée [mailto:[email protected]]
Quoted 7 lines · Pavel Dovgalyuk
Quoted 6 lines
From: Alex Bennée [mailto:[email protected]]
Any serious analysis tool should allow for us to track all memory accesses so I think theguest_mem_beforetrace point should probably be split intoguest_mem_before_storeandguest_mem_after_load. We could go the whole hog and add potential trace points for start/end of all memory operations.
Quoted 8 lines
Quoted 4 lines
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
Quoted 15 lines · Pavel Dovgalyuk
Quoted 15 lines
From: Alex Bennée [mailto:[email protected]]
Quoted 11 lines · Pavel Dovgalyuk
Quoted 6 lines
From: Alex Bennée [mailto:[email protected]]
Any serious analysis tool should allow for us to track all memory accesses so I think theguest_mem_beforetrace point should probably be split intoguest_mem_before_storeandguest_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.
Quoted 6 lines
Quoted 3 lines
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.
Quoted 2 lines
Pavel Dovgalyuk
--
Alex Bennée
Quoted 22 lines
From: Alex Bennée [mailto:[email protected]]
Quoted 19 lines · Pavel Dovgalyuk
Quoted 18 lines
From: Alex Bennée [mailto:[email protected]]
Quoted 11 lines · Pavel Dovgalyuk
Quoted 6 lines
From: Alex Bennée [mailto:[email protected]]
Any serious analysis tool should allow for us to track all memory accesses so I think theguest_mem_beforetrace point should probably be split intoguest_mem_before_storeandguest_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.
Quoted 6 lines
Quoted 2 lines
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_tcgintcg-op.calready 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
Quoted 25 lines · Pavel Dovgalyuk
Quoted 25 lines
From: Alex Bennée [mailto:[email protected]]
Quoted 21 lines · Pavel Dovgalyuk
Quoted 10 lines
From: Alex Bennée [mailto:[email protected]]
Quoted 7 lines · Pavel Dovgalyuk
Quoted 6 lines
From: Alex Bennée [mailto:[email protected]]
Any serious analysis tool should allow for us to track all memory accesses so I think theguest_mem_beforetrace point should probably be split intoguest_mem_before_storeandguest_mem_after_load. We could go the whole hog and add potential trace points for start/end of all memory operations.Quoted 8 lines
Quoted 4 lines
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.
Quoted 8 lines
Quoted 3 lines
trace_guest_mem_before_tcgintcg-op.calready 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.
Quoted 1 line
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.
Quoted 2 lines
Pavel Dovgalyuk
--
Alex Bennée
Quoted 11 lines
From: Alex Bennée [mailto:[email protected]]
Quoted 4 lines · Pavel Dovgalyuk
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.
Quoted 5 lines
Quoted 1 line
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
Quoted 11 lines · Pavel Dovgalyuk
Quoted 11 lines
From: Alex Bennée [mailto:[email protected]]
Quoted 4 lines · Pavel Dovgalyuk
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.
Quoted 7 lines
Quoted 5 lines
Quoted 1 line
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