Patchwork [3/3] trace: Flush trace buffer on exit

login
register
mail settings
Submitter Stefan Hajnoczi
Date July 6, 2010, 8:14 p.m.
Message ID <1278447241-2709-3-git-send-email-stefanha@linux.vnet.ibm.com>
Download mbox | patch
Permalink /patch/58060/
State New
Headers show

Comments

Stefan Hajnoczi - July 6, 2010, 8:14 p.m.
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(-)
Prerna Saxena - July 8, 2010, 6:42 a.m.
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,
Stefan Hajnoczi - July 8, 2010, 8:28 a.m.
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
Stefan Hajnoczi - July 8, 2010, 8:34 a.m.
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
>
>

Patch

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;
-        }
     }
 }