qemu-devel.nongnu.org archive mirror
 help / color / mirror / Atom feed
* [Qemu-devel] trace: timestamps, core IDs, and file creation
@ 2016-01-13 23:13 Hollis Blanchard
  2016-02-08 15:30 ` Stefan Hajnoczi
  2016-02-08 18:01 ` Alex Bennée
  0 siblings, 2 replies; 11+ messages in thread
From: Hollis Blanchard @ 2016-01-13 23:13 UTC (permalink / raw)
  To: Stefan Hajnoczi; +Cc: QEMU Developers

Hi Stefan, I've been starting to use qemu tracing and found it quite 
useful. I have a couple comments about the trace events in general:

The event timestamps are host time (get_clock()). I'm correlating qemu 
events with other logs (using icount), so host time is unhelpful. Could 
we use cpu_get_clock() instead? (Trace events are used in other tools 
like qemu-io, where guest time doesn't exist, and there we could 
continue to use get_clock().)

When trying to understand multi-core guest behavior, it's pretty 
important to know which core is performing the traced action (e.g. 
MMIO). Would it make sense to automatically embed the core index, like 
the timestamp, or do you think it should be encoded in each individual 
tracepoint?

Right now, the simple tracepoint backend creates a trace file even when 
no events are active and no -trace options are present. Compounding the 
situation, omitting "-trace file=foo" results in the directory being 
littered with trace-NNNN files... could we create the file only when 
tracing is activated? And maybe with a more predictable name?

-- 
Hollis Blanchard
Mentor Graphics Emulation Division

^ permalink raw reply	[flat|nested] 11+ messages in thread

* Re: [Qemu-devel] trace: timestamps, core IDs, and file creation
  2016-01-13 23:13 [Qemu-devel] trace: timestamps, core IDs, and file creation Hollis Blanchard
@ 2016-02-08 15:30 ` Stefan Hajnoczi
  2016-02-08 16:29   ` Lluís Vilanova
                     ` (2 more replies)
  2016-02-08 18:01 ` Alex Bennée
  1 sibling, 3 replies; 11+ messages in thread
From: Stefan Hajnoczi @ 2016-02-08 15:30 UTC (permalink / raw)
  To: Hollis Blanchard; +Cc: QEMU Developers

