mirror of
https://gitlab.com/qemu-project/qemu
synced 2024-09-06 18:05:37 +00:00
trace: emit name <-> ID mapping in simpletrace header
Currently simpletrace assumes that events are given IDs starting from 0, based on the order in which they appear in the trace-events file, with no gaps. When the trace-events file is split up, this assumption becomes problematic. To deal with this, extend the simpletrace format so that it outputs a table of event name <-> ID mappings. That will allow QEMU to assign arbitrary IDs to events without breaking simpletrace parsing. The v3 simple trace format was FILE HEADER EVENT TRACE RECORD 0 EVENT TRACE RECORD 1 ... EVENT TRACE RECORD N The v4 simple trace format is now FILE HEADER EVENT MAPPING RECORD 0 EVENT MAPPING RECORD 1 ... EVENT MAPPING RECORD M EVENT TRACE RECORD RECORD 0 EVENT TRACE RECORD RECORD 1 ... EVENT TRACE RECORD N Although this shows all the mapping records being emitted upfront, this is not required by the format. While the main simpletrace backend will emit all mappings at startup, the systemtap simpletrace.stp script will emit the mappings at first use. eg FILE HEADER ... EVENT MAPPING RECORD 0 EVENT TRACE RECORD RECORD 0 EVENT TRACE RECORD RECORD 1 EVENT MAPPING RECORD 1 EVENT TRACE RECORD RECORD 2 ... EVENT TRACE RECORD N This is more space efficient given that most trace records only include a subset of events. In modifying the systemtap simpletrace code, a 'begin' probe was added to emit the trace event header, so you no longer need to add '--no-header' when running simpletrace.py for systemtap generated trace files. Signed-off-by: Daniel P. Berrange <berrange@redhat.com> Message-id: 1475588159-30598-12-git-send-email-berrange@redhat.com Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
This commit is contained in:
parent
ef4c9fc854
commit
7f1b588f20
|
@ -19,6 +19,9 @@
|
||||||
header_magic = 0xf2b177cb0aa429b4
|
header_magic = 0xf2b177cb0aa429b4
|
||||||
dropped_event_id = 0xfffffffffffffffe
|
dropped_event_id = 0xfffffffffffffffe
|
||||||
|
|
||||||
|
record_type_mapping = 0
|
||||||
|
record_type_event = 1
|
||||||
|
|
||||||
log_header_fmt = '=QQQ'
|
log_header_fmt = '=QQQ'
|
||||||
rec_header_fmt = '=QQII'
|
rec_header_fmt = '=QQII'
|
||||||
|
|
||||||
|
@ -30,14 +33,16 @@ def read_header(fobj, hfmt):
|
||||||
return None
|
return None
|
||||||
return struct.unpack(hfmt, hdr)
|
return struct.unpack(hfmt, hdr)
|
||||||
|
|
||||||
def get_record(edict, rechdr, fobj):
|
def get_record(edict, idtoname, rechdr, fobj):
|
||||||
"""Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
|
"""Deserialize a trace record from a file into a tuple
|
||||||
|
(name, timestamp, pid, arg1, ..., arg6)."""
|
||||||
if rechdr is None:
|
if rechdr is None:
|
||||||
return None
|
return None
|
||||||
rec = (rechdr[0], rechdr[1], rechdr[3])
|
|
||||||
if rechdr[0] != dropped_event_id:
|
if rechdr[0] != dropped_event_id:
|
||||||
event_id = rechdr[0]
|
event_id = rechdr[0]
|
||||||
event = edict[event_id]
|
name = idtoname[event_id]
|
||||||
|
rec = (name, rechdr[1], rechdr[3])
|
||||||
|
event = edict[name]
|
||||||
for type, name in event.args:
|
for type, name in event.args:
|
||||||
if is_string(type):
|
if is_string(type):
|
||||||
l = fobj.read(4)
|
l = fobj.read(4)
|
||||||
|
@ -48,15 +53,22 @@ def get_record(edict, rechdr, fobj):
|
||||||
(value,) = struct.unpack('=Q', fobj.read(8))
|
(value,) = struct.unpack('=Q', fobj.read(8))
|
||||||
rec = rec + (value,)
|
rec = rec + (value,)
|
||||||
else:
|
else:
|
||||||
|
rec = ("dropped", rechdr[1], rechdr[3])
|
||||||
(value,) = struct.unpack('=Q', fobj.read(8))
|
(value,) = struct.unpack('=Q', fobj.read(8))
|
||||||
rec = rec + (value,)
|
rec = rec + (value,)
|
||||||
return rec
|
return rec
|
||||||
|
|
||||||
|
def get_mapping(fobj):
|
||||||
|
(event_id, ) = struct.unpack('=Q', fobj.read(8))
|
||||||
|
(len, ) = struct.unpack('=L', fobj.read(4))
|
||||||
|
name = fobj.read(len)
|
||||||
|
|
||||||
def read_record(edict, fobj):
|
return (event_id, name)
|
||||||
|
|
||||||
|
def read_record(edict, idtoname, fobj):
|
||||||
"""Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
|
"""Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
|
||||||
rechdr = read_header(fobj, rec_header_fmt)
|
rechdr = read_header(fobj, rec_header_fmt)
|
||||||
return get_record(edict, rechdr, fobj) # return tuple of record elements
|
return get_record(edict, idtoname, rechdr, fobj)
|
||||||
|
|
||||||
def read_trace_header(fobj):
|
def read_trace_header(fobj):
|
||||||
"""Read and verify trace file header"""
|
"""Read and verify trace file header"""
|
||||||
|
@ -67,20 +79,30 @@ def read_trace_header(fobj):
|
||||||
raise ValueError('Not a valid trace file!')
|
raise ValueError('Not a valid trace file!')
|
||||||
|
|
||||||
log_version = header[2]
|
log_version = header[2]
|
||||||
if log_version not in [0, 2, 3]:
|
if log_version not in [0, 2, 3, 4]:
|
||||||
raise ValueError('Unknown version of tracelog format!')
|
raise ValueError('Unknown version of tracelog format!')
|
||||||
if log_version != 3:
|
if log_version != 4:
|
||||||
raise ValueError('Log format %d not supported with this QEMU release!'
|
raise ValueError('Log format %d not supported with this QEMU release!'
|
||||||
% log_version)
|
% log_version)
|
||||||
|
|
||||||
def read_trace_records(edict, fobj):
|
def read_trace_records(edict, fobj):
|
||||||
"""Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6)."""
|
"""Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6)."""
|
||||||
|
idtoname = {
|
||||||
|
dropped_event_id: "dropped"
|
||||||
|
}
|
||||||
while True:
|
while True:
|
||||||
rec = read_record(edict, fobj)
|
t = fobj.read(8)
|
||||||
if rec is None:
|
if len(t) == 0:
|
||||||
break
|
break
|
||||||
|
|
||||||
yield rec
|
(rectype, ) = struct.unpack('=Q', t)
|
||||||
|
if rectype == record_type_mapping:
|
||||||
|
event_id, name = get_mapping(fobj)
|
||||||
|
idtoname[event_id] = name
|
||||||
|
else:
|
||||||
|
rec = read_record(edict, idtoname, fobj)
|
||||||
|
|
||||||
|
yield rec
|
||||||
|
|
||||||
class Analyzer(object):
|
class Analyzer(object):
|
||||||
"""A trace file analyzer which processes trace records.
|
"""A trace file analyzer which processes trace records.
|
||||||
|
@ -115,10 +137,10 @@ def process(events, log, analyzer, read_header=True):
|
||||||
read_trace_header(log)
|
read_trace_header(log)
|
||||||
|
|
||||||
dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
|
dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
|
||||||
edict = {dropped_event_id: dropped_event}
|
edict = {"dropped": dropped_event}
|
||||||
|
|
||||||
for num, event in enumerate(events):
|
for event in events:
|
||||||
edict[num] = event
|
edict[event.name] = event
|
||||||
|
|
||||||
def build_fn(analyzer, event):
|
def build_fn(analyzer, event):
|
||||||
if isinstance(event, str):
|
if isinstance(event, str):
|
||||||
|
|
|
@ -21,6 +21,25 @@
|
||||||
|
|
||||||
def generate(events, backend):
|
def generate(events, backend):
|
||||||
out('/* This file is autogenerated by tracetool, do not edit. */',
|
out('/* This file is autogenerated by tracetool, do not edit. */',
|
||||||
|
'',
|
||||||
|
'global event_name_to_id_map',
|
||||||
|
'global event_next_id',
|
||||||
|
'function simple_trace_map_event(name)',
|
||||||
|
'',
|
||||||
|
'{',
|
||||||
|
' if (!([name] in event_name_to_id_map)) {',
|
||||||
|
' event_name_to_id_map[name] = event_next_id',
|
||||||
|
' name_len = strlen(name)',
|
||||||
|
' printf("%%8b%%8b%%4b%%.*s", 0, ',
|
||||||
|
' event_next_id, name_len, name_len, name)',
|
||||||
|
' event_next_id = event_next_id + 1',
|
||||||
|
' }',
|
||||||
|
' return event_name_to_id_map[name]',
|
||||||
|
'}',
|
||||||
|
'probe begin',
|
||||||
|
'{',
|
||||||
|
' printf("%%8b%%8b%%8b", 0xffffffffffffffff, 0xf2b177cb0aa429b4, 4)',
|
||||||
|
'}',
|
||||||
'')
|
'')
|
||||||
|
|
||||||
for event_id, e in enumerate(events):
|
for event_id, e in enumerate(events):
|
||||||
|
@ -29,6 +48,7 @@ def generate(events, backend):
|
||||||
|
|
||||||
out('probe %(probeprefix)s.simpletrace.%(name)s = %(probeprefix)s.%(name)s ?',
|
out('probe %(probeprefix)s.simpletrace.%(name)s = %(probeprefix)s.%(name)s ?',
|
||||||
'{',
|
'{',
|
||||||
|
' id = simple_trace_map_event("%(name)s")',
|
||||||
probeprefix=probeprefix(),
|
probeprefix=probeprefix(),
|
||||||
name=e.name)
|
name=e.name)
|
||||||
|
|
||||||
|
@ -48,7 +68,7 @@ def generate(events, backend):
|
||||||
sizestr = ' + '.join(sizes)
|
sizestr = ' + '.join(sizes)
|
||||||
|
|
||||||
# Generate format string and value pairs for record header and arguments
|
# Generate format string and value pairs for record header and arguments
|
||||||
fields = [('8b', str(event_id)),
|
fields = [('8b', 'id'),
|
||||||
('8b', 'gettimeofday_ns()'),
|
('8b', 'gettimeofday_ns()'),
|
||||||
('4b', sizestr),
|
('4b', sizestr),
|
||||||
('4b', 'pid()')]
|
('4b', 'pid()')]
|
||||||
|
@ -63,7 +83,7 @@ def generate(events, backend):
|
||||||
# Emit the entire record in a single SystemTap printf()
|
# Emit the entire record in a single SystemTap printf()
|
||||||
fmt_str = '%'.join(fmt for fmt, _ in fields)
|
fmt_str = '%'.join(fmt for fmt, _ in fields)
|
||||||
arg_str = ', '.join(arg for _, arg in fields)
|
arg_str = ', '.join(arg for _, arg in fields)
|
||||||
out(' printf("%%%(fmt_str)s", %(arg_str)s)',
|
out(' printf("%%8b%%%(fmt_str)s", 1, %(arg_str)s)',
|
||||||
fmt_str=fmt_str, arg_str=arg_str)
|
fmt_str=fmt_str, arg_str=arg_str)
|
||||||
|
|
||||||
out('}')
|
out('}')
|
||||||
|
|
|
@ -24,7 +24,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 3
|
#define HEADER_VERSION 4
|
||||||
|
|
||||||
/** 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)
|
||||||
|
@ -56,6 +56,9 @@ static uint32_t trace_pid;
|
||||||
static FILE *trace_fp;
|
static FILE *trace_fp;
|
||||||
static char *trace_file_name;
|
static char *trace_file_name;
|
||||||
|
|
||||||
|
#define TRACE_RECORD_TYPE_MAPPING 0
|
||||||
|
#define TRACE_RECORD_TYPE_EVENT 1
|
||||||
|
|
||||||
/* * Trace buffer entry */
|
/* * Trace buffer entry */
|
||||||
typedef struct {
|
typedef struct {
|
||||||
uint64_t event; /* event ID value */
|
uint64_t event; /* event ID value */
|
||||||
|
@ -160,6 +163,7 @@ static gpointer writeout_thread(gpointer opaque)
|
||||||
unsigned int idx = 0;
|
unsigned int idx = 0;
|
||||||
int dropped_count;
|
int dropped_count;
|
||||||
size_t unused __attribute__ ((unused));
|
size_t unused __attribute__ ((unused));
|
||||||
|
uint64_t type = TRACE_RECORD_TYPE_EVENT;
|
||||||
|
|
||||||
for (;;) {
|
for (;;) {
|
||||||
wait_for_trace_records_available();
|
wait_for_trace_records_available();
|
||||||
|
@ -174,10 +178,12 @@ static gpointer writeout_thread(gpointer opaque)
|
||||||
} while (!g_atomic_int_compare_and_exchange(&dropped_events,
|
} while (!g_atomic_int_compare_and_exchange(&dropped_events,
|
||||||
dropped_count, 0));
|
dropped_count, 0));
|
||||||
dropped.rec.arguments[0] = dropped_count;
|
dropped.rec.arguments[0] = dropped_count;
|
||||||
|
unused = fwrite(&type, sizeof(type), 1, trace_fp);
|
||||||
unused = fwrite(&dropped.rec, dropped.rec.length, 1, trace_fp);
|
unused = fwrite(&dropped.rec, dropped.rec.length, 1, trace_fp);
|
||||||
}
|
}
|
||||||
|
|
||||||
while (get_trace_record(idx, &recordptr)) {
|
while (get_trace_record(idx, &recordptr)) {
|
||||||
|
unused = fwrite(&type, sizeof(type), 1, trace_fp);
|
||||||
unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
|
unused = fwrite(recordptr, recordptr->length, 1, trace_fp);
|
||||||
writeout_idx += recordptr->length;
|
writeout_idx += recordptr->length;
|
||||||
free(recordptr); /* don't use g_free, can deadlock when traced */
|
free(recordptr); /* don't use g_free, can deadlock when traced */
|
||||||
|
@ -273,6 +279,28 @@ void trace_record_finish(TraceBufferRecord *rec)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
static int st_write_event_mapping(void)
|
||||||
|
{
|
||||||
|
uint64_t type = TRACE_RECORD_TYPE_MAPPING;
|
||||||
|
TraceEventIter iter;
|
||||||
|
TraceEvent *ev;
|
||||||
|
|
||||||
|
trace_event_iter_init(&iter, NULL);
|
||||||
|
while ((ev = trace_event_iter_next(&iter)) != NULL) {
|
||||||
|
uint64_t id = trace_event_get_id(ev);
|
||||||
|
const char *name = trace_event_get_name(ev);
|
||||||
|
uint32_t len = strlen(name);
|
||||||
|
if (fwrite(&type, sizeof(type), 1, trace_fp) != 1 ||
|
||||||
|
fwrite(&id, sizeof(id), 1, trace_fp) != 1 ||
|
||||||
|
fwrite(&len, sizeof(len), 1, trace_fp) != 1 ||
|
||||||
|
fwrite(name, len, 1, trace_fp) != 1) {
|
||||||
|
return -1;
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
return 0;
|
||||||
|
}
|
||||||
|
|
||||||
void st_set_trace_file_enabled(bool enable)
|
void st_set_trace_file_enabled(bool enable)
|
||||||
{
|
{
|
||||||
if (enable == !!trace_fp) {
|
if (enable == !!trace_fp) {
|
||||||
|
@ -297,7 +325,8 @@ void st_set_trace_file_enabled(bool enable)
|
||||||
return;
|
return;
|
||||||
}
|
}
|
||||||
|
|
||||||
if (fwrite(&header, sizeof header, 1, trace_fp) != 1) {
|
if (fwrite(&header, sizeof header, 1, trace_fp) != 1 ||
|
||||||
|
st_write_event_mapping() < 0) {
|
||||||
fclose(trace_fp);
|
fclose(trace_fp);
|
||||||
trace_fp = NULL;
|
trace_fp = NULL;
|
||||||
return;
|
return;
|
||||||
|
|
Loading…
Reference in a new issue