On 06/07/2012 08:02 PM, Stefan Hajnoczi wrote:
On Thu, May 24, 2012 at 10:50 AM, Harsh Prateek Bora
<ha...@linux.vnet.ibm.com> wrote:
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<ha...@linux.vnet.ibm.com>
---
scripts/tracetool/backend/simple.py | 84 ++++++++++---
trace/simple.c | 229 ++++++++++++++++++++++-------------
trace/simple.h | 38 +++++-
3 files changed, 240 insertions(+), 111 deletions(-)
Sorry for the delay. Mostly easy to fix comments, some care still
needed to avoid race conditions and use memory barriers in the right
places.
Hi Stefan,
Thanks for reviewing, I have some questions below:
@@ -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 */
The need for the memory barrier is no longer clear. Previously we
were directly accessing the trace ring buffer, and therefore needed to
ensure fields were settled before accessing them. Now we use
read_from_buffer() which copies the data into our temporary struct on
the stack.
I think the best way of doing it is to read the event field first in a
separate step, then do the read memory barrier, and then read the rest
of the record. This ensures that the event field is at least as "old"
as the other fields we read.
Currently, it does a two step read:
read header (which includes event field and length of record as well)
sync
read rest of record (using length from header)
Are you suggesting this:
read event field only
sync (if event valid)
read header (for length)
sync
read rest of record (using length)
or
read event field only
sync (if event valid)
read header (for length)
read rest of record
As we cant read the whole record in one step without knowing its length.
- *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;
}
[....]
-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;
-ENOSPC? A negative errno is clearer than 0 - success, 1 - failure.
+ }
+ idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, rec_len) %
TRACE_BUF_LEN;
How does this deal with the race condition of two or more threads
running trace_alloc_record() concurrently when the buffer reaches max
size? I think two or more threads could think they have enough space
because trace_idx hasn't been updated yet between the buffer length
check and the atomic update.
Are you suggesting to use locking here ? I couldnt find a test-and-set
alternative in glib2. Does qemu have access to any such interface ?
+
+ /* 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);
This suggests a pattern where write_to_buffer() returns the new index:
rec_off = write_to_buffer(rec_off, (uint8_t*)&event, sizeof(event));
That way you don't need to do the separate sizeof() additions.
+
+ 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)
size_t is the type to use for memory size units.
[...]
+void trace_record_finish(TraceBufferRecord *rec);
+uint32_t safe_strlen(const char* str);
Given that safe_strlen() is only used once and a generic utility (not
specific to the simple trace backend), I suggest dropping it an just
open coding the tristate operator: s ? strlen(s) : 0.
safe_strlen is used multiple times in auto-generated code by tracetool
in expression for calculating the sum of size of trace arguments which
as of now looks like:
8 + 8 + 4 + safe_strlen(str1) + 8 + 4 + safe_strlen(str2) ...
for tracing events with string arguments. For trace events with multiple
strings, this expression is more readable as compared to having an
expression with tristate operator like this:
8 + 8 + 4 + (str1 ? strlen(str1) : 0) + 8 + 4 + (str2 ? strlen(str2) :
0) ...
I agree that its a generic function and need not be placed in tracing
code, let me know the right place where to put it if you think its worth
keeping it.
regards,
Harsh
Stefan
