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

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

On 07/18/2012 12:31 AM, Harsh Bora wrote:
> 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?

Ah, I confused it with trace_record_finish where we write back the 
previously read header, which is not the case here. However, I still 
feel using an array is better here probably because:
1) We anyway cant use memcpy here to read from global buffer, we have to 
use read_from_buffer to take care of buffer boundaries.
2) Isnt malloc() expensive for such a small allocation requirement?

regards,
Harsh

>
> ~ 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
>>
>
>
>