[-- Attachment #1: Type: text/plain, Size: 2824 bytes --]

On Wed, Jan 13, 2016 at 03:13:02PM -0800, Hollis Blanchard wrote:
> Hi Stefan, I've been starting to use qemu tracing and found it quite useful.
> I have a couple comments about the trace events in general:

Sorry for the late reply.

> The event timestamps are host time (get_clock()). I'm correlating qemu
> events with other logs (using icount), so host time is unhelpful. Could we
> use cpu_get_clock() instead? (Trace events are used in other tools like
> qemu-io, where guest time doesn't exist, and there we could continue to use
> get_clock().)

It must be possible to trace code while the guest CPUs are stopped, so
cpu_get_clock() on own breaks existing users.

If the CPU clock is more convenient for you, perhaps you can add an
option to use that clocksource?

> When trying to understand multi-core guest behavior, it's pretty important
> to know which core is performing the traced action (e.g. MMIO). Would it
> make sense to automatically embed the core index, like the timestamp, or do
> you think it should be encoded in each individual tracepoint?

I think that Lluís has some of this stuff automated in his TCG tracing
work.  He has added special trace event types for TCG that can be
planted at code generation time as well as TB execution time.  They can
include the vcpu number automatically IIRC.

Regarding I/O emulation, we have to be careful because architecturally
some types of devices (e.g. PCI devices) don't have the concept of which
core is performing an action.  QEMU takes advantage of that with
ioeventfd where a lightweight vmexit simply marks an eventfd file
descriptor readable in the kernel and quickly returns back to vcpu
execution.  Another QEMU thread monitors the eventfd and processes the
notification and there is no concept of the current vcpu at that point.

It might be easiest to include the vcpu id in the trace event explicitly
for now.

> Right now, the simple tracepoint backend creates a trace file even when no
> events are active and no -trace options are present. Compounding the
> situation, omitting "-trace file=foo" results in the directory being
> littered with trace-NNNN files... could we create the file only when tracing
> is activated? And maybe with a more predictable name?

It should be possible to create the file only if traces are actually
generated.  I guess this wasn't done for simplicity and because the
write-out thread needs to empty the ring buffer as quickly as possible
to avoid dropping trace data.

The names contains the QEMU pid.  Although the pid isn't predictable it
is useful for correlating with system logs, host performance tools, etc.

You can override the name with -trace file=foo.log if you want.

Do you have an idea for another automatic file naming scheme?

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

^ permalink raw reply	[flat|nested] 11+ messages in thread

* Re: [Qemu-devel] trace: timestamps, core IDs, and file creation
  2016-02-08 15:30 ` Stefan Hajnoczi
@ 2016-02-08 16:29   ` Lluís Vilanova
  2016-02-08 18:51   ` [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted Hollis Blanchard
  2016-02-08 19:59   ` [Qemu-devel] trace: timestamps, core IDs, and file creation Hollis Blanchard
  2 siblings, 0 replies; 11+ messages in thread
From: Lluís Vilanova @ 2016-02-08 16:29 UTC (permalink / raw)
  To: Stefan Hajnoczi; +Cc: Hollis Blanchard, QEMU Developers

Stefan Hajnoczi writes:

> On Wed, Jan 13, 2016 at 03:13:02PM -0800, Hollis Blanchard wrote:
>> Hi Stefan, I've been starting to use qemu tracing and found it quite useful.
>> I have a couple comments about the trace events in general:

> Sorry for the late reply.

>> The event timestamps are host time (get_clock()). I'm correlating qemu
>> events with other logs (using icount), so host time is unhelpful. Could we
>> use cpu_get_clock() instead? (Trace events are used in other tools like
>> qemu-io, where guest time doesn't exist, and there we could continue to use
>> get_clock().)

> It must be possible to trace code while the guest CPUs are stopped, so
> cpu_get_clock() on own breaks existing users.

> If the CPU clock is more convenient for you, perhaps you can add an
> option to use that clocksource?

Hmmmm, what about abusing the "vcpu" event property I sent to automatically emit
the vCPU icount? We could make that a compile-time option. This also makes me
think that the print format for the vCPU can be auto-generated by tracetool (it
must now be set explicitly), so that what's printed can be easily interchanged.

We can make that a follow-up series.


>> When trying to understand multi-core guest behavior, it's pretty important
>> to know which core is performing the traced action (e.g. MMIO). Would it
>> make sense to automatically embed the core index, like the timestamp, or do
>> you think it should be encoded in each individual tracepoint?

> I think that Lluís has some of this stuff automated in his TCG tracing
> work.  He has added special trace event types for TCG that can be
> planted at code generation time as well as TB execution time.  They can
> include the vcpu number automatically IIRC.

Yup, that's the last series I sent, which hasn't been reviewed yet:

  https://lists.gnu.org/archive/html/qemu-devel/2016-01/msg05996.html

If any event (including outside tcg code) has a pointer to the "guilty" vCPU,
support for showing the vCPU can be easily added.


> Regarding I/O emulation, we have to be careful because architecturally
> some types of devices (e.g. PCI devices) don't have the concept of which
> core is performing an action.  QEMU takes advantage of that with
> ioeventfd where a lightweight vmexit simply marks an eventfd file
> descriptor readable in the kernel and quickly returns back to vcpu
> execution.  Another QEMU thread monitors the eventfd and processes the
> notification and there is no concept of the current vcpu at that point.

> It might be easiest to include the vcpu id in the trace event explicitly
> for now.

See the two responses above.


Cheers,
  Lluis

^ permalink raw reply	[flat|nested] 11+ messages in thread

* Re: [Qemu-devel] trace: timestamps, core IDs, and file creation
  2016-01-13 23:13 [Qemu-devel] trace: timestamps, core IDs, and file creation Hollis Blanchard
  2016-02-08 15:30 ` Stefan Hajnoczi
@ 2016-02-08 18:01 ` Alex Bennée
  2016-02-08 18:34   ` Alex Bennée
  1 sibling, 1 reply; 11+ messages in thread
From: Alex Bennée @ 2016-02-08 18:01 UTC (permalink / raw)
  To: Hollis Blanchard; +Cc: Stefan Hajnoczi, QEMU Developers


Hollis Blanchard <hollis_blanchard@mentor.com> writes:

> Hi Stefan, I've been starting to use qemu tracing and found it quite
> useful. I have a couple comments about the trace events in general:
>
<snip>
> Right now, the simple tracepoint backend creates a trace file even when
> no events are active and no -trace options are present. Compounding the
> situation, omitting "-trace file=foo" results in the directory being
> littered with trace-NNNN files... could we create the file only when
> tracing is activated? And maybe with a more predictable name?

Yeah I've run into trouble when running "make check" with the simple
backend enabled. I'm not sure exactly what mechanism breaks the test but
it seems to me an invocation like:

  ./x86_64-softmmu/qemu-system-x86_64 -qtest
  unix:/tmp/qtest-9458.sock,nowait -qtest-log /dev/null -qmp
  unix:/tmp/qtest-9458.qmp,nowait -machine accel=qtest -display none -M
  pc -device pc-testdev

Shouldn't be generating anything unless an explicit file is set.

AFAICT 41fc57e44ed64cd4ab5393d83624afd897dabd4f is triggering the
default file behaviour.

I'm still digging into this.

--
Alex Bennée

^ permalink raw reply	[flat|nested] 11+ messages in thread

* Re: [Qemu-devel] trace: timestamps, core IDs, and file creation
  2016-02-08 18:01 ` Alex Bennée
@ 2016-02-08 18:34   ` Alex Bennée
  0 siblings, 0 replies; 11+ messages in thread
From: Alex Bennée @ 2016-02-08 18:34 UTC (permalink / raw)
  To: Hollis Blanchard; +Cc: Stefan Hajnoczi, QEMU Developers


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

> Hollis Blanchard <hollis_blanchard@mentor.com> writes:
>
>> Hi Stefan, I've been starting to use qemu tracing and found it quite
>> useful. I have a couple comments about the trace events in general:
>>
> <snip>
>> Right now, the simple tracepoint backend creates a trace file even when
>> no events are active and no -trace options are present. Compounding the
>> situation, omitting "-trace file=foo" results in the directory being
>> littered with trace-NNNN files... could we create the file only when
>> tracing is activated? And maybe with a more predictable name?
>
> Yeah I've run into trouble when running "make check" with the simple
> backend enabled. I'm not sure exactly what mechanism breaks the test but
> it seems to me an invocation like:
>
>   ./x86_64-softmmu/qemu-system-x86_64 -qtest
>   unix:/tmp/qtest-9458.sock,nowait -qtest-log /dev/null -qmp
>   unix:/tmp/qtest-9458.qmp,nowait -machine accel=qtest -display none -M
>   pc -device pc-testdev
>
> Shouldn't be generating anything unless an explicit file is set.
>
> AFAICT 41fc57e44ed64cd4ab5393d83624afd897dabd4f is triggering the
> default file behaviour.
>
> I'm still digging into this.

OK ignore me, that commit breaks "make check" but not while spamming the
trace-files. That must be later in my tree.


--
Alex Bennée

^ permalink raw reply	[flat|nested] 11+ messages in thread

* [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted.
  2016-02-08 15:30 ` Stefan Hajnoczi
  2016-02-08 16:29   ` Lluís Vilanova
@ 2016-02-08 18:51   ` Hollis Blanchard
  2016-02-08 20:02     ` Alex Bennée
                       ` (2 more replies)
  2016-02-08 19:59   ` [Qemu-devel] trace: timestamps, core IDs, and file creation Hollis Blanchard
  2 siblings, 3 replies; 11+ messages in thread
From: Hollis Blanchard @ 2016-02-08 18:51 UTC (permalink / raw)
  To: qemu-devel; +Cc: stefanha, Hollis Blanchard

Previously, trace record files (created by st_set_trace_file_enabled(true))
were created by the simple backend at initialization time, even if no events
were actually enabled.

As a consequence, the working directory would become littered with trace-PID
files just by enabling the simple backend at configure time, even when no
-trace options were used.

---
I've been using this to avoid creation of empty trace record files. I haven't
done any scientific performance studies, but an extra function
call/conditional/return when recording every trace event doesn't seem to have
any noticeable effect.

Signed-off-by: Hollis Blanchard <hollis_blanchard@mentor.com>
---
 trace/simple.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/trace/simple.c b/trace/simple.c
index 3fdcc82..67ccc3c 100644
--- a/trace/simple.c
+++ b/trace/simple.c
@@ -209,6 +209,8 @@ int trace_record_start(TraceBufferRecord *rec, TraceEventID event, size_t datasi
     uint64_t event_u64 = event;
     uint64_t timestamp_ns = get_clock();
 
+    st_set_trace_file_enabled(true);
+
     do {
         old_idx = g_atomic_int_get(&trace_idx);
         smp_rmb();
@@ -320,6 +322,7 @@ void st_set_trace_file_enabled(bool enable)
  */
 void st_set_trace_file(const char *file)
 {
+    /* Tracing will be re-enabled when the next event is written. */
     st_set_trace_file_enabled(false);
 
     g_free(trace_file_name);
@@ -330,8 +333,6 @@ void st_set_trace_file(const char *file)
     } else {
         trace_file_name = g_strdup_printf("%s", file);
     }
-
-    st_set_trace_file_enabled(true);
 }
 
 void st_print_trace_file_status(FILE *stream, int (*stream_printf)(FILE *stream, const char *fmt, ...))
-- 
1.9.1

^ permalink raw reply	[flat|nested] 11+ messages in thread

* Re: [Qemu-devel] trace: timestamps, core IDs, and file creation
  2016-02-08 15:30 ` Stefan Hajnoczi
  2016-02-08 16:29   ` Lluís Vilanova
  2016-02-08 18:51   ` [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted Hollis Blanchard
@ 2016-02-08 19:59   ` Hollis Blanchard
  2016-02-15 15:29     ` Stefan Hajnoczi
  2 siblings, 1 reply; 11+ messages in thread
From: Hollis Blanchard @ 2016-02-08 19:59 UTC (permalink / raw)
  To: Stefan Hajnoczi; +Cc: QEMU Developers, vilanova

[-- Attachment #1: Type: text/plain, Size: 4537 bytes --]

On 02/08/2016 07:30 AM, Stefan Hajnoczi wrote:
> On Wed, Jan 13, 2016 at 03:13:02PM -0800, Hollis Blanchard wrote:
>> The event timestamps are host time (get_clock()). I'm correlating qemu
>> events with other logs (using icount), so host time is unhelpful. Could we
>> use cpu_get_clock() instead? (Trace events are used in other tools like
>> qemu-io, where guest time doesn't exist, and there we could continue to use
>> get_clock().)
> It must be possible to trace code while the guest CPUs are stopped, so
> cpu_get_clock() on own breaks existing users.
>
> If the CPU clock is more convenient for you, perhaps you can add an
> option to use that clocksource?

"Breaks"? Is that because every trace record is assumed to have a unique 
timestamp? Who makes that assumption? Qemu's tracing infrastructure 
works fine without it...

Hmm, an option. I guess if you want to debug Qemu behavior, like "why 
are block operations taking so long", seeing host time is the most 
important thing. However, if you want debug visibility into guest 
behavior, like "how long did I run with IRQs disabled", guest time is 
the most important thing. I'm not sure when a developer should be forced 
to make that decision...?

>> When trying to understand multi-core guest behavior, it's pretty important
>> to know which core is performing the traced action (e.g. MMIO). Would it
>> make sense to automatically embed the core index, like the timestamp, or do
>> you think it should be encoded in each individual tracepoint?
> I think that Lluís has some of this stuff automated in his TCG tracing
> work.  He has added special trace event types for TCG that can be
> planted at code generation time as well as TB execution time.  They can
> include the vcpu number automatically IIRC.

Neat.

> Regarding I/O emulation, we have to be careful because architecturally
> some types of devices (e.g. PCI devices) don't have the concept of which
> core is performing an action.  QEMU takes advantage of that with
> ioeventfd where a lightweight vmexit simply marks an eventfd file
> descriptor readable in the kernel and quickly returns back to vcpu
> execution.  Another QEMU thread monitors the eventfd and processes the
> notification and there is no concept of the current vcpu at that point.

Yeah, by "MMIO" I was thinking in particular of memory.c 
instrumentation, which almost always executes in the context of a vcpu.

I'm not sure a vcpu property could work there. cpu_physical_memory_rw() 
may be executed by a machine init function, before any VCPUs are 
running. To handle that, I have a hack like this in 
memory_region_read_accessor():

         int cpu_index = -1;
         if (current_cpu)
             cpu_index = current_cpu->cpu_index;
         trace_memory_region_ops_read(cpu_index, mr, addr, tmp, size);

... and then my analysis tools, which display guest activity, know to 
ignore events with cpu_index==-1.

I'm not sure if a vcpu property could or should do the same...?

> It might be easiest to include the vcpu id in the trace event explicitly
> for now.

Mmm hmm. That could cause a lot of churn to the current set of trace 
events, but they seem to be mostly IO operations that execute outside 
VCPU context.

>> Right now, the simple tracepoint backend creates a trace file even when no
>> events are active and no -trace options are present. Compounding the
>> situation, omitting "-trace file=foo" results in the directory being
>> littered with trace-NNNN files... could we create the file only when tracing
>> is activated? And maybe with a more predictable name?
> It should be possible to create the file only if traces are actually
> generated.  I guess this wasn't done for simplicity and because the
> write-out thread needs to empty the ring buffer as quickly as possible
> to avoid dropping trace data.
>
> The names contains the QEMU pid.  Although the pid isn't predictable it
> is useful for correlating with system logs, host performance tools, etc.
>
> You can override the name with -trace file=foo.log if you want.
>
> Do you have an idea for another automatic file naming scheme?

"qemu.trace" or something static. If the log is important, the user will 
copy it anyways to give it a descriptive name, e.g. 
"out_of_memory.trace". If the log is not important, it should be 
overwritten by the next run; otherwise the workflow becomes:

qemu-system-... args args args
ls trace-*
rm trace-NNNN
qemu-system-... args args args
ls trace-*
rm trace-MMMM


Hollis Blanchard
Mentor Graphics Emulation Division

[-- Attachment #2: Type: text/html, Size: 5980 bytes --]

^ permalink raw reply	[flat|nested] 11+ messages in thread

* Re: [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted.
  2016-02-08 18:51   ` [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted Hollis Blanchard
@ 2016-02-08 20:02     ` Alex Bennée
  2016-02-15 15:52     ` Stefan Hajnoczi
  2016-02-15 15:54     ` Stefan Hajnoczi
  2 siblings, 0 replies; 11+ messages in thread
From: Alex Bennée @ 2016-02-08 20:02 UTC (permalink / raw)
  To: Hollis Blanchard; +Cc: stefanha, qemu-devel


Hollis Blanchard <hollis_blanchard@mentor.com> writes:

> Previously, trace record files (created by st_set_trace_file_enabled(true))
> were created by the simple backend at initialization time, even if no events
> were actually enabled.
>
> As a consequence, the working directory would become littered with trace-PID
> files just by enabling the simple backend at configure time, even when no
> -trace options were used.
>
> ---
> I've been using this to avoid creation of empty trace record files. I haven't
> done any scientific performance studies, but an extra function
> call/conditional/return when recording every trace event doesn't seem to have
> any noticeable effect.
>
> Signed-off-by: Hollis Blanchard <hollis_blanchard@mentor.com>
> ---
>  trace/simple.c | 5 +++--
>  1 file changed, 3 insertions(+), 2 deletions(-)
>
> diff --git a/trace/simple.c b/trace/simple.c
> index 3fdcc82..67ccc3c 100644
> --- a/trace/simple.c
> +++ b/trace/simple.c
> @@ -209,6 +209,8 @@ int trace_record_start(TraceBufferRecord *rec, TraceEventID event, size_t datasi
>      uint64_t event_u64 = event;
>      uint64_t timestamp_ns = get_clock();
>
> +    st_set_trace_file_enabled(true);
> +
>      do {
>          old_idx = g_atomic_int_get(&trace_idx);
>          smp_rmb();
> @@ -320,6 +322,7 @@ void st_set_trace_file_enabled(bool enable)
>   */
>  void st_set_trace_file(const char *file)
>  {
> +    /* Tracing will be re-enabled when the next event is written. */
>      st_set_trace_file_enabled(false);
>
>      g_free(trace_file_name);
> @@ -330,8 +333,6 @@ void st_set_trace_file(const char *file)
>      } else {
>          trace_file_name = g_strdup_printf("%s", file);
>      }
> -
> -    st_set_trace_file_enabled(true);
>  }

This fixes the "make check" bug I reported:

http://lists.nongnu.org/archive/html/qemu-devel/2016-02/msg01811.html

because by not enabling the file it doesn't attempt to flush it before
the test has started. However as it is a side-effect of the patch there
may be a better solution. However have a:

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

--
Alex Bennée

^ permalink raw reply	[flat|nested] 11+ messages in thread

* Re: [Qemu-devel] trace: timestamps, core IDs, and file creation
  2016-02-08 19:59   ` [Qemu-devel] trace: timestamps, core IDs, and file creation Hollis Blanchard
@ 2016-02-15 15:29     ` Stefan Hajnoczi
  0 siblings, 0 replies; 11+ messages in thread
From: Stefan Hajnoczi @ 2016-02-15 15:29 UTC (permalink / raw)
  To: Hollis Blanchard; +Cc: QEMU Developers, vilanova

[-- Attachment #1: Type: text/plain, Size: 5406 bytes --]

On Mon, Feb 08, 2016 at 11:59:00AM -0800, Hollis Blanchard wrote:
> On 02/08/2016 07:30 AM, Stefan Hajnoczi wrote:
> >On Wed, Jan 13, 2016 at 03:13:02PM -0800, Hollis Blanchard wrote:
> >>The event timestamps are host time (get_clock()). I'm correlating qemu
> >>events with other logs (using icount), so host time is unhelpful. Could we
> >>use cpu_get_clock() instead? (Trace events are used in other tools like
> >>qemu-io, where guest time doesn't exist, and there we could continue to use
> >>get_clock().)
> >It must be possible to trace code while the guest CPUs are stopped, so
> >cpu_get_clock() on own breaks existing users.
> >
> >If the CPU clock is more convenient for you, perhaps you can add an
> >option to use that clocksource?
> 
> "Breaks"? Is that because every trace record is assumed to have a unique
> timestamp? Who makes that assumption? Qemu's tracing infrastructure works
> fine without it...

It breaks existing users in the sense that the timestamp will not be
valid while vCPUs are paused.  Today you can trace any part of QEMU and
the timestamps will be valid even while vCPUs are paused (e.g. migration
after vm_stop()).  Having valid timestamps is important for performance
analysis so the time between two trace events can be calculated.

> Hmm, an option. I guess if you want to debug Qemu behavior, like "why are
> block operations taking so long", seeing host time is the most important
> thing. However, if you want debug visibility into guest behavior, like "how
> long did I run with IRQs disabled", guest time is the most important thing.
> I'm not sure when a developer should be forced to make that decision...?

When invoking QEMU (qemu -trace clocksource=vcpu).  It's not ideal, but
should be good enough for using the simple trace backend during
development.  In this case the developer knows what information they
want from tracing so they can decide whether to use cpu time or wall
clock time at startup.

> >Regarding I/O emulation, we have to be careful because architecturally
> >some types of devices (e.g. PCI devices) don't have the concept of which
> >core is performing an action.  QEMU takes advantage of that with
> >ioeventfd where a lightweight vmexit simply marks an eventfd file
> >descriptor readable in the kernel and quickly returns back to vcpu
> >execution.  Another QEMU thread monitors the eventfd and processes the
> >notification and there is no concept of the current vcpu at that point.
> 
> Yeah, by "MMIO" I was thinking in particular of memory.c instrumentation,
> which almost always executes in the context of a vcpu.
> 
> I'm not sure a vcpu property could work there. cpu_physical_memory_rw() may
> be executed by a machine init function, before any VCPUs are running. To
> handle that, I have a hack like this in memory_region_read_accessor():
> 
>         int cpu_index = -1;
>         if (current_cpu)
>             cpu_index = current_cpu->cpu_index;
>         trace_memory_region_ops_read(cpu_index, mr, addr, tmp, size);
> 
> ... and then my analysis tools, which display guest activity, know to ignore
> events with cpu_index==-1.
> 
> I'm not sure if a vcpu property could or should do the same...?

Your cpu_index = -1 trick seems fine to me.  I'd merge it.

Another corner case: KVM's coalesced MMIO ring.  MMIO does not
necessarily happen in the vcpu context that caused it.  Most of the time
it will but I think SMP guests could violate this.

Guest MMIO writes to coalesced MMIO physical memory regions are
accumulated in the ring buffer instead of being dispatched by memory.c
right away.  QEMU flushes the ring eventually and executes the buffered
writes.  See kvm-all.c:kvm_flush_coalesced_mmio_buffer().

> >It might be easiest to include the vcpu id in the trace event explicitly
> >for now.
> 
> Mmm hmm. That could cause a lot of churn to the current set of trace events,
> but they seem to be mostly IO operations that execute outside VCPU context.
> 
> >>Right now, the simple tracepoint backend creates a trace file even when no
> >>events are active and no -trace options are present. Compounding the
> >>situation, omitting "-trace file=foo" results in the directory being
> >>littered with trace-NNNN files... could we create the file only when tracing
> >>is activated? And maybe with a more predictable name?
> >It should be possible to create the file only if traces are actually
> >generated.  I guess this wasn't done for simplicity and because the
> >write-out thread needs to empty the ring buffer as quickly as possible
> >to avoid dropping trace data.
> >
> >The names contains the QEMU pid.  Although the pid isn't predictable it
> >is useful for correlating with system logs, host performance tools, etc.
> >
> >You can override the name with -trace file=foo.log if you want.
> >
> >Do you have an idea for another automatic file naming scheme?
> 
> "qemu.trace" or something static. If the log is important, the user will
> copy it anyways to give it a descriptive name, e.g. "out_of_memory.trace".
> If the log is not important, it should be overwritten by the next run;
> otherwise the workflow becomes:
> 
> qemu-system-... args args args
> ls trace-*
> rm trace-NNNN
> qemu-system-... args args args
> ls trace-*
> rm trace-MMMM

Then use -trace file=qemu.trace :).

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

^ permalink raw reply	[flat|nested] 11+ messages in thread

* Re: [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted.
  2016-02-08 18:51   ` [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted Hollis Blanchard
  2016-02-08 20:02     ` Alex Bennée
@ 2016-02-15 15:52     ` Stefan Hajnoczi
  2016-02-15 15:54     ` Stefan Hajnoczi
  2 siblings, 0 replies; 11+ messages in thread
From: Stefan Hajnoczi @ 2016-02-15 15:52 UTC (permalink / raw)
  To: Hollis Blanchard; +Cc: qemu-devel

[-- Attachment #1: Type: text/plain, Size: 1858 bytes --]

On Mon, Feb 08, 2016 at 10:51:55AM -0800, Hollis Blanchard wrote:
> Previously, trace record files (created by st_set_trace_file_enabled(true))
> were created by the simple backend at initialization time, even if no events
> were actually enabled.
> 
> As a consequence, the working directory would become littered with trace-PID
> files just by enabling the simple backend at configure time, even when no
> -trace options were used.
> 
> ---
> I've been using this to avoid creation of empty trace record files. I haven't
> done any scientific performance studies, but an extra function
> call/conditional/return when recording every trace event doesn't seem to have
> any noticeable effect.
> 
> Signed-off-by: Hollis Blanchard <hollis_blanchard@mentor.com>
> ---
>  trace/simple.c | 5 +++--
>  1 file changed, 3 insertions(+), 2 deletions(-)
> 
> diff --git a/trace/simple.c b/trace/simple.c
> index 3fdcc82..67ccc3c 100644
> --- a/trace/simple.c
> +++ b/trace/simple.c
> @@ -209,6 +209,8 @@ int trace_record_start(TraceBufferRecord *rec, TraceEventID event, size_t datasi
>      uint64_t event_u64 = event;
>      uint64_t timestamp_ns = get_clock();
>  
> +    st_set_trace_file_enabled(true);

trace_record_start() can be called from multiple threads.
st_set_trace_file_enabled() is not thread-safe.

One way to solve this is to use a read memory barrier to fetch trace_fp.
If it's NULL then acquire trace_lock and recheck (in case another thread
has modified it since).  Now continue with the rest of
st_set_trace_file_enabled() to open the file.

If multiple threads pile up they will just wait for trace_lock until the
first thread has completed opening the file.  Or you could use try_lock
instead and return -EBUSY to drop those events similar to the -ENOSPC
error case in trace_record_start().

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

^ permalink raw reply	[flat|nested] 11+ messages in thread

* Re: [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted.
  2016-02-08 18:51   ` [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted Hollis Blanchard
  2016-02-08 20:02     ` Alex Bennée
  2016-02-15 15:52     ` Stefan Hajnoczi
@ 2016-02-15 15:54     ` Stefan Hajnoczi
  2 siblings, 0 replies; 11+ messages in thread
From: Stefan Hajnoczi @ 2016-02-15 15:54 UTC (permalink / raw)
  To: Hollis Blanchard; +Cc: qemu-devel

[-- Attachment #1: Type: text/plain, Size: 1038 bytes --]

On Mon, Feb 08, 2016 at 10:51:55AM -0800, Hollis Blanchard wrote:
> Previously, trace record files (created by st_set_trace_file_enabled(true))
> were created by the simple backend at initialization time, even if no events
> were actually enabled.
> 
> As a consequence, the working directory would become littered with trace-PID
> files just by enabling the simple backend at configure time, even when no
> -trace options were used.
> 
> ---
> I've been using this to avoid creation of empty trace record files. I haven't
> done any scientific performance studies, but an extra function
> call/conditional/return when recording every trace event doesn't seem to have
> any noticeable effect.
> 
> Signed-off-by: Hollis Blanchard <hollis_blanchard@mentor.com>
> ---
>  trace/simple.c | 5 +++--
>  1 file changed, 3 insertions(+), 2 deletions(-)

By the way, thanks for the patch.  I didn't see it because my
maintainership scripts use my stefanha@redhat.com email account that is
listed in ./MAINTAINERS.

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

^ permalink raw reply	[flat|nested] 11+ messages in thread

end of thread, other threads:[~2016-02-15 15:54 UTC | newest]

Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-01-13 23:13 [Qemu-devel] trace: timestamps, core IDs, and file creation Hollis Blanchard
2016-02-08 15:30 ` Stefan Hajnoczi
2016-02-08 16:29   ` Lluís Vilanova
2016-02-08 18:51   ` [Qemu-devel] [PATCH] trace: only create simple backend trace files when an event is emitted Hollis Blanchard
2016-02-08 20:02     ` Alex Bennée
2016-02-15 15:52     ` Stefan Hajnoczi
2016-02-15 15:54     ` Stefan Hajnoczi
2016-02-08 19:59   ` [Qemu-devel] trace: timestamps, core IDs, and file creation Hollis Blanchard
2016-02-15 15:29     ` Stefan Hajnoczi
2016-02-08 18:01 ` Alex Bennée
2016-02-08 18:34   ` Alex Bennée

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).