Minki/linux
1
0
Fork 1
mirror of https://github.com/torvalds/linux.git synced 2024-09-23 08:23:44 +00:00
Code Issues Packages Projects Releases Wiki Activity

libtraceevent, perf tools: Changes in tep_print_event_* APIs

Browse Source 
Libtraceevent APIs for printing various trace events information are
complicated, there are complex extra parameters. To control the way
event information is printed, the user should call a set of functions in
a specific sequence.

These APIs are reimplemented to provide a more simple interface for
printing event information.

Removed APIs:

 	tep_print_event_task()
	tep_print_event_time()
	tep_print_event_data()
	tep_event_info()
	tep_is_latency_format()
	tep_set_latency_format()
	tep_data_latency_format()
	tep_set_print_raw()

A new API for printing event information is introduced:
   void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
		        struct tep_record *record, const char *fmt, ...);
where "fmt" is a printf-like format string, followed by the event
fields to be printed. Supported fields:
 TEP_PRINT_PID, "%d" - event PID
 TEP_PRINT_CPU, "%d" - event CPU
 TEP_PRINT_COMM, "%s" - event command string
 TEP_PRINT_NAME, "%s" - event name
 TEP_PRINT_LATENCY, "%s" - event latency
 TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
   can be specified as part of this format string:
   "%precision.divisord". Example:
   "%3.1000d" - divide the time by 1000 and print the first 3 digits
   before the dot. Thus, the time stamp "123456000" will be printed as
   "123.456"
 TEP_PRINT_INFO, "%s" - event information.
 TEP_PRINT_INFO_RAW, "%s" - event information, in raw format.

Example:
  tep_print_event(tep, s, record, "%16s-%-5d [%03d] %s %6.1000d %s %s",
		  TEP_PRINT_COMM, TEP_PRINT_PID, TEP_PRINT_CPU,
		  TEP_PRINT_LATENCY, TEP_PRINT_TIME, TEP_PRINT_NAME, TEP_PRINT_INFO);
Output:
	ls-11314 [005] d.h. 185207.366383 function __wake_up

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: linux-trace-devel@vger.kernel.org
Cc: Patrick McLean <chutzpah@gentoo.org>
Link: http://lore.kernel.org/linux-trace-devel/20190801074959.22023-2-tz.stoyanov@gmail.com
Link: http://lore.kernel.org/lkml/20190805204355.041132030@goodmis.org
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
This commit is contained in:
Tzvetomir Stoyanov 2019-08-05 16:43:13 -04:00 committed by Arnaldo Carvalho de Melo
parent 4cb3c6d546
commit 38847db974
7 changed files with 215 additions and 212 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

40
tools/lib/traceevent/event-parse-api.c
View File

