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

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

On 07/17/2012 08:51 PM, Stefan Hajnoczi wrote:
> On Tue, Jul 3, 2012 at 10:20 AM, Harsh Prateek Bora
> <harsh@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 with strings:
>> 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
>>
>> Signed-off-by: Harsh Prateek Bora <harsh@linux.vnet.ibm.com>
>> ---
>>   scripts/tracetool/backend/simple.py |   84 +++++++++---
>>   trace/simple.c                      |  256 ++++++++++++++++++++++-------------
>>   trace/simple.h                      |   39 +++++-
>>   3 files changed, 260 insertions(+), 119 deletions(-)
>>
>> diff --git a/scripts/tracetool/backend/simple.py b/scripts/tracetool/backend/simple.py
>> index fbb5717..d3cf4da 100644
>> --- a/scripts/tracetool/backend/simple.py
>> +++ b/scripts/tracetool/backend/simple.py
>> @@ -15,9 +15,16 @@ __email__      = "stefanha@linux.vnet.ibm.com"
>>
>>   from tracetool import out
>>
>> +def is_string(arg):
>> +    strtype = ('const char*', 'char*', 'const char *', 'char *')
>> +    if arg.lstrip().startswith(strtype):
>> +        return True
>> +    else:
>> +        return False
>>
>>   def c(events):
>>       out('#include "trace.h"',
>> +        '#include "trace/simple.h"',
>>           '',
>>           'TraceEvent trace_list[] = {')
>>
>> @@ -26,30 +33,69 @@ def c(events):
>>               name = e.name,
>>               )
>>
>> -    out('};')
>> -
>> -def h(events):
>> -    out('#include "trace/simple.h"',
>> +    out('};',
>>           '')
>>
>> -    for num, e in enumerate(events):
>> -        if len(e.args):
>> -            argstr = e.args.names()
>> -            arg_prefix = ', (uint64_t)(uintptr_t)'
>> -            cast_args = arg_prefix + arg_prefix.join(argstr)
>> -            simple_args = (str(num) + cast_args)
>> -        else:
>> -            simple_args = str(num)
>> +    for num, event in enumerate(events):
>> +        sizes = []
>> +        for type_, name in event.args:
>> +            if is_string(type_):
>> +                sizes.append("4 + ((" + name + " ? strlen(" + name + ") : 0) % MAX_TRACE_STRLEN)")
>
> trace_record_write_str() and this code both use % to truncate the
> string.  If the string is 512 characters long you get an empty string.
>   That's weird and not normally how truncation works.
>
> Perhaps it's better to change this Python code to emit something like:
> size_t arg%(num)d_len = %(name)s ? MAX(strlen(%(name)s, MAX_TRACE_STRLEN)) : 0;
>

I think we need to use MIN instead of MAX, right ?

Another question below ..

> Then you can emit the following to actual store the string:
>
> out('    trace_record_write_str(&rec, %(name)s, arg%(num)d_len);',
> name=name, num=num)
>
> The difference is that MAX() is used to truncate and we only do strlen() once.
>
>> +            else:
>> +                sizes.append("8")
>> +        sizestr = " + ".join(sizes)
>> +        if len(event.args) == 0:
>> +            sizestr = '0'
>>
>> -        out('static inline void trace_%(name)s(%(args)s)',
>> +        out('void trace_%(name)s(%(args)s)',
>>               '{',
>> -            '    trace%(argc)d(%(trace_args)s);',
>> -            '}',
>> -            name = e.name,
>> -            args = e.args,
>> -            argc = len(e.args),
>> -            trace_args = simple_args,
>> +            '    TraceBufferRecord rec;',
>> +            '',
>> +            '    if (!trace_list[%(event_id)s].state) {',
>> +            '        return;',
>> +            '    }',
>> +            '',
>> +            '    if (trace_record_start(&rec, %(event_id)s, %(size_str)s)) {',
>> +            '        return; /* Trace Buffer Full, Event Dropped ! */',
>> +            '    }',
>> +            name = event.name,
>> +            args = event.args,
>> +            event_id = num,
>> +            size_str = sizestr,
>>               )
>>
>> +        if len(event.args) > 0:
>> +            for type_, name in event.args:
>> +                # string
>> +                if is_string(type_):
>> +                    out('    trace_record_write_str(&rec, %(name)s);',
>> +                        name = name,
>> +                       )
>> +                # pointer var (not string)
>> +                elif type_.endswith('*'):
>> +                    out('    trace_record_write_u64(&rec, (uint64_t)(uint64_t *)%(name)s);',
>> +                        name = name,
>> +                       )
>> +                # primitive data type
>> +                else:
>> +                    out('    trace_record_write_u64(&rec, (uint64_t)%(name)s);',
>> +                       name = name,
>> +                       )
>> +
>> +        out('    trace_record_finish(&rec);',
>> +            '}',
>> +            '')
>> +
>> +
>> +def h(events):
>> +    out('#include "trace/simple.h"',
>> +        '')
>> +
>> +    for event in events:
>> +        out('void trace_%(name)s(%(args)s);',
>> +            name = event.name,
>> +            args = event.args,
>> +            )
>> +    out('')
>>       out('#define NR_TRACE_EVENTS %d' % len(events))
>>       out('extern TraceEvent trace_list[NR_TRACE_EVENTS];')
>> diff --git a/trace/simple.c b/trace/simple.c
>> index b64bcf4..3c14568 100644
>> --- a/trace/simple.c
>> +++ b/trace/simple.c
>> @@ -27,7 +27,7 @@
>>   #define HEADER_MAGIC 0xf2b177cb0aa429b4ULL

[..snip..]

>>   /**
>>    * Read a trace record from the trace buffer
>>    *
>> @@ -75,16 +96,31 @@ 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 rec_hdr[sizeof(TraceRecord)];
>> +    uint64_t event_flag = 0;
>> +    TraceRecord *record = (TraceRecord *) rec_hdr;
>
> Declaring rec_hdr as a uint8_t array is only because you're trying to
> avoid a cast later?  The easiest way to make this nice is to do what
> memset(), memcpy() and friends do: just use a void *buf argument.
> That way a caller can pass a TraceRecord* or any other pointer without
> explicit casts, unions, or the uint8_t array trick you are using.

Are you suggesting to use malloc() here?

void *rec_hdr = malloc(sizeof(TraceRecord));

I kept a static array to make sure structure padding doesnt take place.
I am not sure if using malloc here is recommended as we are reading 
header and then writing this header byte-by-byte?

~ Harsh

>
>> +    /* 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;
>> +    /* 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);
>> +    smp_rmb(); /* memory barrier before clearing valid flag */
>
> You are adding smp_*() instead of __sync_synchronize().  Please either
> continue to use __sync_synchronize() or convert everything to smp_*()
> barriers from qemu-barrier.h.
>
>> +    (*recordptr)->event &= ~TRACE_RECORD_VALID;
>> +    /* clear the trace buffer range for consumed record otherwise any byte
>> +     * with its MSB set may be considered as a valid event id when the writer
>> +     * thread crosses this range of buffer again.
>> +     */
>> +    clear_buffer_range(idx, record->length);
>>       return true;
>>   }
>>
>> @@ -120,29 +156,41 @@ static void wait_for_trace_records_available(void)
>>
>>   static gpointer writeout_thread(gpointer opaque)
>>   {
>> -    TraceRecord record;
>> -    unsigned int writeout_idx = 0;
>> -    unsigned int num_available, idx;
>> +    TraceRecord *recordptr, *dropped_ptr;
>> +    union {
>> +        TraceRecord rec;
>> +        uint8_t bytes[sizeof(TraceRecord) + sizeof(uint64_t)];
>> +    } dropped;
>> +    dropped_ptr = (TraceRecord *)dropped.bytes;
>
> dropped_ptr isn't needed, just use dropped.rec.
>
>> +    unsigned int idx = 0;
>> +    uint64_t dropped_count;
>>       size_t unused __attribute__ ((unused));
>>
>>       for (;;) {
>>           wait_for_trace_records_available();
>>
>> -        num_available = trace_idx - writeout_idx;
>> -        if (num_available > TRACE_BUF_LEN) {
>> -            record = (TraceRecord){
>> -                .event = DROPPED_EVENT_ID,
>> -                .x1 = num_available,
>> -            };
>> -            unused = fwrite(&record, sizeof(record), 1, trace_fp);
>> -            writeout_idx += num_available;
>> +        if (dropped_events) {
>> +            dropped_ptr->event = DROPPED_EVENT_ID,
>> +            dropped_ptr->timestamp_ns = get_clock();
>> +            dropped_ptr->length = sizeof(TraceRecord) + sizeof(dropped_events),
>> +            dropped_ptr->reserved = 0;
>> +            while (1) {
>> +                dropped_count = dropped_events;
>> +                smp_rmb();
>
> Not needed, glib says g_atomic_int_compare_and_exchange() "acts as a
> full compiler and hardware memory barrier".
>
> http://developer.gnome.org/glib/2.32/glib-Atomic-Operations.html#g-atomic-int-compare-and-exchange
>
>> +                if (g_atomic_int_compare_and_exchange((gint *)&dropped_events,
>> +                                                      dropped_count, 0)) {
>> +                    break;
>> +                }
>> +            }
>
> It's a shame we have to loop when a simple atomic exchange would have
> done the job better but glib doesn't seem to support that.
>
> Stefan
>