[Qemu-devel] [PATCH 1/3] trace: Document programmatically enabling/disabling trace events

[Qemu-devel] [PATCH 1/3] trace: Document programmatically enabling/disabling trace events

[Stefan Hajnoczi]

The simple trace backend exports a function that can be used to
programmatically enable/disable trace events at runtime.

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
This applies to the tracing branch at:

  http://repo.or.cz/w/qemu/stefanha.git/shortlog/refs/heads/tracing-dev

 docs/tracing.txt |   11 +++++++++++
 1 files changed, 11 insertions(+), 0 deletions(-)

diff --git a/docs/tracing.txt b/docs/tracing.txt
index ec44552..abbae6b 100644
--- a/docs/tracing.txt
+++ b/docs/tracing.txt
@@ -116,6 +116,17 @@ unless you have specific needs for more advanced backends.
 * trace-event NAME on|off
   Enable/disable a given trace event.
 
+==== Enabling/disabling trace events programmatically ====
+
+The change_trace_event_state() function can be used to enable or disable trace
+events at runtime inside QEMU:
+
+    #include "trace.h"
+    
+    change_trace_event_state("virtio_irq", true); /* enable */
+    [...]
+    change_trace_event_state("virtio_irq", false); /* disable */
+
 ==== Analyzing trace files ====
 
 The "simple" backend produces binary trace files that can be formatted with the
-- 
1.7.1

[Qemu-devel] [PATCH 2/3] trace: Conform to QEMU coding style

[Stefan Hajnoczi]

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
This applies to the tracing branch at:

  http://repo.or.cz/w/qemu/stefanha.git/shortlog/refs/heads/tracing-dev

 simpletrace.c |   21 ++++++++++++++-------
 tracetool     |    3 ++-
 2 files changed, 16 insertions(+), 8 deletions(-)

diff --git a/simpletrace.c b/simpletrace.c
index 5c327af..ace009f 100644
--- a/simpletrace.c
+++ b/simpletrace.c
@@ -24,7 +24,8 @@ static FILE *trace_fp;
 
 static void trace(TraceEventID event, unsigned long x1,
                   unsigned long x2, unsigned long x3,
-                  unsigned long x4, unsigned long x5) {
+                  unsigned long x4, unsigned long x5)
+{
     struct timespec ts; /* TODO make qemu-timer.h work in qemu-io and friends */
     clock_gettime(CLOCK_MONOTONIC, &ts);
 
@@ -55,27 +56,33 @@ static void trace(TraceEventID event, unsigned long x1,
     }
 }
 