@ -302,33 +302,6 @@ void tep_set_local_bigendian(struct tep_handle *tep, enum tep_endian endian)
tep->host_bigendian = endian;
}
/**
* tep_is_latency_format - get if the latency output format is configured
* @tep: a handle to the tep_handle
*
* This returns true if the latency output format is configured
* If @tep is NULL, false is returned.
*/
bool tep_is_latency_format(struct tep_handle *tep)
{
if (tep)
return (tep->latency_format);
return false;
}
/**
* tep_set_latency_format - set the latency output format
* @tep: a handle to the tep_handle
* @lat: non zero for latency output format
*
* This sets the latency output format
*/
void tep_set_latency_format(struct tep_handle *tep, int lat)
{
if (tep)
tep->latency_format = lat;
}
/**
* tep_is_old_format - get if an old kernel is used
* @tep: a handle to the tep_handle
@ -344,19 +317,6 @@ bool tep_is_old_format(struct tep_handle *tep)
return false;
}
/**
* tep_set_print_raw - set a flag to force print in raw format
* @tep: a handle to the tep_handle
* @print_raw: the new value of the print_raw flag
*
* This sets a flag to force print in raw format
*/
void tep_set_print_raw(struct tep_handle *tep, int print_raw)
{
if (tep)
tep->print_raw = print_raw;
}
/**
* tep_set_test_filters - set a flag to test a filter string
* @tep: a handle to the tep_handle

4
tools/lib/traceevent/event-parse-local.h
View File

@ -28,8 +28,6 @@ struct tep_handle {
enum tep_endian file_bigendian;
enum tep_endian host_bigendian;
int latency_format;
int old_format;
int cpus;
@ -70,8 +68,6 @@ struct tep_handle {
int ld_offset;
int ld_size;
int print_raw;
int test_filters;
int flags;

346
tools/lib/traceevent/event-parse.c
View File

@ -5212,24 +5212,20 @@ out_failed:
}
}
/**
* tep_data_latency_format - parse the data for the latency format
* @tep: a handle to the trace event parser context
* @s: the trace_seq to write to
* @record: the record to read from
*
/*
* This parses out the Latency format (interrupts disabled,
* need rescheduling, in hard/soft interrupt, preempt count
* and lock depth) and places it into the trace_seq.
*/
void tep_data_latency_format(struct tep_handle *tep,
struct trace_seq *s, struct tep_record *record)
static void data_latency_format(struct tep_handle *tep, struct trace_seq *s,
char *format, struct tep_record *record)
{
static int check_lock_depth = 1;
static int check_migrate_disable = 1;
static int lock_depth_exists;
static int migrate_disable_exists;
unsigned int lat_flags;
struct trace_seq sq;
unsigned int pc;
int lock_depth = 0;
int migrate_disable = 0;
@ -5237,6 +5233,7 @@ void tep_data_latency_format(struct tep_handle *tep,
int softirq;
void *data = record->data;
trace_seq_init(&sq);
lat_flags = parse_common_flags(tep, data);
pc = parse_common_pc(tep, data);
/* lock_depth may not always exist */
@ -5264,7 +5261,7 @@ void tep_data_latency_format(struct tep_handle *tep,
hardirq = lat_flags & TRACE_FLAG_HARDIRQ;
softirq = lat_flags & TRACE_FLAG_SOFTIRQ;
trace_seq_printf(s, "%c%c%c",
trace_seq_printf(&sq, "%c%c%c",
(lat_flags & TRACE_FLAG_IRQS_OFF) ? 'd' :
(lat_flags & TRACE_FLAG_IRQS_NOSUPPORT) ?
'X' : '.',
@ -5274,24 +5271,32 @@ void tep_data_latency_format(struct tep_handle *tep,
hardirq ? 'h' : softirq ? 's' : '.');
if (pc)
trace_seq_printf(s, "%x", pc);
trace_seq_printf(&sq, "%x", pc);
else
trace_seq_putc(s, '.');
trace_seq_printf(&sq, ".");
if (migrate_disable_exists) {
if (migrate_disable < 0)
trace_seq_putc(s, '.');
trace_seq_printf(&sq, ".");
else
trace_seq_printf(s, "%d", migrate_disable);
trace_seq_printf(&sq, "%d", migrate_disable);
}
if (lock_depth_exists) {
if (lock_depth < 0)
trace_seq_putc(s, '.');
trace_seq_printf(&sq, ".");
else
trace_seq_printf(s, "%d", lock_depth);
trace_seq_printf(&sq, "%d", lock_depth);
}
if (sq.state == TRACE_SEQ__MEM_ALLOC_FAILED) {
s->state = TRACE_SEQ__MEM_ALLOC_FAILED;
return;
}
trace_seq_terminate(&sq);
trace_seq_puts(s, sq.buffer);
trace_seq_destroy(&sq);
trace_seq_terminate(s);
}
@ -5452,21 +5457,16 @@ int tep_cmdline_pid(struct tep_handle *tep, struct tep_cmdline *cmdline)
return cmdline->pid;
}
/**
* tep_event_info - parse the data into the print format
* @s: the trace_seq to write to
* @event: the handle to the event
* @record: the record to read from
*
/*
* This parses the raw @data using the given @event information and
* writes the print format into the trace_seq.
*/
void tep_event_info(struct trace_seq *s, struct tep_event *event,
struct tep_record *record)
static void print_event_info(struct trace_seq *s, char *format, bool raw,
struct tep_event *event, struct tep_record *record)
{
int print_pretty = 1;
if (event->tep->print_raw || (event->flags & TEP_EVENT_FL_PRINTRAW))
if (raw || (event->flags & TEP_EVENT_FL_PRINTRAW))
tep_print_fields(s, record->data, record->size, event);
else {
@ -5481,20 +5481,6 @@ void tep_event_info(struct trace_seq *s, struct tep_event *event,
trace_seq_terminate(s);
}
static bool is_timestamp_in_us(char *trace_clock, bool use_trace_clock)
{
if (!trace_clock || !use_trace_clock)
return true;
if (!strcmp(trace_clock, "local") || !strcmp(trace_clock, "global")
|| !strcmp(trace_clock, "uptime") || !strcmp(trace_clock, "perf")
|| !strncmp(trace_clock, "mono", 4))
return true;
/* trace_clock is setting in tsc or counter mode */
return false;
}
/**
* tep_find_event_by_record - return the event from a given record
* @tep: a handle to the trace event parser context
@ -5518,129 +5504,195 @@ tep_find_event_by_record(struct tep_handle *tep, struct tep_record *record)
return tep_find_event(tep, type);
}
/**
* tep_print_event_task - Write the event task comm, pid and CPU
* @tep: a handle to the trace event parser context
* @s: the trace_seq to write to
* @event: the handle to the record's event
* @record: The record to get the event from
*
* Writes the tasks comm, pid and CPU to @s.
/*
* Writes the timestamp of the record into @s. Time divisor and precision can be
* specified as part of printf @format string. Example:
* "%3.1000d" - divide the time by 1000 and print the first 3 digits
* before the dot. Thus, the timestamp "123456000" will be printed as
* "123.456"
*/
void tep_print_event_task(struct tep_handle *tep, struct trace_seq *s,
struct tep_event *event,
struct tep_record *record)
static void print_event_time(struct tep_handle *tep, struct trace_seq *s,
char *format, struct tep_event *event,
struct tep_record *record)
{
unsigned long long time;
char *divstr;
int prec = 0, pr;
int div = 0;
int p10 = 1;
if (isdigit(*(format + 1)))
prec = atoi(format + 1);
divstr = strchr(format, '.');
if (divstr && isdigit(*(divstr + 1)))
div = atoi(divstr + 1);
time = record->ts;
if (div)
time /= div;
pr = prec;
while (pr--)
p10 *= 10;
if (p10 > 1 && p10 < time)
trace_seq_printf(s, "%5llu.%0*llu", time / p10, prec, time % p10);
else
trace_seq_printf(s, "%12llu\n", time);
}
struct print_event_type {
enum {
EVENT_TYPE_INT = 1,
EVENT_TYPE_STRING,
EVENT_TYPE_UNKNOWN,
} type;
char format[32];
};
static void print_string(struct tep_handle *tep, struct trace_seq *s,
struct tep_record *record, struct tep_event *event,
const char *arg, struct print_event_type *type)
{
void *data = record->data;
const char *comm;
int pid;
pid = parse_common_pid(tep, data);
comm = find_cmdline(tep, pid);
if (tep->latency_format)
trace_seq_printf(s, "%8.8s-%-5d %3d", comm, pid, record->cpu);
else
trace_seq_printf(s, "%16s-%-5d [%03d]", comm, pid, record->cpu);
}
/**
* tep_print_event_time - Write the event timestamp
* @tep: a handle to the trace event parser context
* @s: the trace_seq to write to
* @event: the handle to the record's event
* @record: The record to get the event from
* @use_trace_clock: Set to parse according to the @tep->trace_clock
*
* Writes the timestamp of the record into @s.
*/
void tep_print_event_time(struct tep_handle *tep, struct trace_seq *s,
struct tep_event *event,
struct tep_record *record,
bool use_trace_clock)
{
unsigned long secs;
unsigned long usecs;
unsigned long nsecs;
int p;
bool use_usec_format;
use_usec_format = is_timestamp_in_us(tep->trace_clock, use_trace_clock);
if (use_usec_format) {
secs = record->ts / NSEC_PER_SEC;
nsecs = record->ts - secs * NSEC_PER_SEC;
if (strncmp(arg, TEP_PRINT_LATENCY, strlen(TEP_PRINT_LATENCY)) == 0) {
data_latency_format(tep, s, type->format, record);
} else if (strncmp(arg, TEP_PRINT_COMM, strlen(TEP_PRINT_COMM)) == 0) {
pid = parse_common_pid(tep, record->data);
comm = find_cmdline(tep, pid);
trace_seq_printf(s, type->format, comm);
} else if (strncmp(arg, TEP_PRINT_INFO_RAW, strlen(TEP_PRINT_INFO_RAW)) == 0) {
print_event_info(s, type->format, true, event, record);
} else if (strncmp(arg, TEP_PRINT_INFO, strlen(TEP_PRINT_INFO)) == 0) {
print_event_info(s, type->format, false, event, record);
} else if (strncmp(arg, TEP_PRINT_NAME, strlen(TEP_PRINT_NAME)) == 0) {
trace_seq_printf(s, type->format, event->name);
} else {
trace_seq_printf(s, "[UNKNOWN TEP TYPE %s]", arg);
}
if (tep->latency_format) {
tep_data_latency_format(tep, s, record);
}
if (use_usec_format) {
if (tep->flags & TEP_NSEC_OUTPUT) {
usecs = nsecs;
p = 9;
} else {
usecs = (nsecs + 500) / NSEC_PER_USEC;
/* To avoid usecs larger than 1 sec */
if (usecs >= USEC_PER_SEC) {
usecs -= USEC_PER_SEC;
secs++;
}
p = 6;
}
trace_seq_printf(s, " %5lu.%0*lu:", secs, p, usecs);
} else
trace_seq_printf(s, " %12llu:", record->ts);
}
/**
* tep_print_event_data - Write the event data section
* @tep: a handle to the trace event parser context
* @s: the trace_seq to write to
* @event: the handle to the record's event
* @record: The record to get the event from
*
* Writes the parsing of the record's data to @s.
*/
void tep_print_event_data(struct tep_handle *tep, struct trace_seq *s,
struct tep_event *event,
struct tep_record *record)
static void print_int(struct tep_handle *tep, struct trace_seq *s,
struct tep_record *record, struct tep_event *event,
int arg, struct print_event_type *type)
{
static const char *spaces = " "; /* 20 spaces */
int len;
int param;
trace_seq_printf(s, " %s: ", event->name);
/* Space out the event names evenly. */
len = strlen(event->name);
if (len < 20)
trace_seq_printf(s, "%.*s", 20 - len, spaces);
tep_event_info(s, event, record);
}
void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
struct tep_record *record, bool use_trace_clock)
{
struct tep_event *event;
event = tep_find_event_by_record(tep, record);
if (!event) {
int i;
int type = trace_parse_common_type(tep, record->data);
do_warning("ug! no event found for type %d", type);
trace_seq_printf(s, "[UNKNOWN TYPE %d]", type);
for (i = 0; i < record->size; i++)
trace_seq_printf(s, " %02x",
((unsigned char *)record->data)[i]);
switch (arg) {
case TEP_PRINT_CPU:
param = record->cpu;
break;
case TEP_PRINT_PID:
param = parse_common_pid(tep, record->data);
break;
case TEP_PRINT_TIME:
return print_event_time(tep, s, type->format, event, record);
default:
return;
}
trace_seq_printf(s, type->format, param);
}
tep_print_event_task(tep, s, event, record);
tep_print_event_time(tep, s, event, record, use_trace_clock);
tep_print_event_data(tep, s, event, record);
static int tep_print_event_param_type(char *format,
struct print_event_type *type)
{
char *str = format + 1;
int i = 1;
type->type = EVENT_TYPE_UNKNOWN;
while (*str) {
switch (*str) {
case 'd':
case 'u':
case 'i':
case 'x':
case 'X':
case 'o':
type->type = EVENT_TYPE_INT;
break;
case 's':
type->type = EVENT_TYPE_STRING;
break;
}
str++;
i++;
if (type->type != EVENT_TYPE_UNKNOWN)
break;
}
memset(type->format, 0, 32);
memcpy(type->format, format, i < 32 ? i : 31);
return i;
}
/**
* tep_print_event - Write various event information
* @tep: a handle to the trace event parser context
* @s: the trace_seq to write to
* @record: The record to get the event from
* @format: a printf format string. Supported event fileds:
* TEP_PRINT_PID, "%d" - event PID
* TEP_PRINT_CPU, "%d" - event CPU
* TEP_PRINT_COMM, "%s" - event command string
* TEP_PRINT_NAME, "%s" - event name
* TEP_PRINT_LATENCY, "%s" - event latency
* TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
* can be specified as part of this format string:
* "%precision.divisord". Example:
* "%3.1000d" - divide the time by 1000 and print the first
* 3 digits before the dot. Thus, the time stamp
* "123456000" will be printed as "123.456"
* TEP_PRINT_INFO, "%s" - event information. If any width is specified in
* the format string, the event information will be printed
* in raw format.
* Writes the specified event information into @s.
*/
void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
struct tep_record *record, const char *fmt, ...)
{
struct print_event_type type;
char *format = strdup(fmt);
char *current = format;
char *str = format;
int offset;
va_list args;
struct tep_event *event;
if (!format)
return;
event = tep_find_event_by_record(tep, record);
va_start(args, fmt);
while (*current) {
current = strchr(str, '%');
if (!current) {
trace_seq_puts(s, str);
break;
}
memset(&type, 0, sizeof(type));
offset = tep_print_event_param_type(current, &type);
*current = '\0';
trace_seq_puts(s, str);
current += offset;
switch (type.type) {
case EVENT_TYPE_STRING:
print_string(tep, s, record, event,
va_arg(args, char*), &type);
break;
case EVENT_TYPE_INT:
print_int(tep, s, record, event,
va_arg(args, int), &type);
break;
case EVENT_TYPE_UNKNOWN:
default:
trace_seq_printf(s, "[UNKNOWN TYPE]");
break;
}
str = current;
}
va_end(args);
free(format);
}
static int events_id_cmp(const void *a, const void *b)

29
tools/lib/traceevent/event-parse.h
View File

@ -442,18 +442,18 @@ int tep_register_print_string(struct tep_handle *tep, const char *fmt,
unsigned long long addr);
bool tep_is_pid_registered(struct tep_handle *tep, int pid);
void tep_print_event_task(struct tep_handle *tep, struct trace_seq *s,
struct tep_event *event,
struct tep_record *record);
void tep_print_event_time(struct tep_handle *tep, struct trace_seq *s,
struct tep_event *event,
struct tep_record *record,
bool use_trace_clock);
void tep_print_event_data(struct tep_handle *tep, struct trace_seq *s,
struct tep_event *event,
struct tep_record *record);
#define TEP_PRINT_INFO "INFO"
#define TEP_PRINT_INFO_RAW "INFO_RAW"
#define TEP_PRINT_COMM "COMM"
#define TEP_PRINT_LATENCY "LATENCY"
#define TEP_PRINT_NAME "NAME"
#define TEP_PRINT_PID 1U
#define TEP_PRINT_TIME 2U
#define TEP_PRINT_CPU 3U
void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
struct tep_record *record, bool use_trace_clock);
struct tep_record *record, const char *fmt, ...)
__attribute__ ((format (printf, 4, 5)));
int tep_parse_header_page(struct tep_handle *tep, char *buf, unsigned long size,
int long_size);
@ -525,8 +525,6 @@ tep_find_event_by_name(struct tep_handle *tep, const char *sys, const char *name
struct tep_event *
tep_find_event_by_record(struct tep_handle *tep, struct tep_record *record);
void tep_data_latency_format(struct tep_handle *tep,
struct trace_seq *s, struct tep_record *record);
int tep_data_type(struct tep_handle *tep, struct tep_record *rec);
int tep_data_pid(struct tep_handle *tep, struct tep_record *rec);
int tep_data_preempt_count(struct tep_handle *tep, struct tep_record *rec);
@ -541,8 +539,6 @@ void tep_print_field(struct trace_seq *s, void *data,
struct tep_format_field *field);
void tep_print_fields(struct trace_seq *s, void *data,
int size __maybe_unused, struct tep_event *event);
void tep_event_info(struct trace_seq *s, struct tep_event *event,
struct tep_record *record);
int tep_strerror(struct tep_handle *tep, enum tep_errno errnum,
char *buf, size_t buflen);
@ -566,12 +562,9 @@ bool tep_is_file_bigendian(struct tep_handle *tep);
void tep_set_file_bigendian(struct tep_handle *tep, enum tep_endian endian);
bool tep_is_local_bigendian(struct tep_handle *tep);
void tep_set_local_bigendian(struct tep_handle *tep, enum tep_endian endian);
bool tep_is_latency_format(struct tep_handle *tep);
void tep_set_latency_format(struct tep_handle *tep, int lat);
int tep_get_header_page_size(struct tep_handle *tep);
int tep_get_header_timestamp_size(struct tep_handle *tep);
bool tep_is_old_format(struct tep_handle *tep);
void tep_set_print_raw(struct tep_handle *tep, int print_raw);
void tep_set_test_filters(struct tep_handle *tep, int test_filters);
struct tep_handle *tep_alloc(void);

3
tools/perf/builtin-kmem.c
View File

@ -750,7 +750,8 @@ static int parse_gfp_flags(struct evsel *evsel, struct perf_sample *sample,
}
trace_seq_init(&seq);
tep_event_info(&seq, evsel->tp_format, &record);
tep_print_event(evsel->tp_format->tep,
&seq, &record, "%s", TEP_PRINT_INFO);
str = strtok_r(seq.buffer, " ", &pos);
while (str) {

3
tools/perf/util/sort.c
View File

@ -709,7 +709,8 @@ static char *get_trace_output(struct hist_entry *he)
tep_print_fields(&seq, he->raw_data, he->raw_size,
evsel->tp_format);
} else {
tep_event_info(&seq, evsel->tp_format, &rec);
tep_print_event(evsel->tp_format->tep,
&seq, &rec, "%s", TEP_PRINT_INFO);
}
/*
* Trim the buffer, it starts at 4KB and we're not going to

2
tools/perf/util/trace-event-parse.c
View File

@ -109,7 +109,7 @@ void event_format__fprintf(struct tep_event *event,
record.data = data;
trace_seq_init(&s);
tep_event_info(&s, event, &record);
tep_print_event(event->tep, &s, &record, "%s", TEP_PRINT_INFO);
trace_seq_do_fprintf(&s, fp);
trace_seq_destroy(&s);
}