From patchwork Thu May 24 09:50:31 2012 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Harsh Prateek Bora X-Patchwork-Id: 161112 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.gnu.org (lists.gnu.org [208.118.235.17]) (using TLSv1 with cipher AES256-SHA (256/256 bits)) (Client did not present a certificate) by ozlabs.org (Postfix) with ESMTPS id 0D753B6FF7 for ; Thu, 24 May 2012 20:12:32 +1000 (EST) Received: from localhost ([::1]:42090 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1SXV1x-0004fn-R3 for incoming@patchwork.ozlabs.org; Thu, 24 May 2012 06:12:29 -0400 Received: from eggs.gnu.org ([208.118.235.92]:48343) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1SXV1k-0004dk-0c for qemu-devel@nongnu.org; Thu, 24 May 2012 06:12:21 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1SXV1e-0000oP-04 for qemu-devel@nongnu.org; Thu, 24 May 2012 06:12:15 -0400 Received: from e28smtp09.in.ibm.com ([122.248.162.9]:44261) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1SXV1d-0000iC-43 for qemu-devel@nongnu.org; Thu, 24 May 2012 06:12:09 -0400 Received: from /spool/local by e28smtp09.in.ibm.com with IBM ESMTP SMTP Gateway: Authorized Use Only! Violators will be prosecuted for from ; Thu, 24 May 2012 15:23:39 +0530 Received: from d28relay02.in.ibm.com (9.184.220.59) by e28smtp09.in.ibm.com (192.168.1.139) with IBM ESMTP SMTP Gateway: Authorized Use Only! Violators will be prosecuted; Thu, 24 May 2012 15:23:07 +0530 Received: from d28av01.in.ibm.com (d28av01.in.ibm.com [9.184.220.63]) by d28relay02.in.ibm.com (8.13.8/8.13.8/NCO v10.0) with ESMTP id q4O9og5016580732 for ; Thu, 24 May 2012 15:20:42 +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 q4OFKJgn020751 for ; Thu, 24 May 2012 20:50:20 +0530 Received: from harshbora.in.ibm.com ([9.124.35.163]) by d28av01.in.ibm.com (8.14.4/8.13.1/NCO v10.0 AVin) with ESMTP id q4OFKGvB020614; Thu, 24 May 2012 20:50:19 +0530 From: Harsh Prateek Bora To: qemu-devel@nongnu.org Date: Thu, 24 May 2012 15:20:31 +0530 Message-Id: <1337853032-32590-3-git-send-email-harsh@linux.vnet.ibm.com> X-Mailer: git-send-email 1.7.1.1 In-Reply-To: <1337853032-32590-1-git-send-email-harsh@linux.vnet.ibm.com> References: <1337853032-32590-1-git-send-email-harsh@linux.vnet.ibm.com> x-cbid: 12052409-2674-0000-0000-000004AA4687 X-detected-operating-system: by eggs.gnu.org: Genre and OS details not recognized. X-Received-From: 122.248.162.9 Cc: Harsh Prateek Bora , stefanha@linux.vnet.ibm.com, aneesh.kumar@linux.vnet.ibm.com Subject: [Qemu-devel] [PATCH v2 2/3] Simpletrace v2: Add support for multiple args, strings. X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org Sender: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org 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 --- scripts/tracetool/backend/simple.py | 84 ++++++++++--- trace/simple.c | 229 ++++++++++++++++++++++------------- trace/simple.h | 38 +++++- 3 files changed, 240 insertions(+), 111 deletions(-) diff --git a/scripts/tracetool/backend/simple.py b/scripts/tracetool/backend/simple.py index fbb5717..ef9ed93 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 + safe_strlen(%s)" % name) + 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 a6583d3..4e3ae65 100644 --- a/trace/simple.c +++ b/trace/simple.c @@ -27,7 +27,7 @@ #define HEADER_MAGIC 0xf2b177cb0aa429b4ULL /** Trace file version number, bump if format changes */ -#define HEADER_VERSION 0 +#define HEADER_VERSION 2 /** Records were dropped event ID */ #define DROPPED_EVENT_ID (~(uint64_t)0 - 1) @@ -35,23 +35,6 @@ /** Trace record is valid */ #define TRACE_RECORD_VALID ((uint64_t)1 << 63) -/** Trace buffer entry */ -typedef struct { - uint64_t event; - uint64_t timestamp_ns; - uint64_t x1; - uint64_t x2; - uint64_t x3; - uint64_t x4; - uint64_t x5; - uint64_t x6; -} TraceRecord; - -enum { - TRACE_BUF_LEN = 4096, - TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4, -}; - /* * Trace records are written out by a dedicated thread. The thread waits for * records to become available, writes them out, and then waits again. @@ -62,11 +45,49 @@ static GCond *trace_empty_cond; static bool trace_available; static bool trace_writeout_enabled; -static TraceRecord trace_buf[TRACE_BUF_LEN]; +enum { + TRACE_BUF_LEN = 4096 * 64, + TRACE_BUF_FLUSH_THRESHOLD = TRACE_BUF_LEN / 4, +}; + +uint8_t trace_buf[TRACE_BUF_LEN]; static unsigned int trace_idx; +static unsigned int writeout_idx; +static uint64_t dropped_events; static FILE *trace_fp; static char *trace_file_name = NULL; +/* * Trace buffer entry */ +typedef struct { + uint64_t event; /* TraceEventID */ + uint64_t timestamp_ns; + uint32_t length; /* in bytes */ + uint32_t reserved; /* unused */ + uint8_t arguments[]; /* arguments position affects ST_REC_HDR_LEN */ +} TraceRecord; + +typedef struct { + uint64_t header_event_id; /* HEADER_EVENT_ID */ + uint64_t header_magic; /* HEADER_MAGIC */ + uint64_t header_version; /* HEADER_VERSION */ +} TraceRecordHeader; + +/* * Trace record header length */ +#define ST_REC_HDR_LEN sizeof(TraceRecord) + +int trace_alloc_record(TraceBufferRecord *rec, TraceEventID event, uint32_t datasize); +static void read_from_buffer(unsigned int idx, uint8_t *dataptr, uint32_t size); +static void write_to_buffer(unsigned int idx, uint8_t *dataptr, uint32_t size); +void trace_mark_record_complete(TraceBufferRecord *rec); + +uint32_t safe_strlen(const char* str) +{ + if (str == NULL) { + return 0; + } + return strlen(str); +} + /** * Read a trace record from the trace buffer * @@ -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 */ - *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; } @@ -120,29 +147,31 @@ 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; + unsigned int idx = 0; 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) { + recordptr = g_malloc(ST_REC_HDR_LEN + sizeof(dropped_events)); + recordptr->event = DROPPED_EVENT_ID, + recordptr->timestamp_ns = get_clock(); + recordptr->length = ST_REC_HDR_LEN + sizeof(dropped_events), + recordptr->reserved = 0; + *(uint64_t *) &(recordptr->arguments[0]) = dropped_events; + dropped_events = 0; + unused = fwrite(recordptr, recordptr->length, 1, trace_fp); } - idx = writeout_idx % TRACE_BUF_LEN; - while (get_trace_record(idx, &record)) { - trace_buf[idx].event = 0; /* clear valid bit */ - unused = fwrite(&record, sizeof(record), 1, trace_fp); - idx = ++writeout_idx % TRACE_BUF_LEN; + while (get_trace_record(idx, &recordptr)) { + unused = fwrite(recordptr, recordptr->length, 1, trace_fp); + writeout_idx += recordptr->length; + g_free(recordptr); + recordptr = (TraceRecord *) &trace_buf[idx]; + recordptr->event = 0; + idx = writeout_idx % TRACE_BUF_LEN; } fflush(trace_fp); @@ -150,72 +179,101 @@ static gpointer writeout_thread(gpointer opaque) return NULL; } -static void trace(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, - uint64_t x4, uint64_t x5, uint64_t x6) +int trace_record_start(TraceBufferRecord *rec, TraceEventID id, size_t arglen) { - unsigned int idx; - uint64_t timestamp; - - if (!trace_list[event].state) { - return; - } - - timestamp = get_clock(); - - idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, 1) % TRACE_BUF_LEN; - trace_buf[idx] = (TraceRecord){ - .event = event, - .timestamp_ns = timestamp, - .x1 = x1, - .x2 = x2, - .x3 = x3, - .x4 = x4, - .x5 = x5, - .x6 = x6, - }; - __sync_synchronize(); /* write barrier before marking as valid */ - trace_buf[idx].event |= TRACE_RECORD_VALID; - - if ((idx + 1) % TRACE_BUF_FLUSH_THRESHOLD == 0) { - flush_trace_file(false); - } + return trace_alloc_record(rec, id, arglen); /* return 0 on success */ } -void trace0(TraceEventID event) +void trace_record_write_u64(TraceBufferRecord *rec, uint64_t val) { - trace(event, 0, 0, 0, 0, 0, 0); + write_to_buffer(rec->rec_off, (uint8_t *)&val, sizeof(uint64_t)); + rec->rec_off += sizeof(uint64_t); } -void trace1(TraceEventID event, uint64_t x1) +void trace_record_write_str(TraceBufferRecord *rec, const char *s) { - trace(event, x1, 0, 0, 0, 0, 0); + /* Write string length first */ + uint32_t slen = (s == NULL ? 0 : strlen(s)); + write_to_buffer(rec->rec_off, (uint8_t *)&slen, sizeof(slen)); + rec->rec_off += sizeof(slen); + /* Write actual string now */ + write_to_buffer(rec->rec_off, (uint8_t *)s, slen); + rec->rec_off += slen; } -void trace2(TraceEventID event, uint64_t x1, uint64_t x2) +void trace_record_finish(TraceBufferRecord *rec) { - trace(event, x1, x2, 0, 0, 0, 0); + trace_mark_record_complete(rec); } -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; + } + idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, rec_len) % TRACE_BUF_LEN; + + /* 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*)×tamp_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); + + 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) { - trace(event, x1, x2, x3, x4, 0, 0); + uint32_t x = 0; + while (x < size) { + if (idx >= TRACE_BUF_LEN) { + idx = idx % TRACE_BUF_LEN; + } + dataptr[x++] = trace_buf[idx++]; + } } -void trace5(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5) +static void write_to_buffer(unsigned int idx, uint8_t *dataptr, uint32_t size) { - trace(event, x1, x2, x3, x4, x5, 0); + uint32_t x = 0; + while (x < size) { + if (idx >= TRACE_BUF_LEN) { + idx = idx % TRACE_BUF_LEN; + } + trace_buf[idx++] = dataptr[x++]; + } } -void trace6(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6) +void trace_mark_record_complete(TraceBufferRecord *rec) { - trace(event, x1, x2, x3, x4, x5, x6); + uint8_t temp_rec[ST_REC_HDR_LEN]; + TraceRecord *record = (TraceRecord *) temp_rec; + read_from_buffer(rec->tbuf_idx, temp_rec, ST_REC_HDR_LEN); + __sync_synchronize(); /* write barrier before marking as valid */ + record->event |= TRACE_RECORD_VALID; + write_to_buffer(rec->tbuf_idx, temp_rec, ST_REC_HDR_LEN); + + if (rec->next_tbuf_idx > TRACE_BUF_FLUSH_THRESHOLD && + rec->tbuf_idx <= TRACE_BUF_FLUSH_THRESHOLD) { + flush_trace_file(false); + } } + + void st_set_trace_file_enabled(bool enable) { if (enable == !!trace_fp) { @@ -228,10 +286,11 @@ void st_set_trace_file_enabled(bool enable) flush_trace_file(true); if (enable) { - static const TraceRecord header = { - .event = HEADER_EVENT_ID, - .timestamp_ns = HEADER_MAGIC, - .x1 = HEADER_VERSION, + static const TraceRecordHeader header = { + .header_event_id = HEADER_EVENT_ID, + .header_magic = HEADER_MAGIC, + /* Older log readers will check for version at next location */ + .header_version = HEADER_VERSION, }; trace_fp = fopen(trace_file_name, "wb"); diff --git a/trace/simple.h b/trace/simple.h index 6b5358c..06ea778 100644 --- a/trace/simple.h +++ b/trace/simple.h @@ -22,16 +22,40 @@ typedef struct { bool state; } TraceEvent; -void trace0(TraceEventID event); -void trace1(TraceEventID event, uint64_t x1); -void trace2(TraceEventID event, uint64_t x1, uint64_t x2); -void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3); -void trace4(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4); -void trace5(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5); -void trace6(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6); void st_print_trace_file_status(FILE *stream, fprintf_function stream_printf); void st_set_trace_file_enabled(bool enable); bool st_set_trace_file(const char *file); void st_flush_trace_buffer(void); +typedef struct { + unsigned int tbuf_idx; + unsigned int next_tbuf_idx; + unsigned int rec_off; +} TraceBufferRecord; + +/* * + * Initialize a trace record and claim space for it in the buffer + * + * @arglen number of bytes required for arguments + */ +int trace_record_start(TraceBufferRecord *rec, TraceEventID id, size_t arglen); + +/* * + * Append a 64-bit argument to a trace record + */ +void trace_record_write_u64(TraceBufferRecord *rec, uint64_t val); + +/* * + * Append a string argument to a trace record + */ +void trace_record_write_str(TraceBufferRecord *rec, const char *s); + +/* * + * Mark a trace record completed + * + * Don't append any more arguments to the trace record after calling this. + */ +void trace_record_finish(TraceBufferRecord *rec); +uint32_t safe_strlen(const char* str); + #endif /* TRACE_SIMPLE_H */