Re: [Qemu-devel] [PATCH v5 2/3] Simpletrace v2: Support multiple arguments, strings.

[Harsh Bora <harsh@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*)&timestamp_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 */