From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from eggs.gnu.org ([208.118.235.92]:40893) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1SrE4v-0002Ju-HC for qemu-devel@nongnu.org; Tue, 17 Jul 2012 16:09:07 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1SrE4t-00079I-MV for qemu-devel@nongnu.org; Tue, 17 Jul 2012 16:09:05 -0400 Received: from e28smtp02.in.ibm.com ([122.248.162.2]:57046) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1SrE4s-00078i-QC for qemu-devel@nongnu.org; Tue, 17 Jul 2012 16:09:03 -0400 Received: from /spool/local by e28smtp02.in.ibm.com with IBM ESMTP SMTP Gateway: Authorized Use Only! Violators will be prosecuted for from ; Wed, 18 Jul 2012 01:38:53 +0530 Received: from d28av01.in.ibm.com (d28av01.in.ibm.com [9.184.220.63]) by d28relay01.in.ibm.com (8.13.8/8.13.8/NCO v10.0) with ESMTP id q6HK8ps358589356 for ; Wed, 18 Jul 2012 01:38:51 +0530 Received: from d28av01.in.ibm.com (loopback [127.0.0.1]) by d28av01.in.ibm.com (8.14.4/8.13.1/NCO v10.0 AVout) with ESMTP id q6I1cNwX003336 for ; Wed, 18 Jul 2012 07:08:23 +0530 Message-ID: <5005C643.5000606@linux.vnet.ibm.com> Date: Wed, 18 Jul 2012 01:38:35 +0530 From: Harsh Bora MIME-Version: 1.0 References: <1341307259-27262-1-git-send-email-harsh@linux.vnet.ibm.com> <1341307259-27262-3-git-send-email-harsh@linux.vnet.ibm.com> <5005B6A5.7030000@linux.vnet.ibm.com> In-Reply-To: <5005B6A5.7030000@linux.vnet.ibm.com> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Subject: Re: [Qemu-devel] [PATCH v7 2/3] Simpletrace v2: Support multiple arguments, strings. List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Stefan Hajnoczi Cc: qemu-devel@nongnu.org, stefanha@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 >> 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 >>> --- >>> 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 >> > > >