Re: [Qemu-devel] [PATCH v7 0/3] Simpletrace v2: Support multiple args, strings.

[Stefan Hajnoczi <stefanha@gmail.com>]

On Tue, Jul 17, 2012 at 3:07 PM, Stefan Hajnoczi <stefanha@gmail.com> wrote:
> On Tue, Jul 3, 2012 at 10:20 AM, Harsh Prateek Bora
> <harsh@linux.vnet.ibm.com> wrote:
>> Existing simpletrace backend allows to trace at max 6 args and does not
>> support strings. This newer tracelog format gets rid of fixed size records
>> and therefore allows to trace variable number of args including strings.
>>
>> Sample trace:
>> v9fs_version 0.000 tag=0xffff id=0x64 msize=0x2000 version=9P2000.L
>> v9fs_version_return 6.705 tag=0xffff id=0x64 msize=0x2000 version=9P2000.L
>> v9fs_attach 174.467 tag=0x1 id=0x68 fid=0x0 afid=0xffffffffffffffff
>> uname=nobody aname=
>> v9fs_attach_return 4720.454 tag=0x1 id=0x68 type=0xffffffffffffff80
>> version=0x4f2a4dd0  path=0x220ea6
>
> The writeout thread deadlocked itself when it called g_malloc() and
> therefore became a tracing thread:
>
> Thread 3 (Thread 0x7fad8b144700 (LWP 1387)):
> #0  0x00007ffffa1e88de in ?? ()
> #1  0x00007fad9421de86 in *__GI_clock_gettime
> (clock_id=clock_id@entry=1, tp=tp@entry=0x7fad8b143be0) at
> ../sysdeps/unix/clock_gettime.c:116
> #2  0x00007fad94813e46 in get_clock () at ./qemu-timer.h:124
> #3  trace_record_start (rec=rec@entry=0x7fad8b143c10,
> event=140383339428832, event@entry=0, datasize=datasize@entry=16) at
> trace/simple.c:219
> #4  0x00007fad947f7185 in trace_g_malloc (size=size@entry=32,
> ptr=ptr@entry=0x7fad340008b0) at trace.c:770
> #5  0x00007fad947b5754 in malloc_and_trace (n_bytes=32) at
> /home/stefanha/qemu/vl.c:2240
> #6  0x00007fad93d70de1 in g_malloc (n_bytes=n_bytes@entry=32) at
> /tmp/buildd/glib2.0-2.32.3/./glib/gmem.c:159
> #7  0x00007fad94813bce in get_trace_record (recordptr=<synthetic
> pointer>, idx=56943) at trace/simple.c:114
> #8  writeout_thread (opaque=<optimized out>) at trace/simple.c:189
> #9  0x00007fad93d8ddf5 in g_thread_proxy (data=0x7fad96738800) at
> /tmp/buildd/glib2.0-2.32.3/./glib/gthread.c:801
> #10 0x00007fad90ed7b50 in start_thread (arg=<optimized out>) at
> pthread_create.c:304
> #11 0x00007fad90c226dd in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
> #12 0x0000000000000000 in ?? ()

Here's a fix, in order to avoid reentrancy use raw malloc(3) and free(3):

diff --git a/trace/simple.c b/trace/simple.c
index 3c14568..5a4d607 100644
--- a/trace/simple.c
+++ b/trace/simple.c
@@ -111,7 +111,7 @@ static bool get_trace_record(unsigned int idx,
TraceRecord **recordptr)
     __sync_synchronize(); /* read memory barrier before accessing record */
     /* read the record header to know record length */
     read_from_buffer(idx, rec_hdr, sizeof(TraceRecord));
-    *recordptr = g_malloc(record->length);
+    *recordptr = malloc(record->length);
     /* make a copy of record to avoid being overwritten */
     read_from_buffer(idx, (uint8_t *)*recordptr, record->length);
     smp_rmb(); /* memory barrier before clearing valid flag */
@@ -189,7 +189,7 @@ static gpointer writeout_thread(gpointer opaque)
         while (get_trace_record(idx, &recordptr)) {
             unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
             writeout_idx += recordptr->length;
-            g_free(recordptr);
+            free(recordptr);
             idx = writeout_idx % TRACE_BUF_LEN;
         }