On Tue, Jul 17, 2012 at 3:07 PM, Stefan Hajnoczi <stefa...@gmail.com> wrote: > On Tue, Jul 3, 2012 at 10:20 AM, Harsh Prateek Bora > <ha...@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; }