-void trace0(TraceEventID event) {
+void trace0(TraceEventID event)
+{
     trace(event, 0, 0, 0, 0, 0);
 }
 
-void trace1(TraceEventID event, unsigned long x1) {
+void trace1(TraceEventID event, unsigned long x1)
+{
     trace(event, x1, 0, 0, 0, 0);
 }
 
-void trace2(TraceEventID event, unsigned long x1, unsigned long x2) {
+void trace2(TraceEventID event, unsigned long x1, unsigned long x2)
+{
     trace(event, x1, x2, 0, 0, 0);
 }
 
-void trace3(TraceEventID event, unsigned long x1, unsigned long x2, unsigned long x3) {
+void trace3(TraceEventID event, unsigned long x1, unsigned long x2, unsigned long x3)
+{
     trace(event, x1, x2, x3, 0, 0);
 }
 
-void trace4(TraceEventID event, unsigned long x1, unsigned long x2, unsigned long x3, unsigned long x4) {
+void trace4(TraceEventID event, unsigned long x1, unsigned long x2, unsigned long x3, unsigned long x4)
+{
     trace(event, x1, x2, x3, x4, 0);
 }
 
-void trace5(TraceEventID event, unsigned long x1, unsigned long x2, unsigned long x3, unsigned long x4, unsigned long x5) {
+void trace5(TraceEventID event, unsigned long x1, unsigned long x2, unsigned long x3, unsigned long x4, unsigned long x5)
+{
     trace(event, x1, x2, x3, x4, x5);
 }
 
diff --git a/tracetool b/tracetool
index 9ce8e74..43757e3 100755
--- a/tracetool
+++ b/tracetool
@@ -169,7 +169,8 @@ linetoh_simple()
     fi
 
     cat <<EOF
-static inline void trace_$name($args) {
+static inline void trace_$name($args)
+{
     trace$argc($trace_args);
 }
 EOF
-- 
1.7.1

[Qemu-devel] [PATCH 3/3] trace: Flush trace buffer on exit

[Stefan Hajnoczi]

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
This applies to the tracing branch at:

  http://repo.or.cz/w/qemu/stefanha.git/shortlog/refs/heads/tracing-dev

 simpletrace.c |   23 +++++++++++++++--------
 1 files changed, 15 insertions(+), 8 deletions(-)

diff --git a/simpletrace.c b/simpletrace.c
index ace009f..9604ea6 100644
--- a/simpletrace.c
+++ b/simpletrace.c
@@ -22,6 +22,20 @@ static TraceRecord trace_buf[TRACE_BUF_LEN];
 static unsigned int trace_idx;
 static FILE *trace_fp;
 
+static void flush_trace_buffer(void)
+{
+    if (!trace_fp) {
+        trace_fp = fopen("/tmp/trace.log", "w");
+        if (trace_fp) {
+            atexit(flush_trace_buffer);
+        }
+    }
+    if (trace_fp) {
+        size_t unused; /* for when fwrite(3) is declared warn_unused_result */
+        unused = fwrite(trace_buf, trace_idx * sizeof(trace_buf[0]), 1, trace_fp);
+    }
+}
+
 static void trace(TraceEventID event, unsigned long x1,
                   unsigned long x2, unsigned long x3,
                   unsigned long x4, unsigned long x5)
@@ -44,15 +58,8 @@ static void trace(TraceEventID event, unsigned long x1,
     rec->x5 = x5;
 
     if (++trace_idx == TRACE_BUF_LEN) {
+        flush_trace_buffer();
         trace_idx = 0;
-
-        if (!trace_fp) {
-            trace_fp = fopen("/tmp/trace.log", "w");
-        }
-        if (trace_fp) {
-            size_t result = fwrite(trace_buf, sizeof trace_buf, 1, trace_fp);
-            result = result;
-        }
     }
 }
 
-- 
1.7.1

Re: [Qemu-devel] [PATCH 3/3] trace: Flush trace buffer on exit

[Prerna Saxena]

Hi Stefan,
On 07/07/2010 01:44 AM, Stefan Hajnoczi wrote:
> Signed-off-by: Stefan Hajnoczi<stefanha@linux.vnet.ibm.com>
> ---
> This applies to the tracing branch at:
>
>    http://repo.or.cz/w/qemu/stefanha.git/shortlog/refs/heads/tracing-dev
>
>   simpletrace.c |   23 +++++++++++++++--------
>   1 files changed, 15 insertions(+), 8 deletions(-)
>
> diff --git a/simpletrace.c b/simpletrace.c
> index ace009f..9604ea6 100644
> --- a/simpletrace.c
> +++ b/simpletrace.c
> @@ -22,6 +22,20 @@ static TraceRecord trace_buf[TRACE_BUF_LEN];
>   static unsigned int trace_idx;
>   static FILE *trace_fp;
>
> +static void flush_trace_buffer(void)
> +{
> +    if (!trace_fp) {
> +        trace_fp = fopen("/tmp/trace.log", "w");
> +        if (trace_fp) {
> +            atexit(flush_trace_buffer);
> +        }
> +    }
> +    if (trace_fp) {
> +        size_t unused; /* for when fwrite(3) is declared warn_unused_result */
> +        unused = fwrite(trace_buf, trace_idx * sizeof(trace_buf[0]), 1, trace_fp);

I think this would be better denoted as :
unused = fwrite(trace_buf, trace_idx * sizeof(TraceRecord), 1, trace_fp);

> +    }
> +}
> +
>   static void trace(TraceEventID event, unsigned long x1,
>                     unsigned long x2, unsigned long x3,
>                     unsigned long x4, unsigned long x5)
> @@ -44,15 +58,8 @@ static void trace(TraceEventID event, unsigned long x1,
>       rec->x5 = x5;
>
>       if (++trace_idx == TRACE_BUF_LEN) {
> +        flush_trace_buffer();
>           trace_idx = 0;
> -
> -        if (!trace_fp) {
> -            trace_fp = fopen("/tmp/trace.log", "w");
> -        }
> -        if (trace_fp) {
> -            size_t result = fwrite(trace_buf, sizeof trace_buf, 1, trace_fp);
> -            result = result;
> -        }
>       }
>   }
>

I was wondering if we can extend this. One can have a monitor command 
such as "dump-trace" which would write a partly-filled buffer to file 
using a call to flush_trace_buffer().
But this has a few caveats. flush_trace_buffer() must reset trace_idx to 
0 to prevent duplicate traces to be written once the buffer is filled up.
Also, I'm wondering what happens in case qemu is started with -smp 2 or 
more. We might need to enforce some kind of synchronisation so that 
threads on other cpus do not log traces while the buffer is being 
sync'ed. ( For now, I have not been able to get upstream qemu run with 
-smp. Going forward, this is something that might need to be looked into.)

Regards,

-- 
Prerna Saxena

Linux Technology Centre,
IBM Systems and Technology Lab,
Bangalore, India

Re: [Qemu-devel] [PATCH 3/3] trace: Flush trace buffer on exit

[Stefan Hajnoczi]

On Thu, Jul 08, 2010 at 12:12:10PM +0530, Prerna Saxena wrote:
> Hi Stefan,
> On 07/07/2010 01:44 AM, Stefan Hajnoczi wrote:
> >Signed-off-by: Stefan Hajnoczi<stefanha@linux.vnet.ibm.com>
> >---
> >This applies to the tracing branch at:
> >
> >   http://repo.or.cz/w/qemu/stefanha.git/shortlog/refs/heads/tracing-dev
> >
> >  simpletrace.c |   23 +++++++++++++++--------
> >  1 files changed, 15 insertions(+), 8 deletions(-)
> >
> >diff --git a/simpletrace.c b/simpletrace.c
> >index ace009f..9604ea6 100644
> >--- a/simpletrace.c
> >+++ b/simpletrace.c
> >@@ -22,6 +22,20 @@ static TraceRecord trace_buf[TRACE_BUF_LEN];
> >  static unsigned int trace_idx;
> >  static FILE *trace_fp;
> >
> >+static void flush_trace_buffer(void)
> >+{
> >+    if (!trace_fp) {
> >+        trace_fp = fopen("/tmp/trace.log", "w");
> >+        if (trace_fp) {
> >+            atexit(flush_trace_buffer);
> >+        }
> >+    }
> >+    if (trace_fp) {
> >+        size_t unused; /* for when fwrite(3) is declared warn_unused_result */
> >+        unused = fwrite(trace_buf, trace_idx * sizeof(trace_buf[0]), 1, trace_fp);
> 
> I think this would be better denoted as :
> unused = fwrite(trace_buf, trace_idx * sizeof(TraceRecord), 1, trace_fp);

The sizeof(trace_buf[0]) idiom prevents bugs creeping in when the type
of trace_buf[] is changed.  It is easy to forget to update all relevant
uses of sizeof(TraceRecord) across the codebase and end up with
incorrect memset/memcpy() or read/write().  It also means that a patch
changing the type of trace_buf[] doesn't need to touch as many places.

Why repeat the trace_buf[]'s throughout the codebase?

> >+    }
> >+}
> >+
> >  static void trace(TraceEventID event, unsigned long x1,
> >                    unsigned long x2, unsigned long x3,
> >                    unsigned long x4, unsigned long x5)
> >@@ -44,15 +58,8 @@ static void trace(TraceEventID event, unsigned long x1,
> >      rec->x5 = x5;
> >
> >      if (++trace_idx == TRACE_BUF_LEN) {
> >+        flush_trace_buffer();
> >          trace_idx = 0;
> >-
> >-        if (!trace_fp) {
> >-            trace_fp = fopen("/tmp/trace.log", "w");
> >-        }
> >-        if (trace_fp) {
> >-            size_t result = fwrite(trace_buf, sizeof trace_buf, 1, trace_fp);
> >-            result = result;
> >-        }
> >      }
> >  }
> >
> 
> I was wondering if we can extend this. One can have a monitor
> command such as "dump-trace" which would write a partly-filled
> buffer to file using a call to flush_trace_buffer().

Definitely!  I'd like that to be part of the trace file management
command patch.  This patch just adds the functionality to flush the
trace buffer.

> But this has a few caveats. flush_trace_buffer() must reset
> trace_idx to 0 to prevent duplicate traces to be written once the
> buffer is filled up.
> Also, I'm wondering what happens in case qemu is started with -smp 2
> or more. We might need to enforce some kind of synchronisation so
> that threads on other cpus do not log traces while the buffer is
> being sync'ed. ( For now, I have not been able to get upstream qemu
> run with -smp. Going forward, this is something that might need to
> be looked into.)

The simple trace backend performs no synchronization - it is only safe
under the global QEMU iothread mutex.  This actually covers the majority
of the code when using KVM, but we need to be explicit about this
limitation and explore it under non-KVM scenarios.

> 
> Regards,
> 
> -- 
> Prerna Saxena
> 
> Linux Technology Centre,
> IBM Systems and Technology Lab,
> Bangalore, India

Re: [Qemu-devel] [PATCH 3/3] trace: Flush trace buffer on exit

[Stefan Hajnoczi]

On Thu, Jul 8, 2010 at 9:28 AM, Stefan Hajnoczi
<stefanha@linux.vnet.ibm.com> wrote:
> On Thu, Jul 08, 2010 at 12:12:10PM +0530, Prerna Saxena wrote:
>> Hi Stefan,
>> On 07/07/2010 01:44 AM, Stefan Hajnoczi wrote:
>> >Signed-off-by: Stefan Hajnoczi<stefanha@linux.vnet.ibm.com>
>> >---
>> >This applies to the tracing branch at:
>> >
>> >   http://repo.or.cz/w/qemu/stefanha.git/shortlog/refs/heads/tracing-dev
>> >
>> >  simpletrace.c |   23 +++++++++++++++--------
>> >  1 files changed, 15 insertions(+), 8 deletions(-)
>> >
>> >diff --git a/simpletrace.c b/simpletrace.c
>> >index ace009f..9604ea6 100644
>> >--- a/simpletrace.c
>> >+++ b/simpletrace.c
>> >@@ -22,6 +22,20 @@ static TraceRecord trace_buf[TRACE_BUF_LEN];
>> >  static unsigned int trace_idx;
>> >  static FILE *trace_fp;
>> >
>> >+static void flush_trace_buffer(void)
>> >+{
>> >+    if (!trace_fp) {
>> >+        trace_fp = fopen("/tmp/trace.log", "w");
>> >+        if (trace_fp) {
>> >+            atexit(flush_trace_buffer);
>> >+        }
>> >+    }
>> >+    if (trace_fp) {
>> >+        size_t unused; /* for when fwrite(3) is declared warn_unused_result */
>> >+        unused = fwrite(trace_buf, trace_idx * sizeof(trace_buf[0]), 1, trace_fp);
>>
>> I think this would be better denoted as :
>> unused = fwrite(trace_buf, trace_idx * sizeof(TraceRecord), 1, trace_fp);
>
> The sizeof(trace_buf[0]) idiom prevents bugs creeping in when the type
> of trace_buf[] is changed.  It is easy to forget to update all relevant
> uses of sizeof(TraceRecord) across the codebase and end up with
> incorrect memset/memcpy() or read/write().  It also means that a patch
> changing the type of trace_buf[] doesn't need to touch as many places.
>
> Why repeat the trace_buf[]'s throughout the codebase?

Should read: Why repeat trace_buf[]'s type throughout the codebase? :)

>
>> >+    }
>> >+}
>> >+
>> >  static void trace(TraceEventID event, unsigned long x1,
>> >                    unsigned long x2, unsigned long x3,
>> >                    unsigned long x4, unsigned long x5)
>> >@@ -44,15 +58,8 @@ static void trace(TraceEventID event, unsigned long x1,
>> >      rec->x5 = x5;
>> >
>> >      if (++trace_idx == TRACE_BUF_LEN) {
>> >+        flush_trace_buffer();
>> >          trace_idx = 0;
>> >-
>> >-        if (!trace_fp) {
>> >-            trace_fp = fopen("/tmp/trace.log", "w");
>> >-        }
>> >-        if (trace_fp) {
>> >-            size_t result = fwrite(trace_buf, sizeof trace_buf, 1, trace_fp);
>> >-            result = result;
>> >-        }
>> >      }
>> >  }
>> >
>>
>> I was wondering if we can extend this. One can have a monitor
>> command such as "dump-trace" which would write a partly-filled
>> buffer to file using a call to flush_trace_buffer().
>
> Definitely!  I'd like that to be part of the trace file management
> command patch.  This patch just adds the functionality to flush the
> trace buffer.
>
>> But this has a few caveats. flush_trace_buffer() must reset
>> trace_idx to 0 to prevent duplicate traces to be written once the
>> buffer is filled up.
>> Also, I'm wondering what happens in case qemu is started with -smp 2
>> or more. We might need to enforce some kind of synchronisation so
>> that threads on other cpus do not log traces while the buffer is
>> being sync'ed. ( For now, I have not been able to get upstream qemu
>> run with -smp. Going forward, this is something that might need to
>> be looked into.)
>
> The simple trace backend performs no synchronization - it is only safe
> under the global QEMU iothread mutex.  This actually covers the majority
> of the code when using KVM, but we need to be explicit about this
> limitation and explore it under non-KVM scenarios.
>
>>
>> Regards,
>>
>> --
>> Prerna Saxena
>>
>> Linux Technology Centre,
>> IBM Systems and Technology Lab,
>> Bangalore, India
>
>