From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from eggs.gnu.org ([208.118.235.92]:42803) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1SfASv-0000sZ-6d for qemu-devel@nongnu.org; Thu, 14 Jun 2012 09:52:07 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1SfASm-0001QX-4r for qemu-devel@nongnu.org; Thu, 14 Jun 2012 09:52:00 -0400 Received: from e28smtp07.in.ibm.com ([122.248.162.7]:37395) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1SfASl-0001Oq-6f for qemu-devel@nongnu.org; Thu, 14 Jun 2012 09:51:52 -0400 Received: from /spool/local by e28smtp07.in.ibm.com with IBM ESMTP SMTP Gateway: Authorized Use Only! Violators will be prosecuted for from ; Thu, 14 Jun 2012 19:21:42 +0530 Received: from d28av04.in.ibm.com (d28av04.in.ibm.com [9.184.220.66]) by d28relay02.in.ibm.com (8.13.8/8.13.8/NCO v10.0) with ESMTP id q5EDpeAC2556282 for ; Thu, 14 Jun 2012 19:21:40 +0530 Received: from d28av04.in.ibm.com (loopback [127.0.0.1]) by d28av04.in.ibm.com (8.14.4/8.13.1/NCO v10.0 AVout) with ESMTP id q5EJLRnM025570 for ; Fri, 15 Jun 2012 05:21:27 +1000 Message-ID: <4FD9EC67.5080301@linux.vnet.ibm.com> Date: Thu, 14 Jun 2012 19:21:35 +0530 From: Harsh Bora MIME-Version: 1.0 References: <1339680775-23610-1-git-send-email-harsh@linux.vnet.ibm.com> <1339680775-23610-3-git-send-email-harsh@linux.vnet.ibm.com> In-Reply-To: <1339680775-23610-3-git-send-email-harsh@linux.vnet.ibm.com> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Subject: Re: [Qemu-devel] [PATCH v5 2/3] Simpletrace v2: Support multiple arguments, strings. List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Harsh Prateek Bora Cc: stefanha@gmail.com, qemu-devel@nongnu.org, stefanha@linux.vnet.ibm.com Hi Stefan, Please see comment below: On 06/14/2012 07:02 PM, Harsh Prateek Bora wrote: [...] > -static bool get_trace_record(unsigned int idx, TraceRecord *record) > +static bool get_trace_record(unsigned int idx, TraceRecord **recordptr) > { > - if (!(trace_buf[idx].event& TRACE_RECORD_VALID)) { > + uint8_t rec_hdr[sizeof(TraceRecord)]; > + uint64_t event_flag = 0; > + TraceRecord *record = (TraceRecord *) rec_hdr; > + /* read the event flag to see if its a valid record */ > + read_from_buffer(idx, rec_hdr, sizeof(event_flag)); > + > + if (!(record->event& TRACE_RECORD_VALID)) { > return false; > } > > __sync_synchronize(); /* read memory barrier before accessing record */ > - > - *record = trace_buf[idx]; > - record->event&= ~TRACE_RECORD_VALID; > - return true; > + /* read the record header to know record length */ > + read_from_buffer(idx, rec_hdr, sizeof(TraceRecord)); > + *recordptr = g_malloc(record->length); > + /* make a copy of record to avoid being overwritten */ > + read_from_buffer(idx, (uint8_t *)*recordptr, record->length); > + __sync_synchronize(); /* memory barrier before clearing valid flag */ > + (*recordptr)->event&= ~TRACE_RECORD_VALID; > + /* reset record event validity flag on global trace buffer */ > + write_to_buffer(idx,&event_flag, sizeof(event_flag)); > + if ((*recordptr)->event< NR_TRACE_EVENTS) { > + return true; > + } else { > + /* XXX: Ideally this should not happen, but its possible ! > + * See comments in trace_record_start for more details. > + * We dont know where to start next and therefore resetting > + * writeout_idx to trace_idx. Also, as we dont know how many > + * events dropped in between, at least increment the count by one. > + */ > + g_atomic_int_inc((gint *)&dropped_events); > + g_free(*recordptr); > + writeout_idx = trace_idx; > + return false; > + } > } > [...] > -void trace1(TraceEventID event, uint64_t x1) > +int trace_record_start(TraceBufferRecord *rec, TraceEventID event, size_t datasize) > { > - trace(event, x1, 0, 0, 0, 0, 0); > -} > + unsigned int idx, rec_off, old_idx, new_idx; > + uint32_t rec_len = sizeof(TraceRecord) + datasize; > + uint64_t timestamp_ns = get_clock(); > + > + while (1) { > + old_idx = trace_idx; > + smp_rmb(); > + new_idx = old_idx + rec_len; > + > + if (new_idx - writeout_idx> TRACE_BUF_LEN) { > + /* Trace Buffer Full, Event dropped ! */ > + g_atomic_int_inc((gint *)&dropped_events); > + return -ENOSPC; > + } > > -void trace2(TraceEventID event, uint64_t x1, uint64_t x2) > -{ > - trace(event, x1, x2, 0, 0, 0, 0); > -} > + /* XXX: If threads race here, take care in get_trace_record */ I see that this comment is invalid, but there is something corrupting the trace buffer. If I remove the check for event_id < NR_TRACE_EVENTS in get_trace_record, it is finding corrupted records after about 10K records being traced, strangely with valid flag set set. I do not see any obvious reason for this, do you ? regards, Harsh > > -void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3) > -{ > - trace(event, x1, x2, x3, 0, 0, 0); > + if (g_atomic_int_compare_and_exchange((gint *)&trace_idx, > + old_idx, new_idx)) { > + break; > + } > + } > + > + idx = old_idx % TRACE_BUF_LEN; > + /* To check later if threshold crossed */ > + rec->next_tbuf_idx = new_idx % TRACE_BUF_LEN; > + > + rec_off = idx; > + rec_off = write_to_buffer(rec_off, (uint8_t*)&event, sizeof(event)); > + rec_off = write_to_buffer(rec_off, (uint8_t*)×tamp_ns, sizeof(timestamp_ns)); > + rec_off = write_to_buffer(rec_off, (uint8_t*)&rec_len, sizeof(rec_len)); > + > + rec->tbuf_idx = idx; > + rec->rec_off = (idx + sizeof(TraceRecord)) % TRACE_BUF_LEN; > + return 0; > } > > -void trace4(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4) > +static void read_from_buffer(unsigned int idx, void *dataptr, size_t size) > { > - trace(event, x1, x2, x3, x4, 0, 0); > + uint8_t *data_ptr = dataptr; > + uint32_t x = 0; > + while (x< size) { > + if (idx>= TRACE_BUF_LEN) { > + idx = idx % TRACE_BUF_LEN; > + } > + data_ptr[x++] = trace_buf[idx++]; > + } > } > > -void trace5(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5) > +static unsigned int write_to_buffer(unsigned int idx, void *dataptr, size_t size) > { > - trace(event, x1, x2, x3, x4, x5, 0); > + uint8_t *data_ptr = dataptr; > + uint32_t x = 0; > + while (x< size) { > + if (idx>= TRACE_BUF_LEN) { > + idx = idx % TRACE_BUF_LEN; > + } > + trace_buf[idx++] = data_ptr[x++]; > + } > + return idx; /* most callers wants to know where to write next */ > } > > -void trace6(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6) > +void trace_record_finish(TraceBufferRecord *rec) > { > - trace(event, x1, x2, x3, x4, x5, x6); > + uint8_t temp_rec[sizeof(TraceRecord)]; > + TraceRecord *record = (TraceRecord *) temp_rec; > + read_from_buffer(rec->tbuf_idx, temp_rec, sizeof(TraceRecord)); > + __sync_synchronize(); /* write barrier before marking as valid */ > + record->event |= TRACE_RECORD_VALID; > + write_to_buffer(rec->tbuf_idx, temp_rec, sizeof(TraceRecord)); > + > + if ((trace_idx> writeout_idx)&& > + (trace_idx - writeout_idx)> TRACE_BUF_FLUSH_THRESHOLD) { > + flush_trace_file(false); > + } else if ((writeout_idx> trace_idx)&& > + (trace_idx> TRACE_BUF_FLUSH_THRESHOLD)) { > + /* if trace_idx rollover before writeout_idx */ > + flush_trace_file(false); > + } > } > > void st_set_trace_file_enabled(bool enable) > @@ -231,10 +304,11 @@ void st_set_trace_file_enabled(bool enable) > flush_trace_file(true); > > if (enable) { > - static const TraceRecord header = { > - .event = HEADER_EVENT_ID, > - .timestamp_ns = HEADER_MAGIC, > - .x1 = HEADER_VERSION, > + static const TraceRecordHeader header = { > + .header_event_id = HEADER_EVENT_ID, > + .header_magic = HEADER_MAGIC, > + /* Older log readers will check for version at next location */ > + .header_version = HEADER_VERSION, > }; > > trace_fp = fopen(trace_file_name, "wb"); > diff --git a/trace/simple.h b/trace/simple.h > index 6b5358c..6755e99 100644 > --- a/trace/simple.h > +++ b/trace/simple.h > @@ -22,16 +22,39 @@ typedef struct { > bool state; > } TraceEvent; > > -void trace0(TraceEventID event); > -void trace1(TraceEventID event, uint64_t x1); > -void trace2(TraceEventID event, uint64_t x1, uint64_t x2); > -void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3); > -void trace4(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4); > -void trace5(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5); > -void trace6(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6); > void st_print_trace_file_status(FILE *stream, fprintf_function stream_printf); > void st_set_trace_file_enabled(bool enable); > bool st_set_trace_file(const char *file); > void st_flush_trace_buffer(void); > > +typedef struct { > + unsigned int tbuf_idx; > + unsigned int next_tbuf_idx; > + unsigned int rec_off; > +} TraceBufferRecord; > + > +/** > + * Initialize a trace record and claim space for it in the buffer > + * > + * @arglen number of bytes required for arguments > + */ > +int trace_record_start(TraceBufferRecord *rec, TraceEventID id, size_t arglen); > + > +/** > + * Append a 64-bit argument to a trace record > + */ > +void trace_record_write_u64(TraceBufferRecord *rec, uint64_t val); > + > +/** > + * Append a string argument to a trace record > + */ > +void trace_record_write_str(TraceBufferRecord *rec, const char *s); > + > +/** > + * Mark a trace record completed > + * > + * Don't append any more arguments to the trace record after calling this. > + */ > +void trace_record_finish(TraceBufferRecord *rec); > + > #endif /* TRACE_SIMPLE_H */