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 */
