From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from eggs.gnu.org ([208.118.235.92]:59654) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1SrD2S-0006sU-6a for qemu-devel@nongnu.org; Tue, 17 Jul 2012 15:02:29 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1SrD2Q-0005uO-6m for qemu-devel@nongnu.org; Tue, 17 Jul 2012 15:02:28 -0400 Received: from e28smtp02.in.ibm.com ([122.248.162.2]:46643) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1SrD2P-0005uA-9L for qemu-devel@nongnu.org; Tue, 17 Jul 2012 15:02:26 -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 00:32:14 +0530 Received: from d28av05.in.ibm.com (d28av05.in.ibm.com [9.184.220.67]) by d28relay03.in.ibm.com (8.13.8/8.13.8/NCO v10.0) with ESMTP id q6HJ2C1e7274912 for ; Wed, 18 Jul 2012 00:32:13 +0530 Received: from d28av05.in.ibm.com (loopback [127.0.0.1]) by d28av05.in.ibm.com (8.14.4/8.13.1/NCO v10.0 AVout) with ESMTP id q6I0WlPE007183 for ; Wed, 18 Jul 2012 10:32:48 +1000 Message-ID: <5005B6A5.7030000@linux.vnet.ibm.com> Date: Wed, 18 Jul 2012 00:31:57 +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> In-Reply-To: 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/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? ~ 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 >