Merge remote-tracking branch 'stefanha/tracing' into staging
* stefanha/tracing: Update simpletrace.py for new log format Simpletrace v2: Support multiple arguments, strings. monitor: remove unused do_info_trace trace: added ability to comment out events in the list
This commit is contained in:
commit
903f650b0c
16
monitor.c
16
monitor.c
|
@ -941,13 +941,6 @@ static void do_info_cpu_stats(Monitor *mon)
|
||||||
}
|
}
|
||||||
#endif
|
#endif
|
||||||
|
|
||||||
#if defined(CONFIG_TRACE_SIMPLE)
|
|
||||||
static void do_info_trace(Monitor *mon)
|
|
||||||
{
|
|
||||||
st_print_trace((FILE *)mon, &monitor_fprintf);
|
|
||||||
}
|
|
||||||
#endif
|
|
||||||
|
|
||||||
static void do_trace_print_events(Monitor *mon)
|
static void do_trace_print_events(Monitor *mon)
|
||||||
{
|
{
|
||||||
trace_print_events((FILE *)mon, &monitor_fprintf);
|
trace_print_events((FILE *)mon, &monitor_fprintf);
|
||||||
|
@ -2689,15 +2682,6 @@ static mon_cmd_t info_cmds[] = {
|
||||||
.help = "show roms",
|
.help = "show roms",
|
||||||
.mhandler.info = do_info_roms,
|
.mhandler.info = do_info_roms,
|
||||||
},
|
},
|
||||||
#if defined(CONFIG_TRACE_SIMPLE)
|
|
||||||
{
|
|
||||||
.name = "trace",
|
|
||||||
.args_type = "",
|
|
||||||
.params = "",
|
|
||||||
.help = "show current contents of trace buffer",
|
|
||||||
.mhandler.info = do_info_trace,
|
|
||||||
},
|
|
||||||
#endif
|
|
||||||
{
|
{
|
||||||
.name = "trace-events",
|
.name = "trace-events",
|
||||||
.args_type = "",
|
.args_type = "",
|
||||||
|
|
|
@ -12,53 +12,69 @@
|
||||||
import struct
|
import struct
|
||||||
import re
|
import re
|
||||||
import inspect
|
import inspect
|
||||||
|
from tracetool import _read_events, Event
|
||||||
|
from tracetool.backend.simple import is_string
|
||||||
|
|
||||||
header_event_id = 0xffffffffffffffff
|
header_event_id = 0xffffffffffffffff
|
||||||
header_magic = 0xf2b177cb0aa429b4
|
header_magic = 0xf2b177cb0aa429b4
|
||||||
header_version = 0
|
|
||||||
dropped_event_id = 0xfffffffffffffffe
|
dropped_event_id = 0xfffffffffffffffe
|
||||||
|
|
||||||
trace_fmt = '=QQQQQQQQ'
|
log_header_fmt = '=QQQ'
|
||||||
trace_len = struct.calcsize(trace_fmt)
|
rec_header_fmt = '=QQII'
|
||||||
event_re = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\).*')
|
|
||||||
|
|
||||||
def parse_events(fobj):
|
def read_header(fobj, hfmt):
|
||||||
"""Parse a trace-events file into {event_num: (name, arg1, ...)}."""
|
'''Read a trace record header'''
|
||||||
|
hlen = struct.calcsize(hfmt)
|
||||||
def get_argnames(args):
|
hdr = fobj.read(hlen)
|
||||||
"""Extract argument names from a parameter list."""
|
if len(hdr) != hlen:
|
||||||
return tuple(arg.split()[-1].lstrip('*') for arg in args.split(','))
|
|
||||||
|
|
||||||
events = {dropped_event_id: ('dropped', 'count')}
|
|
||||||
event_num = 0
|
|
||||||
for line in fobj:
|
|
||||||
m = event_re.match(line.strip())
|
|
||||||
if m is None:
|
|
||||||
continue
|
|
||||||
|
|
||||||
disable, name, args = m.groups()
|
|
||||||
events[event_num] = (name,) + get_argnames(args)
|
|
||||||
event_num += 1
|
|
||||||
return events
|
|
||||||
|
|
||||||
def read_record(fobj):
|
|
||||||
"""Deserialize a trace record from a file into a tuple (event_num, timestamp, arg1, ..., arg6)."""
|
|
||||||
s = fobj.read(trace_len)
|
|
||||||
if len(s) != trace_len:
|
|
||||||
return None
|
return None
|
||||||
return struct.unpack(trace_fmt, s)
|
return struct.unpack(hfmt, hdr)
|
||||||
|
|
||||||
def read_trace_file(fobj):
|
def get_record(edict, rechdr, fobj):
|
||||||
|
"""Deserialize a trace record from a file into a tuple (event_num, timestamp, arg1, ..., arg6)."""
|
||||||
|
if rechdr is None:
|
||||||
|
return None
|
||||||
|
rec = (rechdr[0], rechdr[1])
|
||||||
|
if rechdr[0] != dropped_event_id:
|
||||||
|
event_id = rechdr[0]
|
||||||
|
event = edict[event_id]
|
||||||
|
for type, name in event.args:
|
||||||
|
if is_string(type):
|
||||||
|
l = fobj.read(4)
|
||||||
|
(len,) = struct.unpack('=L', l)
|
||||||
|
s = fobj.read(len)
|
||||||
|
rec = rec + (s,)
|
||||||
|
else:
|
||||||
|
(value,) = struct.unpack('=Q', fobj.read(8))
|
||||||
|
rec = rec + (value,)
|
||||||
|
else:
|
||||||
|
(value,) = struct.unpack('=Q', fobj.read(8))
|
||||||
|
rec = rec + (value,)
|
||||||
|
return rec
|
||||||
|
|
||||||
|
|
||||||
|
def read_record(edict, fobj):
|
||||||
|
"""Deserialize a trace record from a file into a tuple (event_num, timestamp, arg1, ..., arg6)."""
|
||||||
|
rechdr = read_header(fobj, rec_header_fmt)
|
||||||
|
return get_record(edict, rechdr, fobj) # return tuple of record elements
|
||||||
|
|
||||||
|
def read_trace_file(edict, fobj):
|
||||||
"""Deserialize trace records from a file, yielding record tuples (event_num, timestamp, arg1, ..., arg6)."""
|
"""Deserialize trace records from a file, yielding record tuples (event_num, timestamp, arg1, ..., arg6)."""
|
||||||
header = read_record(fobj)
|
header = read_header(fobj, log_header_fmt)
|
||||||
if header is None or \
|
if header is None or \
|
||||||
header[0] != header_event_id or \
|
header[0] != header_event_id or \
|
||||||
header[1] != header_magic or \
|
header[1] != header_magic:
|
||||||
header[2] != header_version:
|
raise ValueError('Not a valid trace file!')
|
||||||
raise ValueError('not a trace file or incompatible version')
|
if header[2] != 0 and \
|
||||||
|
header[2] != 2:
|
||||||
|
raise ValueError('Unknown version of tracelog format!')
|
||||||
|
|
||||||
|
log_version = header[2]
|
||||||
|
if log_version == 0:
|
||||||
|
raise ValueError('Older log format, not supported with this Qemu release!')
|
||||||
|
|
||||||
while True:
|
while True:
|
||||||
rec = read_record(fobj)
|
rec = read_record(edict, fobj)
|
||||||
if rec is None:
|
if rec is None:
|
||||||
break
|
break
|
||||||
|
|
||||||
|
@ -89,16 +105,29 @@ class Analyzer(object):
|
||||||
def process(events, log, analyzer):
|
def process(events, log, analyzer):
|
||||||
"""Invoke an analyzer on each event in a log."""
|
"""Invoke an analyzer on each event in a log."""
|
||||||
if isinstance(events, str):
|
if isinstance(events, str):
|
||||||
events = parse_events(open(events, 'r'))
|
events = _read_events(open(events, 'r'))
|
||||||
if isinstance(log, str):
|
if isinstance(log, str):
|
||||||
log = open(log, 'rb')
|
log = open(log, 'rb')
|
||||||
|
|
||||||
|
enabled_events = []
|
||||||
|
dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
|
||||||
|
edict = {dropped_event_id: dropped_event}
|
||||||
|
|
||||||
|
for e in events:
|
||||||
|
if 'disable' not in e.properties:
|
||||||
|
enabled_events.append(e)
|
||||||
|
for num, event in enumerate(enabled_events):
|
||||||
|
edict[num] = event
|
||||||
|
|
||||||
def build_fn(analyzer, event):
|
def build_fn(analyzer, event):
|
||||||
fn = getattr(analyzer, event[0], None)
|
if isinstance(event, str):
|
||||||
|
return analyzer.catchall
|
||||||
|
|
||||||
|
fn = getattr(analyzer, event.name, None)
|
||||||
if fn is None:
|
if fn is None:
|
||||||
return analyzer.catchall
|
return analyzer.catchall
|
||||||
|
|
||||||
event_argcount = len(event) - 1
|
event_argcount = len(event.args)
|
||||||
fn_argcount = len(inspect.getargspec(fn)[0]) - 1
|
fn_argcount = len(inspect.getargspec(fn)[0]) - 1
|
||||||
if fn_argcount == event_argcount + 1:
|
if fn_argcount == event_argcount + 1:
|
||||||
# Include timestamp as first argument
|
# Include timestamp as first argument
|
||||||
|
@ -109,9 +138,9 @@ def process(events, log, analyzer):
|
||||||
|
|
||||||
analyzer.begin()
|
analyzer.begin()
|
||||||
fn_cache = {}
|
fn_cache = {}
|
||||||
for rec in read_trace_file(log):
|
for rec in read_trace_file(edict, log):
|
||||||
event_num = rec[0]
|
event_num = rec[0]
|
||||||
event = events[event_num]
|
event = edict[event_num]
|
||||||
if event_num not in fn_cache:
|
if event_num not in fn_cache:
|
||||||
fn_cache[event_num] = build_fn(analyzer, event)
|
fn_cache[event_num] = build_fn(analyzer, event)
|
||||||
fn_cache[event_num](event, rec)
|
fn_cache[event_num](event, rec)
|
||||||
|
@ -128,7 +157,7 @@ def run(analyzer):
|
||||||
sys.stderr.write('usage: %s <trace-events> <trace-file>\n' % sys.argv[0])
|
sys.stderr.write('usage: %s <trace-events> <trace-file>\n' % sys.argv[0])
|
||||||
sys.exit(1)
|
sys.exit(1)
|
||||||
|
|
||||||
events = parse_events(open(sys.argv[1], 'r'))
|
events = _read_events(open(sys.argv[1], 'r'))
|
||||||
process(events, sys.argv[2], analyzer)
|
process(events, sys.argv[2], analyzer)
|
||||||
|
|
||||||
if __name__ == '__main__':
|
if __name__ == '__main__':
|
||||||
|
@ -137,15 +166,20 @@ if __name__ == '__main__':
|
||||||
self.last_timestamp = None
|
self.last_timestamp = None
|
||||||
|
|
||||||
def catchall(self, event, rec):
|
def catchall(self, event, rec):
|
||||||
|
i = 1
|
||||||
timestamp = rec[1]
|
timestamp = rec[1]
|
||||||
if self.last_timestamp is None:
|
if self.last_timestamp is None:
|
||||||
self.last_timestamp = timestamp
|
self.last_timestamp = timestamp
|
||||||
delta_ns = timestamp - self.last_timestamp
|
delta_ns = timestamp - self.last_timestamp
|
||||||
self.last_timestamp = timestamp
|
self.last_timestamp = timestamp
|
||||||
|
|
||||||
fields = [event[0], '%0.3f' % (delta_ns / 1000.0)]
|
fields = [event.name, '%0.3f' % (delta_ns / 1000.0)]
|
||||||
for i in xrange(1, len(event)):
|
for type, name in event.args:
|
||||||
fields.append('%s=0x%x' % (event[i], rec[i + 1]))
|
if is_string(type):
|
||||||
|
fields.append('%s=%s' % (name, rec[i + 1]))
|
||||||
|
else:
|
||||||
|
fields.append('%s=0x%x' % (name, rec[i + 1]))
|
||||||
|
i += 1
|
||||||
print ' '.join(fields)
|
print ' '.join(fields)
|
||||||
|
|
||||||
run(Formatter())
|
run(Formatter())
|
||||||
|
|
|
@ -15,9 +15,16 @@ __email__ = "stefanha@linux.vnet.ibm.com"
|
||||||
|
|
||||||
from tracetool import out
|
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):
|
def c(events):
|
||||||
out('#include "trace.h"',
|
out('#include "trace.h"',
|
||||||
|
'#include "trace/simple.h"',
|
||||||
'',
|
'',
|
||||||
'TraceEvent trace_list[] = {')
|
'TraceEvent trace_list[] = {')
|
||||||
|
|
||||||
|
@ -26,30 +33,75 @@ def c(events):
|
||||||
name = e.name,
|
name = e.name,
|
||||||
)
|
)
|
||||||
|
|
||||||
out('};')
|
out('};',
|
||||||
|
'')
|
||||||
|
|
||||||
|
for num, event in enumerate(events):
|
||||||
|
out('void trace_%(name)s(%(args)s)',
|
||||||
|
'{',
|
||||||
|
' TraceBufferRecord rec;',
|
||||||
|
name = event.name,
|
||||||
|
args = event.args,
|
||||||
|
)
|
||||||
|
sizes = []
|
||||||
|
for type_, name in event.args:
|
||||||
|
if is_string(type_):
|
||||||
|
out(' size_t arg%(name)s_len = %(name)s ? MIN(strlen(%(name)s), MAX_TRACE_STRLEN) : 0;',
|
||||||
|
name = name,
|
||||||
|
)
|
||||||
|
strsizeinfo = "4 + arg%s_len" % name
|
||||||
|
sizes.append(strsizeinfo)
|
||||||
|
else:
|
||||||
|
sizes.append("8")
|
||||||
|
sizestr = " + ".join(sizes)
|
||||||
|
if len(event.args) == 0:
|
||||||
|
sizestr = '0'
|
||||||
|
|
||||||
|
|
||||||
|
out('',
|
||||||
|
' 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 ! */',
|
||||||
|
' }',
|
||||||
|
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, arg%(name)s_len);',
|
||||||
|
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):
|
def h(events):
|
||||||
out('#include "trace/simple.h"',
|
out('#include "trace/simple.h"',
|
||||||
'')
|
'')
|
||||||
|
|
||||||
for num, e in enumerate(events):
|
for event in events:
|
||||||
if len(e.args):
|
out('void trace_%(name)s(%(args)s);',
|
||||||
argstr = e.args.names()
|
name = event.name,
|
||||||
arg_prefix = ', (uint64_t)(uintptr_t)'
|
args = event.args,
|
||||||
cast_args = arg_prefix + arg_prefix.join(argstr)
|
|
||||||
simple_args = (str(num) + cast_args)
|
|
||||||
else:
|
|
||||||
simple_args = str(num)
|
|
||||||
|
|
||||||
out('static inline 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,
|
|
||||||
)
|
)
|
||||||
|
out('')
|
||||||
out('#define NR_TRACE_EVENTS %d' % len(events))
|
out('#define NR_TRACE_EVENTS %d' % len(events))
|
||||||
out('extern TraceEvent trace_list[NR_TRACE_EVENTS];')
|
out('extern TraceEvent trace_list[NR_TRACE_EVENTS];')
|
||||||
|
|
|
@ -27,6 +27,9 @@ void trace_backend_init_events(const char *fname)
|
||||||
size_t len = strlen(line_buf);
|
size_t len = strlen(line_buf);
|
||||||
if (len > 1) { /* skip empty lines */
|
if (len > 1) { /* skip empty lines */
|
||||||
line_buf[len - 1] = '\0';
|
line_buf[len - 1] = '\0';
|
||||||
|
if ('#' == line_buf[0]) { /* skip commented lines */
|
||||||
|
continue;
|
||||||
|
}
|
||||||
if (!trace_event_set_state(line_buf, true)) {
|
if (!trace_event_set_state(line_buf, true)) {
|
||||||
fprintf(stderr,
|
fprintf(stderr,
|
||||||
"error: trace event '%s' does not exist\n", line_buf);
|
"error: trace event '%s' does not exist\n", line_buf);
|
||||||
|
|
293
trace/simple.c
293
trace/simple.c
|
@ -27,7 +27,7 @@
|
||||||
#define HEADER_MAGIC 0xf2b177cb0aa429b4ULL
|
#define HEADER_MAGIC 0xf2b177cb0aa429b4ULL
|
||||||
|
|
||||||
/** Trace file version number, bump if format changes */
|
/** Trace file version number, bump if format changes */
|
||||||
#define HEADER_VERSION 0
|
#define HEADER_VERSION 2
|
||||||
|
|
||||||
/** Records were dropped event ID */
|
/** Records were dropped event ID */
|
||||||
#define DROPPED_EVENT_ID (~(uint64_t)0 - 1)
|
#define DROPPED_EVENT_ID (~(uint64_t)0 - 1)
|
||||||
|
@ -35,23 +35,6 @@
|
||||||
/** Trace record is valid */
|
/** Trace record is valid */
|
||||||
#define TRACE_RECORD_VALID ((uint64_t)1 << 63)
|
#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
|
* Trace records are written out by a dedicated thread. The thread waits for
|
||||||
* records to become available, writes them out, and then waits again.
|
* records to become available, writes them out, and then waits again.
|
||||||
|
@ -62,11 +45,48 @@ static GCond *trace_empty_cond;
|
||||||
static bool trace_available;
|
static bool trace_available;
|
||||||
static bool trace_writeout_enabled;
|
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 trace_idx;
|
||||||
|
static unsigned int writeout_idx;
|
||||||
|
static uint64_t dropped_events;
|
||||||
static FILE *trace_fp;
|
static FILE *trace_fp;
|
||||||
static char *trace_file_name = NULL;
|
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[];
|
||||||
|
} TraceRecord;
|
||||||
|
|
||||||
|
typedef struct {
|
||||||
|
uint64_t header_event_id; /* HEADER_EVENT_ID */
|
||||||
|
uint64_t header_magic; /* HEADER_MAGIC */
|
||||||
|
uint64_t header_version; /* HEADER_VERSION */
|
||||||
|
} TraceRecordHeader;
|
||||||
|
|
||||||
|
|
||||||
|
static void read_from_buffer(unsigned int idx, void *dataptr, size_t size);
|
||||||
|
static unsigned int write_to_buffer(unsigned int idx, void *dataptr, size_t size);
|
||||||
|
|
||||||
|
static void clear_buffer_range(unsigned int idx, size_t len)
|
||||||
|
{
|
||||||
|
uint32_t num = 0;
|
||||||
|
while (num < len) {
|
||||||
|
if (idx >= TRACE_BUF_LEN) {
|
||||||
|
idx = idx % TRACE_BUF_LEN;
|
||||||
|
}
|
||||||
|
trace_buf[idx++] = 0;
|
||||||
|
num++;
|
||||||
|
}
|
||||||
|
}
|
||||||
/**
|
/**
|
||||||
* Read a trace record from the trace buffer
|
* Read a trace record from the trace buffer
|
||||||
*
|
*
|
||||||
|
@ -75,16 +95,30 @@ static char *trace_file_name = NULL;
|
||||||
*
|
*
|
||||||
* Returns false if the record is not valid.
|
* 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)) {
|
uint64_t event_flag = 0;
|
||||||
|
TraceRecord record;
|
||||||
|
/* read the event flag to see if its a valid record */
|
||||||
|
read_from_buffer(idx, &record, sizeof(event_flag));
|
||||||
|
|
||||||
|
if (!(record.event & TRACE_RECORD_VALID)) {
|
||||||
return false;
|
return false;
|
||||||
}
|
}
|
||||||
|
|
||||||
__sync_synchronize(); /* read memory barrier before accessing record */
|
smp_rmb(); /* read memory barrier before accessing record */
|
||||||
|
/* read the record header to know record length */
|
||||||
*record = trace_buf[idx];
|
read_from_buffer(idx, &record, sizeof(TraceRecord));
|
||||||
record->event &= ~TRACE_RECORD_VALID;
|
*recordptr = malloc(record.length); /* dont use g_malloc, can deadlock when traced */
|
||||||
|
/* make a copy of record to avoid being overwritten */
|
||||||
|
read_from_buffer(idx, *recordptr, record.length);
|
||||||
|
smp_rmb(); /* memory barrier before clearing valid flag */
|
||||||
|
(*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;
|
return true;
|
||||||
}
|
}
|
||||||
|
|
||||||
|
@ -120,29 +154,39 @@ static void wait_for_trace_records_available(void)
|
||||||
|
|
||||||
static gpointer writeout_thread(gpointer opaque)
|
static gpointer writeout_thread(gpointer opaque)
|
||||||
{
|
{
|
||||||
TraceRecord record;
|
TraceRecord *recordptr;
|
||||||
unsigned int writeout_idx = 0;
|
union {
|
||||||
unsigned int num_available, idx;
|
TraceRecord rec;
|
||||||
|
uint8_t bytes[sizeof(TraceRecord) + sizeof(uint64_t)];
|
||||||
|
} dropped;
|
||||||
|
unsigned int idx = 0;
|
||||||
|
uint64_t dropped_count;
|
||||||
size_t unused __attribute__ ((unused));
|
size_t unused __attribute__ ((unused));
|
||||||
|
|
||||||
for (;;) {
|
for (;;) {
|
||||||
wait_for_trace_records_available();
|
wait_for_trace_records_available();
|
||||||
|
|
||||||
num_available = trace_idx - writeout_idx;
|
if (dropped_events) {
|
||||||
if (num_available > TRACE_BUF_LEN) {
|
dropped.rec.event = DROPPED_EVENT_ID,
|
||||||
record = (TraceRecord){
|
dropped.rec.timestamp_ns = get_clock();
|
||||||
.event = DROPPED_EVENT_ID,
|
dropped.rec.length = sizeof(TraceRecord) + sizeof(dropped_events),
|
||||||
.x1 = num_available,
|
dropped.rec.reserved = 0;
|
||||||
};
|
while (1) {
|
||||||
unused = fwrite(&record, sizeof(record), 1, trace_fp);
|
dropped_count = dropped_events;
|
||||||
writeout_idx += num_available;
|
if (g_atomic_int_compare_and_exchange((gint *)&dropped_events,
|
||||||
|
dropped_count, 0)) {
|
||||||
|
break;
|
||||||
|
}
|
||||||
|
}
|
||||||
|
memcpy(dropped.rec.arguments, &dropped_count, sizeof(uint64_t));
|
||||||
|
unused = fwrite(&dropped.rec, dropped.rec.length, 1, trace_fp);
|
||||||
}
|
}
|
||||||
|
|
||||||
idx = writeout_idx % TRACE_BUF_LEN;
|
while (get_trace_record(idx, &recordptr)) {
|
||||||
while (get_trace_record(idx, &record)) {
|
unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
|
||||||
trace_buf[idx].event = 0; /* clear valid bit */
|
writeout_idx += recordptr->length;
|
||||||
unused = fwrite(&record, sizeof(record), 1, trace_fp);
|
free(recordptr); /* dont use g_free, can deadlock when traced */
|
||||||
idx = ++writeout_idx % TRACE_BUF_LEN;
|
idx = writeout_idx % TRACE_BUF_LEN;
|
||||||
}
|
}
|
||||||
|
|
||||||
fflush(trace_fp);
|
fflush(trace_fp);
|
||||||
|
@ -150,75 +194,95 @@ static gpointer writeout_thread(gpointer opaque)
|
||||||
return NULL;
|
return NULL;
|
||||||
}
|
}
|
||||||
|
|
||||||
static void trace(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3,
|
void trace_record_write_u64(TraceBufferRecord *rec, uint64_t val)
|
||||||
uint64_t x4, uint64_t x5, uint64_t x6)
|
|
||||||
{
|
{
|
||||||
unsigned int idx;
|
rec->rec_off = write_to_buffer(rec->rec_off, &val, sizeof(uint64_t));
|
||||||
uint64_t timestamp;
|
}
|
||||||
|
|
||||||
if (!trace_list[event].state) {
|
void trace_record_write_str(TraceBufferRecord *rec, const char *s, uint32_t slen)
|
||||||
return;
|
{
|
||||||
|
/* Write string length first */
|
||||||
|
rec->rec_off = write_to_buffer(rec->rec_off, &slen, sizeof(slen));
|
||||||
|
/* Write actual string now */
|
||||||
|
rec->rec_off = write_to_buffer(rec->rec_off, (void*)s, slen);
|
||||||
|
}
|
||||||
|
|
||||||
|
int trace_record_start(TraceBufferRecord *rec, TraceEventID event, size_t datasize)
|
||||||
|
{
|
||||||
|
unsigned int idx, rec_off, old_idx, new_idx;
|
||||||
|
uint32_t rec_len = sizeof(TraceRecord) + datasize;
|
||||||
|
uint64_t timestamp_ns = get_clock();
|
||||||
|
|
||||||
|
while (1) {
|
||||||
|
old_idx = trace_idx;
|
||||||
|
smp_rmb();
|
||||||
|
new_idx = old_idx + rec_len;
|
||||||
|
|
||||||
|
if (new_idx - writeout_idx > TRACE_BUF_LEN) {
|
||||||
|
/* Trace Buffer Full, Event dropped ! */
|
||||||
|
g_atomic_int_inc((gint *)&dropped_events);
|
||||||
|
return -ENOSPC;
|
||||||
|
}
|
||||||
|
|
||||||
|
if (g_atomic_int_compare_and_exchange((gint *)&trace_idx,
|
||||||
|
old_idx, new_idx)) {
|
||||||
|
break;
|
||||||
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
timestamp = get_clock();
|
idx = old_idx % TRACE_BUF_LEN;
|
||||||
#if GLIB_CHECK_VERSION(2, 30, 0)
|
/* To check later if threshold crossed */
|
||||||
idx = g_atomic_int_add((gint *)&trace_idx, 1) % TRACE_BUF_LEN;
|
rec->next_tbuf_idx = new_idx % TRACE_BUF_LEN;
|
||||||
#else
|
|
||||||
idx = g_atomic_int_exchange_and_add((gint *)&trace_idx, 1) % TRACE_BUF_LEN;
|
|
||||||
#endif
|
|
||||||
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) {
|
rec_off = idx;
|
||||||
|
rec_off = write_to_buffer(rec_off, (uint8_t*)&event, sizeof(event));
|
||||||
|
rec_off = write_to_buffer(rec_off, (uint8_t*)×tamp_ns, sizeof(timestamp_ns));
|
||||||
|
rec_off = write_to_buffer(rec_off, (uint8_t*)&rec_len, sizeof(rec_len));
|
||||||
|
|
||||||
|
rec->tbuf_idx = idx;
|
||||||
|
rec->rec_off = (idx + sizeof(TraceRecord)) % TRACE_BUF_LEN;
|
||||||
|
return 0;
|
||||||
|
}
|
||||||
|
|
||||||
|
static void read_from_buffer(unsigned int idx, void *dataptr, size_t size)
|
||||||
|
{
|
||||||
|
uint8_t *data_ptr = dataptr;
|
||||||
|
uint32_t x = 0;
|
||||||
|
while (x < size) {
|
||||||
|
if (idx >= TRACE_BUF_LEN) {
|
||||||
|
idx = idx % TRACE_BUF_LEN;
|
||||||
|
}
|
||||||
|
data_ptr[x++] = trace_buf[idx++];
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
static unsigned int write_to_buffer(unsigned int idx, void *dataptr, size_t size)
|
||||||
|
{
|
||||||
|
uint8_t *data_ptr = dataptr;
|
||||||
|
uint32_t x = 0;
|
||||||
|
while (x < size) {
|
||||||
|
if (idx >= TRACE_BUF_LEN) {
|
||||||
|
idx = idx % TRACE_BUF_LEN;
|
||||||
|
}
|
||||||
|
trace_buf[idx++] = data_ptr[x++];
|
||||||
|
}
|
||||||
|
return idx; /* most callers wants to know where to write next */
|
||||||
|
}
|
||||||
|
|
||||||
|
void trace_record_finish(TraceBufferRecord *rec)
|
||||||
|
{
|
||||||
|
uint8_t temp_rec[sizeof(TraceRecord)];
|
||||||
|
TraceRecord *record = (TraceRecord *) temp_rec;
|
||||||
|
read_from_buffer(rec->tbuf_idx, temp_rec, sizeof(TraceRecord));
|
||||||
|
smp_wmb(); /* write barrier before marking as valid */
|
||||||
|
record->event |= TRACE_RECORD_VALID;
|
||||||
|
write_to_buffer(rec->tbuf_idx, temp_rec, sizeof(TraceRecord));
|
||||||
|
|
||||||
|
if ((trace_idx - writeout_idx) > TRACE_BUF_FLUSH_THRESHOLD) {
|
||||||
flush_trace_file(false);
|
flush_trace_file(false);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
void trace0(TraceEventID event)
|
|
||||||
{
|
|
||||||
trace(event, 0, 0, 0, 0, 0, 0);
|
|
||||||
}
|
|
||||||
|
|
||||||
void trace1(TraceEventID event, uint64_t x1)
|
|
||||||
{
|
|
||||||
trace(event, x1, 0, 0, 0, 0, 0);
|
|
||||||
}
|
|
||||||
|
|
||||||
void trace2(TraceEventID event, uint64_t x1, uint64_t x2)
|
|
||||||
{
|
|
||||||
trace(event, x1, x2, 0, 0, 0, 0);
|
|
||||||
}
|
|
||||||
|
|
||||||
void trace3(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3)
|
|
||||||
{
|
|
||||||
trace(event, x1, x2, x3, 0, 0, 0);
|
|
||||||
}
|
|
||||||
|
|
||||||
void trace4(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4)
|
|
||||||
{
|
|
||||||
trace(event, x1, x2, x3, x4, 0, 0);
|
|
||||||
}
|
|
||||||
|
|
||||||
void trace5(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5)
|
|
||||||
{
|
|
||||||
trace(event, x1, x2, x3, x4, x5, 0);
|
|
||||||
}
|
|
||||||
|
|
||||||
void trace6(TraceEventID event, uint64_t x1, uint64_t x2, uint64_t x3, uint64_t x4, uint64_t x5, uint64_t x6)
|
|
||||||
{
|
|
||||||
trace(event, x1, x2, x3, x4, x5, x6);
|
|
||||||
}
|
|
||||||
|
|
||||||
void st_set_trace_file_enabled(bool enable)
|
void st_set_trace_file_enabled(bool enable)
|
||||||
{
|
{
|
||||||
if (enable == !!trace_fp) {
|
if (enable == !!trace_fp) {
|
||||||
|
@ -231,10 +295,11 @@ void st_set_trace_file_enabled(bool enable)
|
||||||
flush_trace_file(true);
|
flush_trace_file(true);
|
||||||
|
|
||||||
if (enable) {
|
if (enable) {
|
||||||
static const TraceRecord header = {
|
static const TraceRecordHeader header = {
|
||||||
.event = HEADER_EVENT_ID,
|
.header_event_id = HEADER_EVENT_ID,
|
||||||
.timestamp_ns = HEADER_MAGIC,
|
.header_magic = HEADER_MAGIC,
|
||||||
.x1 = HEADER_VERSION,
|
/* Older log readers will check for version at next location */
|
||||||
|
.header_version = HEADER_VERSION,
|
||||||
};
|
};
|
||||||
|
|
||||||
trace_fp = fopen(trace_file_name, "wb");
|
trace_fp = fopen(trace_file_name, "wb");
|
||||||
|
@ -291,24 +356,6 @@ void st_print_trace_file_status(FILE *stream, int (*stream_printf)(FILE *stream,
|
||||||
trace_file_name, trace_fp ? "on" : "off");
|
trace_file_name, trace_fp ? "on" : "off");
|
||||||
}
|
}
|
||||||
|
|
||||||
void st_print_trace(FILE *stream, int (*stream_printf)(FILE *stream, const char *fmt, ...))
|
|
||||||
{
|
|
||||||
unsigned int i;
|
|
||||||
|
|
||||||
for (i = 0; i < TRACE_BUF_LEN; i++) {
|
|
||||||
TraceRecord record;
|
|
||||||
|
|
||||||
if (!get_trace_record(i, &record)) {
|
|
||||||
continue;
|
|
||||||
}
|
|
||||||
stream_printf(stream, "Event %" PRIu64 " : %" PRIx64 " %" PRIx64
|
|
||||||
" %" PRIx64 " %" PRIx64 " %" PRIx64 " %" PRIx64 "\n",
|
|
||||||
record.event, record.x1, record.x2,
|
|
||||||
record.x3, record.x4, record.x5,
|
|
||||||
record.x6);
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
void st_flush_trace_buffer(void)
|
void st_flush_trace_buffer(void)
|
||||||
{
|
{
|
||||||
flush_trace_file(true);
|
flush_trace_file(true);
|
||||||
|
|
|
@ -22,17 +22,41 @@ typedef struct {
|
||||||
bool state;
|
bool state;
|
||||||
} TraceEvent;
|
} 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 *stream, fprintf_function stream_printf);
|
|
||||||
void st_print_trace_file_status(FILE *stream, fprintf_function stream_printf);
|
void st_print_trace_file_status(FILE *stream, fprintf_function stream_printf);
|
||||||
void st_set_trace_file_enabled(bool enable);
|
void st_set_trace_file_enabled(bool enable);
|
||||||
bool st_set_trace_file(const char *file);
|
bool st_set_trace_file(const char *file);
|
||||||
void st_flush_trace_buffer(void);
|
void st_flush_trace_buffer(void);
|
||||||
|
|
||||||
|
typedef struct {
|
||||||
|
unsigned int tbuf_idx;
|
||||||
|
unsigned int next_tbuf_idx;
|
||||||
|
unsigned int rec_off;
|
||||||
|
} TraceBufferRecord;
|
||||||
|
|
||||||
|
/* Note for hackers: Make sure MAX_TRACE_LEN < sizeof(uint32_t) */
|
||||||
|
#define MAX_TRACE_STRLEN 512
|
||||||
|
/**
|
||||||
|
* 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, uint32_t slen);
|
||||||
|
|
||||||
|
/**
|
||||||
|
* Mark a trace record completed
|
||||||
|
*
|
||||||
|
* Don't append any more arguments to the trace record after calling this.
|
||||||
|
*/
|
||||||
|
void trace_record_finish(TraceBufferRecord *rec);
|
||||||
|
|
||||||
#endif /* TRACE_SIMPLE_H */
|
#endif /* TRACE_SIMPLE_H */
|
||||||
|
|
Loading…
Reference in a new issue