Re: [Qemu-devel] [PATCH v2 2/3] Simpletrace v2: Add support for multiple args, strings.

[Harsh Bora <harsh@linux.vnet.ibm.com>]

On 06/07/2012 08:02 PM, Stefan Hajnoczi wrote:
> On Thu, May 24, 2012 at 10:50 AM, Harsh Prateek Bora
> <harsh@linux.vnet.ibm.com>  wrote:
>> A newer tracelog format which gets rid of fixed size trace records and
>> therefore allows to trace multiple arguments as well as strings in trace
>> events.
>>
>> 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
>>
>> Signed-off-by: Harsh Prateek Bora<harsh@linux.vnet.ibm.com>
>> ---
>>   scripts/tracetool/backend/simple.py |   84 ++++++++++---
>>   trace/simple.c                      |  229 ++++++++++++++++++++++-------------
>>   trace/simple.h                      |   38 +++++-
>>   3 files changed, 240 insertions(+), 111 deletions(-)
>
> Sorry for the delay.  Mostly easy to fix comments, some care still
> needed to avoid race conditions and use memory barriers in the right
> places.
>

Hi Stefan,
Thanks for reviewing, I have some questions below:

>> @@ -75,16 +96,22 @@ static char *trace_file_name = NULL;
>>   *
>>   * Returns false if the record is not valid.
>>   */
>> -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 temp_rec[ST_REC_HDR_LEN];
>> +    TraceRecord *record = (TraceRecord *) temp_rec;
>> +    read_from_buffer(idx, temp_rec, ST_REC_HDR_LEN);
>> +
>> +    if (!(record->event&  TRACE_RECORD_VALID)) {
>>          return false;
>>      }
>>
>>      __sync_synchronize(); /* read memory barrier before accessing record */
>
> The need for the memory barrier is no longer clear.  Previously we
> were directly accessing the trace ring buffer, and therefore needed to
> ensure fields were settled before accessing them.  Now we use
> read_from_buffer() which copies the data into our temporary struct on
> the stack.
>
> I think the best way of doing it is to read the event field first in a
> separate step, then do the read memory barrier, and then read the rest
> of the record.  This ensures that the event field is at least as "old"
> as the other fields we read.

Currently, it does a two step read:

read header (which includes event field and length of record as well)
sync
read rest of record (using length from header)

Are you suggesting this:

read event field only
sync (if event valid)
read header (for length)
sync
read rest of record (using length)

or

read event field only
sync (if event valid)
read header (for length)
read rest of record

As we cant read the whole record in one step without knowing its length.



>
>>
>> -    *record = trace_buf[idx];
>> -    record->event&= ~TRACE_RECORD_VALID;
>> +    *recordptr = g_malloc(record->length);
>> +    /* make a copy of record to avoid being overwritten */
>> +    read_from_buffer(idx, (uint8_t *)*recordptr, record->length);
>> +    (*recordptr)->event&= ~TRACE_RECORD_VALID;
>>      return true;
>>   }
>>

[....]

>>
>> -void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3)
>> +int trace_alloc_record(TraceBufferRecord *rec, TraceEventID event, uint32_t datasize)
>>   {
>> -    trace(event, x1, x2, x3, 0, 0, 0);
>> +    unsigned int idx, rec_off;
>> +    uint32_t rec_len = ST_REC_HDR_LEN + datasize;
>> +    uint64_t timestamp_ns = get_clock();
>> +
>> +    if ((rec_len + trace_idx - writeout_idx)>  TRACE_BUF_LEN) {
>> +        /* Trace Buffer Full, Event dropped ! */
>> +        dropped_events++;
>> +        return 1;
>
> -ENOSPC?  A negative errno is clearer than 0 - success, 1 - failure.
>
>> +    }
>> +    idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, rec_len) % TRACE_BUF_LEN;
>
> How does this deal with the race condition of two or more threads
> running trace_alloc_record() concurrently when the buffer reaches max
> size?  I think two or more threads could think they have enough space
> because trace_idx hasn't been updated yet between the buffer length
> check and the atomic update.

Are you suggesting to use locking here ? I couldnt find a test-and-set 
alternative in glib2. Does qemu have access to any such interface ?

>
>> +
>> +    /*  To check later if threshold crossed */
>> +    rec->next_tbuf_idx = trace_idx % TRACE_BUF_LEN;
>> +
>> +    rec_off = idx;
>> +    write_to_buffer(rec_off, (uint8_t*)&event, sizeof(event));
>> +    rec_off += sizeof(event);
>> +    write_to_buffer(rec_off, (uint8_t*)&timestamp_ns, sizeof(timestamp_ns));
>> +    rec_off += sizeof(timestamp_ns);
>> +    write_to_buffer(rec_off, (uint8_t*)&rec_len, sizeof(rec_len));
>> +    rec_off += sizeof(rec_len);
>
> This suggests a pattern where write_to_buffer() returns the new index:
>
> rec_off = write_to_buffer(rec_off, (uint8_t*)&event, sizeof(event));
>
> That way you don't need to do the separate sizeof() additions.
>
>> +
>> +    rec->tbuf_idx = idx;
>> +    rec->rec_off  = (idx + ST_REC_HDR_LEN) % 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, uint8_t *dataptr, uint32_t size)
>
> size_t is the type to use for memory size units.
>

[...]

>> +void trace_record_finish(TraceBufferRecord *rec);
>> +uint32_t safe_strlen(const char* str);
>
> Given that safe_strlen() is only used once and a generic utility (not
> specific to the simple trace backend), I suggest dropping it an just
> open coding the tristate operator: s ? strlen(s) : 0.
>

safe_strlen is used multiple times in auto-generated code by tracetool 
in expression for calculating the sum of size of trace arguments which 
as of now looks like:

8 + 8 + 4 + safe_strlen(str1) + 8 + 4 + safe_strlen(str2) ...

for tracing events with string arguments. For trace events with multiple 
strings, this expression is more readable as compared to having an 
expression with tristate operator like this:

8 + 8 + 4 + (str1 ? strlen(str1) : 0) + 8  + 4 + (str2 ? strlen(str2) : 
0) ...


I agree that its a generic function and need not be placed in tracing 
code, let me know the right place where to put it if you think its worth 
keeping it.

regards,
Harsh


> Stefan
>