[Crash-utility] [PATCH] trace: Improve "trace show" command

The code were also applied to: git://github.com/laijs/tracing-extension-module-for-crash.git Documents and man pages will/may be added in two weeks. Dave Anderson, could you add a "Requires" entry to its RPM.spec, it requires trace-cmd RPM after this patch applied. Thanks, Lai Subject: [PATCH] trace: Improve "trace show" command Use trace-cmd to implement "trace show" command and remove the related code. It is not a good idea to maintain another set of code with the same functional. trace-cmd is better and mature. How the new "trace show" works: 1) build trace.dat from the core file and dump it to /tmp. 2) exec "trace-cmd report" upon the trace.dat 3) splice the output of trace-cmd to user and unlink the temp file. Signed-off-by: Lai Jiangshan <laijs(a)cn.fujitsu.com&gt; --- trace.c | 1566 ++-------------------------------------------------------------- 1 file changed, 50 insertions(+), 1516 deletions(-) diff --git a/extensions/trace.c b/extensions/trace.c index 714765e..057459b 100755 --- a/extensions/trace.c +++ b/extensions/trace.c @@ -96,8 +96,6 @@ static const char *current_tracer_name; static void ftrace_destroy_event_types(void); static int ftrace_init_event_types(void); -static int ftrace_show_init(void); -static void ftrace_show_destroy(void); /* at = ((struct *)ptr)->member */ #define read_value(at, ptr, struct, member) \ @@ -489,13 +487,8 @@ static int ftrace_init(void) if (ftrace_init_current_tracer() < 0) goto out_2; - if (ftrace_show_init() < 0) - goto out_3; - return 0; -out_3: - free(current_tracer_name); out_2: ftrace_destroy_event_types(); out_1: @@ -511,7 +504,6 @@ out_0: static void ftrace_destroy(void) { - ftrace_show_destroy(); free(current_tracer_name); ftrace_destroy_event_types(); @@ -611,37 +603,21 @@ out_fail: return -1; } -typedef uint64_t u64; -typedef int64_t s64; -typedef uint32_t u32; - #define MAX_CACHE_ID 256 -struct ftrace_field; -typedef u64 (*access_op)(struct ftrace_field *aop, void *data); -static void ftrace_field_access_init(struct ftrace_field *f); - struct ftrace_field { const char *name; const char *type; - access_op op; int offset; int size; int is_signed; }; -struct event_type; -struct format_context; -typedef void (*event_printer)(struct event_type *t, struct format_context *fc); - - /* SIGH, we cann't get "print fmt" from core-file */ - struct event_type { struct event_type *next; const char *system; const char *name; int plugin; - event_printer printer; const char *print_fmt; int id; int nfields; @@ -655,16 +631,6 @@ static int nr_event_types; static struct ftrace_field *ftrace_common_fields; static int ftrace_common_fields_count; -/* - * TODO: implement event_generic_print_fmt_print() when the print fmt - * in tracing/events/$SYSTEM/$TRACE/format becomes a will-defined - * language. - */ -static void event_generic_print_fmt_print(struct event_type *t, - struct format_context *fc); -static void event_default_print(struct event_type *t, - struct format_context *fc); - static int syscall_get_enter_fields(ulong call, ulong *fields) { static int inited; @@ -887,7 +853,6 @@ static int ftrace_init_event_fields(ulong fields_head, int *pnfields, goto out_fail; } - ftrace_field_access_init(&fields[nfields]); nfields++; /* Advance to the next field */ @@ -1186,7 +1151,6 @@ static int ftrace_init_event_types(void) aevent_type->plugin = 1; else aevent_type->plugin = 0; - aevent_type->printer = event_default_print; /* Add a event type */ event_types[nr_event_types++] = aevent_type; @@ -1212,57 +1176,6 @@ out_fail: return -1; } -static -struct ftrace_field *find_event_field(struct event_type *t, const char *name) -{ - int i; - struct ftrace_field *f; - - for (i = 0; i < ftrace_common_fields_count; i++) { - f = ftrace_common_fields + i; - if (!strcmp(name, f->name)) - return f; - } - - for (i = 0; i < t->nfields; i++) { - f = &t->fields[i]; - if (!strcmp(name, f->name)) - return f; - } - - return NULL; -} - -static struct event_type *find_event_type(int id) -{ - int i; - - if ((unsigned int)id < MAX_CACHE_ID) - return event_type_cache[id]; - - for (i = 0; i < nr_event_types; i++) { - if (event_types[i]->id == id) - return event_types[i]; - } - - return NULL; -} - -static -struct event_type *find_event_type_by_name(const char *system, const char *name) -{ - int i; - - for (i = 0; i < nr_event_types; i++) { - if (system && strcmp(system, event_types[i]->system)) - continue; - if (!strcmp(name, event_types[i]->name)) - return event_types[i]; - } - - return NULL; -} - #define default_common_field_count 5 static int ftrace_dump_event_type(struct event_type *t, const char *path) @@ -1364,381 +1277,6 @@ static int ftrace_dump_event_types(const char *events_path) return 0; } -struct ring_buffer_per_cpu_stream { - struct ring_buffer_per_cpu *cpu_buffer; - void *curr_page; - int curr_page_indx; - - uint64_t ts; - uint32_t *offset; - uint32_t *commit; -}; - -static -int ring_buffer_per_cpu_stream_init(struct ring_buffer_per_cpu *cpu_buffer, - unsigned pages, struct ring_buffer_per_cpu_stream *s) -{ - s->cpu_buffer = cpu_buffer; - s->curr_page = malloc(PAGESIZE()); - if (s->curr_page == NULL) - return -1; - - s->curr_page_indx = -1; - return 0; -} - -static -void ring_buffer_per_cpu_stream_destroy(struct ring_buffer_per_cpu_stream *s) -{ - free(s->curr_page); -} - -struct ftrace_event { - uint64_t ts; - int length; - void *data; -}; - -struct event { - u32 type_len:5, time_delta:27; -}; - -#define RINGBUF_TYPE_PADDING 29 -#define RINGBUF_TYPE_TIME_EXTEND 30 -#define RINGBUF_TYPE_TIME_STAMP 31 -#define RINGBUF_TYPE_DATA 0 ... 28 - -#define sizeof_local_t (sizeof(ulong)) -#define PAGE_HEADER_LEN (8 + sizeof_local_t) - -static -int ring_buffer_per_cpu_stream_get_page(struct ring_buffer_per_cpu_stream *s) -{ - ulong raw_page; - - read_value(raw_page, s->cpu_buffer->linear_pages[s->curr_page_indx], - buffer_page, page); - - if (!readmem(raw_page, KVADDR, s->curr_page, PAGESIZE(), - "get page context", RETURN_ON_ERROR)) - return -1; - - s->ts = *(u64 *)s->curr_page; - s->offset = s->curr_page + PAGE_HEADER_LEN; - s->commit = s->offset + *(ulong *)(s->curr_page + 8) / 4; - - return 0; - -out_fail: - return -1; -} - -static -int ring_buffer_per_cpu_stream_pop_event(struct ring_buffer_per_cpu_stream *s, - struct ftrace_event *res) -{ - struct event *event; - - res->data = NULL; - - if (s->curr_page_indx >= s->cpu_buffer->nr_linear_pages) - return -1; - -again: - if ((s->curr_page_indx == -1) || (s->offset >= s->commit)) { - s->curr_page_indx++; - - if (s->curr_page_indx == s->cpu_buffer->nr_linear_pages) - return -1; - - if (ring_buffer_per_cpu_stream_get_page(s) < 0) { - s->curr_page_indx = s->cpu_buffer->nr_linear_pages; - return -1; - } - - if (s->offset >= s->commit) - goto again; - } - - event = (void *)s->offset; - - switch (event->type_len) { - case RINGBUF_TYPE_PADDING: - if (event->time_delta) - s->offset += 1 + ((*(s->offset + 1) + 3) / 4); - else - s->offset = s->commit; - goto again; - - case RINGBUF_TYPE_TIME_EXTEND: - s->ts +=event->time_delta; - s->ts += ((u64)*(s->offset + 1)) << 27; - s->offset += 2; - goto again; - - case RINGBUF_TYPE_TIME_STAMP: - /* FIXME: not implemented */ - s->offset += 4; - goto again; - - case RINGBUF_TYPE_DATA: - if (!event->type_len) { - res->data = s->offset + 2; - res->length = *(s->offset + 1) - 4; - - s->offset += 1 + ((*(s->offset + 1) + 3) / 4); - } else { - res->data = s->offset + 1; - res->length = event->type_len * 4; - - s->offset += 1 + event->type_len; - } - - if (s->offset > s->commit) { - fprintf(fp, "corrupt\n"); - res->data = NULL; - goto again; - } - - s->ts += event->time_delta; - res->ts = s->ts; - - return 0; - - default:; - } - - return -1; -} - -struct ring_buffer_stream { - struct ring_buffer_per_cpu_stream *ss; - struct ftrace_event *es; - u64 ts; - int popped_cpu; - int pushed; -}; - -static void __rbs_destroy(struct ring_buffer_stream *s, int *cpulist, int nr) -{ - int cpu; - - for (cpu = 0; cpu < nr; cpu++) { - if (!s->ss[cpu].cpu_buffer) - continue; - - ring_buffer_per_cpu_stream_destroy(s->ss + cpu); - } - - free(s->ss); - free(s->es); -} - -static -int ring_buffer_stream_init(struct ring_buffer_stream *s, int *cpulist) -{ - int cpu; - - s->ss = malloc(sizeof(*s->ss) * nr_cpu_ids); - if (s->ss == NULL) - return -1; - - s->es = malloc(sizeof(*s->es) * nr_cpu_ids); - if (s->es == NULL) { - free(s->ss); - return -1; - } - - for (cpu = 0; cpu < nr_cpu_ids; cpu++) { - s->ss[cpu].cpu_buffer = NULL; - s->es[cpu].data = NULL; - - if (!global_buffers[cpu].kaddr) - continue; - - if (cpulist && !cpulist[cpu]) - continue; - - if (ring_buffer_per_cpu_stream_init(global_buffers + cpu, - global_pages, s->ss + cpu) < 0) { - __rbs_destroy(s, cpulist, cpu); - return -1; - } - } - - s->ts = 0; - s->popped_cpu = nr_cpu_ids; - s->pushed = 0; - - return 0; -} - -static -void ring_buffer_stream_destroy(struct ring_buffer_stream *s, int *cpulist) -{ - __rbs_destroy(s, cpulist, nr_cpu_ids); -} - -/* make current event be returned again at next pop */ -static void ring_buffer_stream_push_current_event(struct ring_buffer_stream *s) -{ - if ((s->popped_cpu < 0) || (s->popped_cpu == nr_cpu_ids)) - return; - - s->pushed = 1; -} - -/* return the cpu# of this event */ -static int ring_buffer_stream_pop_event(struct ring_buffer_stream *s, - struct ftrace_event *res) -{ - int cpu, min_cpu = -1; - u64 ts, min_ts; - - res->data = NULL; - - if (s->popped_cpu < 0) - return -1; - - if (s->popped_cpu == nr_cpu_ids) { - for (cpu = 0; cpu < nr_cpu_ids; cpu++) { - if (!s->ss[cpu].cpu_buffer) - continue; - - ring_buffer_per_cpu_stream_pop_event(s->ss + cpu, - s->es + cpu); - - if (s->es[cpu].data == NULL) - continue; - - /* - * We do not have start point of time, - * determine the min_ts with heuristic way. - */ - ts = s->es[cpu].ts; - if (min_cpu < 0 || (s64)(ts - min_ts) < 0) { - min_ts = ts; - min_cpu = cpu; - } - } - - s->pushed = 0; - goto done; - } - - if (s->pushed) { - s->pushed = 0; - *res = s->es[s->popped_cpu]; - return s->popped_cpu; - } - - ring_buffer_per_cpu_stream_pop_event(&s->ss[s->popped_cpu], - &s->es[s->popped_cpu]); - - for (cpu = 0; cpu < nr_cpu_ids; cpu++) { - if (s->es[cpu].data == NULL) - continue; - - /* we have start point of time(s->ts) */ - ts = s->es[cpu].ts - s->ts; - if (min_cpu < 0 || ts < min_ts) { - min_ts = ts; - min_cpu = cpu; - } - } - -done: - s->popped_cpu = min_cpu; - - if (min_cpu < 0) - return -1; - - s->ts = s->es[min_cpu].ts; - *res = s->es[min_cpu]; - - return min_cpu; -} - -static u64 access_error(struct ftrace_field *f, void *data) -{ - return 0; -} - -static u64 access_8(struct ftrace_field *f, void *data) -{ - return *(int8_t *)(data + f->offset); -} - -static u64 access_16(struct ftrace_field *f, void *data) -{ - return *(int16_t *)(data + f->offset); -} - -static u64 access_32(struct ftrace_field *f, void *data) -{ - return *(int32_t *)(data + f->offset); -} - -static u64 access_64(struct ftrace_field *f, void *data) -{ - return *(int64_t *)(data + f->offset); -} - -static u64 access_string_local(struct ftrace_field *f, void *data) -{ - int offset; - - if (f->size == 2) - offset = *(int16_t *)(data + f->offset); - else - offset = *(int32_t *)(data + f->offset) & 0xFFFF; - - return (long)(data + offset); -} - -static u64 access_string(struct ftrace_field *f, void *data) -{ - return (long)(data + f->offset); -} - -static u64 access_other_local(struct ftrace_field *f, void *data) -{ - return access_string_local(f, data); -} - -static u64 access_other(struct ftrace_field *f, void *data) -{ - return (long)(data + f->offset); -} - -static void ftrace_field_access_init(struct ftrace_field *f) -{ - /* guess whether it is string array */ - if (!strncmp(f->type, "__data_loc", sizeof("__data_loc") - 1)) { - if (f->size != 2 && f->size != 4) { - /* kernel side may be changed, need fix here */ - f->op = access_error; - } else if (strstr(f->type, "char")) { - f->op = access_string_local; - } else { - f->op = access_other_local; - } - } else if (strchr(f->type, '[')) { - if (strstr(f->type, "char")) - f->op = access_string; - else - f->op = access_other; - } else { - switch (f->size) { - case 1: f->op = access_8; break; - case 2: f->op = access_16; break; - case 4: f->op = access_32; break; - case 8: f->op = access_64; break; - default: f->op = access_other; break; - } - } -} - static void show_basic_info(void) { fprintf(fp, "current tracer is %s\n", current_tracer_name); @@ -1881,334 +1419,58 @@ static void ftrace_dump(int argc, char *argv[]) } } -static char show_event_buf[4096]; -static int show_event_pos; - -#define INVALID_ACCESS_FIELD 1 -static jmp_buf show_event_env; - -struct format_context { - struct ring_buffer_stream stream; - struct ftrace_event event; - int cpu; -}; - -static struct format_context format_context; - -/* !!!! @event_type and @field_name should be const for every call */ -#define access_field(event_type, data, field_name) \ -({ \ - static struct ftrace_field *__access_field##_field; \ - \ - if (__access_field##_field == NULL) { \ - __access_field##_field = find_event_field(event_type, \ - field_name); \ - } \ - \ - if (__access_field##_field == NULL) { \ - event_type->printer = event_default_print; \ - ring_buffer_stream_push_current_event(&format_context.stream);\ - longjmp(show_event_env, INVALID_ACCESS_FIELD); \ - } \ - \ - __access_field##_field->op(__access_field##_field, data); \ -}) - -static int ftrace_event_get_id(void *data) -{ - return access_field(event_types[0], data, "common_type"); -} - -static int ftrace_event_get_pid(void *data) -{ - return access_field(event_types[0], data, "common_pid"); -} - -#define event_printf(fmt, args...) \ -do { \ - show_event_pos += snprintf(show_event_buf + show_event_pos, \ - sizeof(show_event_buf) - show_event_pos, \ - fmt, ##args); \ -} while (0) - - -static void event_field_print(struct ftrace_field *f, void *data) +static void ftrace_show(int argc, char *argv[]) { - u64 value = f->op(f, data); + char buf[4096]; + char tmp[] = "/tmp/crash.trace_dat.XXXXXX"; + char *trace_cmd = "trace-cmd", *env_trace_cmd = getenv("TRACE_CMD"); + int fd; + FILE *file; + size_t ret; - if (f->op == access_error) { - event_printf("<Error>"); - } else if (f->op == access_8) { - if (f->is_signed) - event_printf("%d", (int8_t)value); - else - event_printf("%u", (uint8_t)value); - } else if (f->op == access_16) { - if (f->is_signed) - event_printf("%d", (int16_t)value); - else - event_printf("%u", (uint16_t)value); - } else if (f->op == access_32) { - if (f->is_signed) - event_printf("%d", (int32_t)value); - else - event_printf("%u", (uint32_t)value); - } else if (f->op == access_64) { - if (f->is_signed) - event_printf("%lld", (long long)value); + /* check trace-cmd */ + if (env_trace_cmd) + trace_cmd = env_trace_cmd; + if (!(file = popen(trace_cmd, "r"))) + return; + ret = fread(buf, 1, sizeof(buf), file); + buf[4097] = 0; + if (!strstr(buf, "trace-cmd version")) { + if (env_trace_cmd) + fprintf(fp, "Invalid environment TRACE_CMD: %s\n", + env_trace_cmd); else - event_printf("%llu", (unsigned long long)value); - } else if (f->op == access_string_local) { - int size = 0; + fprintf(fp, "\"trace show\" requires trace-cmd.\n" + "please set the environment TRACE_CMD " + "if you installed it a special path\n" + ); + return; + } - if (f->size == 4) - size = *(int32_t *)(data + f->offset) >> 16; + /* dump trace.dat to the temp file */ + mktemp(tmp); + fd = open(tmp, O_WRONLY | O_CREAT | O_TRUNC, 0644); + if (trace_cmd_data_output(fd) < 0) + goto out; - if (size) - event_printf("%.*s", size, (char *)(long)value); - else - event_printf("%s", (char *)(long)value); - } else if (f->op == access_string) { - event_printf("%.*s", f->size, (char *)(long)value); - } else if (f->op == access_other) { - /* TODO */ - } else if (f->op == access_other_local) { - /* TODO */ - } else { - /* TODO */ + /* splice the output of trace-cmd to user */ + snprintf(buf, sizeof(buf), "%s report %s", trace_cmd, tmp); + if (!(file = popen(buf, "r"))) + goto out; + for (;;) { + ret = fread(buf, 1, sizeof(buf), file); + if (ret == 0) + break; + fwrite(buf, 1, ret, fp); } + pclose(file); +out: + close(fd); + unlink(tmp); + return; } -static void get_comm_from_pid(int pid, char *comm) -{ - int li, hi; - struct task_context *tc; - - if (pid == 0) { - strcpy(comm, "<swapper>"); - return; - } - - tc = FIRST_CONTEXT(); - - li = 0; - hi = RUNNING_TASKS(); - while (li < hi) { - int mid = (li + hi) / 2; - - if (tc[mid].pid > pid) - hi = mid; - else if (tc[mid].pid < pid) - li = mid + 1; - else { - strcpy(comm, tc[mid].comm); - return; - } - } - - strcpy(comm, "<...>"); -} - -static void event_context_print(struct event_type *t, struct format_context *fc) -{ - u64 time = fc->event.ts / 1000; - ulong sec = time / 1000000; - ulong usec = time % 1000000; - int pid = ftrace_event_get_pid(fc->event.data); - char comm[20]; - - get_comm_from_pid(pid, comm); - event_printf("%16s-%-5d [%03d] %5lu.%06lu: ", - comm, pid, fc->cpu, sec, usec); -} - -static int gopt_context_info; -static int gopt_sym_offset; -static int gopt_sym_addr; - -static int gopt_graph_print_duration; -static int gopt_graph_print_overhead; -static int gopt_graph_print_abstime; -static int gopt_graph_print_cpu; -static int gopt_graph_print_proc; -static int gopt_graph_print_overrun; - -static void set_all_flags_default(void) -{ - gopt_context_info = 1; - gopt_sym_offset = 0; - gopt_sym_addr = 0; - - gopt_graph_print_duration = 1; - gopt_graph_print_overhead = 1; - gopt_graph_print_abstime = 0; - gopt_graph_print_cpu = 1; - gopt_graph_print_proc = 0; - gopt_graph_print_overrun = 0; -} - -static void set_clear_flag(const char *flag_name, int set) -{ - if (!strcmp(flag_name, "context_info")) - gopt_context_info = set; - else if (!strcmp(flag_name, "sym_offset")) - gopt_sym_offset = set; - else if (!strcmp(flag_name, "sym_addr")) - gopt_sym_addr = set; - else if (!strcmp(flag_name, "graph_print_duration")) - gopt_graph_print_duration = set; - else if (!strcmp(flag_name, "graph_print_overhead")) - gopt_graph_print_overhead = set; - else if (!strcmp(flag_name, "graph_print_abstime")) - gopt_graph_print_abstime = set; - else if (!strcmp(flag_name, "graph_print_cpu")) - gopt_graph_print_cpu = set; - else if (!strcmp(flag_name, "graph_print_proc")) - gopt_graph_print_proc = set; - else if (!strcmp(flag_name, "graph_print_overrun")) - gopt_graph_print_overrun = set; - /* invalid flage_name is omitted. */ -} - -static int tracer_no_event_context; - -static void ftrace_show_function_graph_init(void); -static void ftrace_show_function_init(void); -static void ftrace_show_trace_event_init(void); - -static int ftrace_show_init(void) -{ - /* ftrace_event_get_id(), ftrace_event_get_pid() should not failed. */ - if (find_event_field(event_types[0], "common_type") == NULL) - return -1; - - if (find_event_field(event_types[0], "common_pid") == NULL) - return -1; - - ftrace_show_function_init(); - ftrace_show_function_graph_init(); - ftrace_show_trace_event_init(); - - return 0; -} - -void show_event(struct format_context *fc) -{ - struct event_type *etype; - int id; - - id = ftrace_event_get_id(fc->event.data); - etype = find_event_type(id); - - if (etype == NULL) { - event_printf("<Unknown event type>\n"); - return; - } - - if (!tracer_no_event_context && gopt_context_info) - event_context_print(etype, fc); - if (!etype->plugin) - event_printf("%s: ", etype->name); - etype->printer(etype, fc); -} - -static int parse_cpulist(int *cpulist, const char *cpulist_str, int len) -{ - unsigned a, b; - const char *s = cpulist_str; - - memset(cpulist, 0, sizeof(int) * len); - - do { - if (!isdigit(*s)) - return -1; - b = a = strtoul(s, (char **)&s, 10); - if (*s == '-') { - s++; - if (!isdigit(*s)) - return -1; - b = strtoul(s, (char **)&s, 10); - } - if (!(a <= b)) - return -1; - if (b >= len) - return -1; - while (a <= b) { - cpulist[a] = 1; - a++; - } - if (*s == ',') - s++; - } while (*s != '\0' && *s != '\n'); - - return 0; -} - -static void ftrace_show_function_graph_start(void); - -static void ftrace_show(int argc, char *argv[]) -{ - int c; - int *cpulist = NULL; - - set_all_flags_default(); - ftrace_show_function_graph_start(); - - while ((c = getopt(argc, argv, "f:c:")) != EOF) { - switch(c) - { - case 'f': - if (optarg[0] == 'n' && optarg[1] == 'o') - set_clear_flag(optarg + 2, 0); - else - set_clear_flag(optarg, 1); - break; - case 'c': - if (cpulist) - goto err_arg; - - cpulist = malloc(sizeof(int) * nr_cpu_ids); - if (cpulist == NULL) { - error(INFO, "malloc() fail\n"); - return; - } - - if (parse_cpulist(cpulist, optarg, nr_cpu_ids) < 0) - goto err_arg; - break; - default: - goto err_arg; - } - } - - if (argc - optind != 0) { -err_arg: - cmd_usage(pc->curcmd, SYNOPSIS); - free(cpulist); - return; - } - - ring_buffer_stream_init(&format_context.stream, cpulist); - - /* Ignore setjmp()'s return value, no special things to do. */ - setjmp(show_event_env); - - for (;;) { - show_event_pos = 0; - format_context.cpu = ring_buffer_stream_pop_event( - &format_context.stream, &format_context.event); - if (format_context.cpu < 0) - break; - - show_event(&format_context); - fprintf(fp, "%s", show_event_buf); - } - - ring_buffer_stream_destroy(&format_context.stream, cpulist); - free(cpulist); -} - -static void cmd_ftrace(void) +static void cmd_ftrace(void) { if (argcnt == 1) show_basic_info(); @@ -2216,729 +1478,12 @@ static void cmd_ftrace(void) ftrace_dump(argcnt - 1, args + 1); else if (!strcmp(args[1], "show")) ftrace_show(argcnt - 1, args + 1); + else if (!strcmp(args[1], "report")) + ftrace_show(argcnt - 1, args + 1); else cmd_usage(pc->curcmd, SYNOPSIS); } -static void event_default_print(struct event_type *t, struct format_context *fc) -{ - int i; - - /* Skip the common types */ - for (i = t->nfields - 6; i >= 0; i--) { - struct ftrace_field *f; - - f = &t->fields[i]; - event_printf("%s=", f->name); - event_field_print(f, fc->event.data); - if (i) - event_printf(", "); - } - - event_printf("\n"); -} - -static void sym_print(ulong sym, int opt_offset) -{ - if (!sym) { - event_printf("0"); - } else { - ulong offset; - struct syment *se; - - se = value_search(sym, &offset); - if (se) { - event_printf("%s", se->name); - if (opt_offset) - event_printf("+%lu", offset); - } - } -} - -static void event_fn_print(struct event_type *t, struct format_context *fc) -{ - unsigned long ip = access_field(t, fc->event.data, "ip"); - unsigned long parent_ip = access_field(t, fc->event.data, "parent_ip"); - - sym_print(ip, gopt_sym_offset); - if (gopt_sym_addr) - event_printf("<%lx>", ip); - - event_printf(" <-"); - - sym_print(parent_ip, gopt_sym_offset); - if (gopt_sym_addr) - event_printf("<%lx>", parent_ip); - - event_printf("\n"); -} - -static void ftrace_show_function_init(void) -{ - struct event_type *t = find_event_type_by_name("ftrace", "function"); - - if (t) - t->printer = event_fn_print; -} - -#if 0 -/* simple */ -static void event_fn_entry_print(struct event_type *t, struct format_context *fc) -{ - ulong func = access_field(t, fc->event.data, "graph_ent.func"); - int depth = access_field(t, fc->event.data, "graph_ent.depth"); - - event_printf("%*s", depth, " "); - sym_print(func, gopt_sym_offset); - if (gopt_sym_addr) - event_printf("<%lx>", func); - event_printf("() {"); -} - -static void event_fn_return_print(struct event_type *t, struct format_context *fc) -{ - ulong func = access_field(t, fc->event.data, "ret.func"); - u64 calltime = access_field(t, fc->event.data, "ret.calltime"); - u64 rettime = access_field(t, fc->event.data, "ret.rettime"); - int depth = access_field(t, fc->event.data, "ret.depth"); - - event_printf("%*s} %lluns", depth, " ", - (unsigned long long)(rettime - calltime)); -} - -static void ftrace_show_function_graph_init(void) -{ - struct event_type *t1 = find_event_type_by_name( - "ftrace", "funcgraph_entry"); - struct event_type *t2 = find_event_type_by_name( - "ftrace", "funcgraph_exit"); - - if (t1 == NULL || t2 == NULL) - return; - - t1->printer = event_fn_entry_print; - t2->printer = event_fn_return_print; -} -#endif - - -#define TRACE_GRAPH_PROCINFO_LENGTH 14 -#define TRACE_GRAPH_INDENT 2 - -static int max_bytes_for_cpu; -static int *cpus_prev_pid; - -static int function_graph_entry_id; -static int function_graph_return_id; -static struct event_type *function_graph_entry_type; -static struct event_type *function_graph_return_type; - -static void ftrace_show_function_graph_start(void) -{ - int i; - - if (cpus_prev_pid == NULL) - return; - - for (i = 0; i < nr_cpu_ids; i++) - cpus_prev_pid[i] = -1; -} - -static void fn_graph_proc_print(int pid) -{ - int pid_strlen, comm_strlen; - char pid_str[20]; - char comm[20] = "<...>"; - - pid_strlen = sprintf(pid_str, "%d", pid); - comm_strlen = TRACE_GRAPH_PROCINFO_LENGTH - 1 - pid_strlen; - - get_comm_from_pid(pid, comm); - event_printf("%*.*s-%s", comm_strlen, comm_strlen, comm, pid_str); -} - -/* If the pid changed since the last trace, output this event */ -static void fn_graph_proc_switch_print(int pid, int cpu) -{ - int prev_pid = cpus_prev_pid[cpu]; - - cpus_prev_pid[cpu] = pid; - if ((prev_pid == pid) || (prev_pid == -1)) - return; - -/* - * Context-switch trace line: - - ------------------------------------------ - | 1) migration/0--1 => sshd-1755 - ------------------------------------------ - - */ - - event_printf(" ------------------------------------------\n"); - event_printf(" %*d) ", max_bytes_for_cpu, cpu); - fn_graph_proc_print(prev_pid); - event_printf(" => "); - fn_graph_proc_print(pid); - event_printf("\n ------------------------------------------\n\n"); -} - -/* Signal a overhead of time execution to the output */ -static void fn_graph_overhead_print(unsigned long long duration) -{ - const char *s = " "; - - /* If duration disappear, we don't need anything */ - if (!gopt_graph_print_duration) - return; - - /* duration == -1 is for non nested entry or return */ - if ((duration != -1) && gopt_graph_print_overhead) { - /* Duration exceeded 100 msecs */ - if (duration > 100000ULL) - s = "! "; - /* Duration exceeded 10 msecs */ - else if (duration > 10000ULL) - s = "+ "; - } - - event_printf(s); -} - -static void fn_graph_abstime_print(u64 ts) -{ - u64 time = ts / 1000; - unsigned long sec = time / 1000000; - unsigned long usec = time % 1000000; - - event_printf("%5lu.%06lu | ", sec, usec); -} - -static void fn_graph_irq_print(int type) -{ - /* TODO: implement it. */ -} - -static void fn_graph_duration_print(unsigned long long duration) -{ - /* log10(ULONG_MAX) + '\0' */ - char msecs_str[21]; - char nsecs_str[5]; - int len; - unsigned long nsecs_rem = duration % 1000; - - duration = duration / 1000; - len = sprintf(msecs_str, "%lu", (unsigned long) duration); - - /* Print msecs */ - event_printf("%s", msecs_str); - - /* Print nsecs (we don't want to exceed 7 numbers) */ - if (len < 7) { - snprintf(nsecs_str, 8 - len, "%03lu", nsecs_rem); - event_printf(".%s", nsecs_str); - - len += strlen(nsecs_str); - } - - if (len > 7) - len = 7; - - event_printf(" us %*s| ", 7 - len, ""); -} - -/* Case of a leaf function on its call entry */ -static void fn_graph_entry_leaf_print(void *entry_data, void *exit_data) -{ - struct event_type *t = function_graph_return_type; - - u64 calltime = access_field(t, exit_data, "ret.calltime"); - u64 rettime = access_field(t, exit_data, "ret.rettime"); - u64 duration = rettime - calltime; - int depth = access_field(t, exit_data, "ret.depth"); - ulong func = access_field(t, exit_data, "ret.func"); - - fn_graph_overhead_print(duration); - if (gopt_graph_print_duration) - fn_graph_duration_print(duration); - - event_printf("%*s", depth * TRACE_GRAPH_INDENT, ""); - sym_print(func, 0); - event_printf("();\n"); -} - -static void fn_graph_entry_nested_print(struct event_type *t, void *data) -{ - int depth = access_field(t, data, "graph_ent.depth"); - ulong func = access_field(t, data, "graph_ent.func"); - - fn_graph_overhead_print(-1); - - /* No time */ - if (gopt_graph_print_duration) - event_printf(" | "); - - event_printf("%*s", depth * TRACE_GRAPH_INDENT, ""); - sym_print(func, 0); - event_printf("() {\n"); -} - -static void fn_graph_prologue_print(int cpu, u64 ts, int pid, int type) -{ - fn_graph_proc_switch_print(pid, cpu); - - if (type) - fn_graph_irq_print(type); - - if (gopt_graph_print_abstime) - fn_graph_abstime_print(ts); - - if (gopt_graph_print_cpu) - event_printf(" %*d) ", max_bytes_for_cpu, cpu); - - if (gopt_graph_print_proc) { - fn_graph_proc_print(pid); - event_printf(" | "); - } -} - -static void *get_return_for_leaf(struct event_type *t, - struct format_context *fc, void *curr_data) -{ - int cpu; - struct ftrace_event next; - ulong entry_func, exit_func; - - cpu = ring_buffer_stream_pop_event(&fc->stream, &next); - - if (cpu < 0) - goto not_leaf; - - if (ftrace_event_get_id(next.data) != function_graph_return_id) - goto not_leaf; - - if (ftrace_event_get_pid(curr_data) != ftrace_event_get_pid(next.data)) - goto not_leaf; - - entry_func = access_field(t, curr_data, "graph_ent.func"); - exit_func = access_field(function_graph_return_type, next.data, - "ret.func"); - - if (entry_func != exit_func) - goto not_leaf; - - return next.data; - -not_leaf: - ring_buffer_stream_push_current_event(&fc->stream); - return NULL; -} - -static -void event_fn_entry_print(struct event_type *t, struct format_context *fc) -{ - void *leaf_ret_data = NULL, *curr_data = fc->event.data, *data; - int pid = ftrace_event_get_pid(curr_data); - - fn_graph_prologue_print(fc->cpu, fc->event.ts, pid, 1); - - data = alloca(fc->event.length); - if (data) { - memcpy(data, fc->event.data, fc->event.length); - curr_data = data; - leaf_ret_data = get_return_for_leaf(t, fc, curr_data); - } - - if (leaf_ret_data) - return fn_graph_entry_leaf_print(curr_data, leaf_ret_data); - else - return fn_graph_entry_nested_print(t, curr_data); -} - -static -void event_fn_return_print(struct event_type *t, struct format_context *fc) -{ - void *data = fc->event.data; - int pid = ftrace_event_get_pid(data); - - u64 calltime = access_field(t, data, "ret.calltime"); - u64 rettime = access_field(t, data, "ret.rettime"); - u64 duration = rettime - calltime; - int depth = access_field(t, data, "ret.depth"); - - fn_graph_prologue_print(fc->cpu, fc->event.ts, pid, 0); - fn_graph_overhead_print(duration); - - if (gopt_graph_print_duration) - fn_graph_duration_print(duration); - - event_printf("%*s}\n", depth * TRACE_GRAPH_INDENT, ""); - - if (gopt_graph_print_overrun) { - unsigned long overrun = access_field(t, data, "ret.overrun"); - event_printf(" (Overruns: %lu)\n", overrun); - } - - fn_graph_irq_print(0); -} - -static void ftrace_show_function_graph_init(void) -{ - if (strcmp(current_tracer_name, "function_graph")) - return; - - function_graph_entry_type = find_event_type_by_name( - "ftrace", "funcgraph_entry"); - function_graph_return_type = find_event_type_by_name( - "ftrace", "funcgraph_exit"); - - if (!function_graph_entry_type || !function_graph_return_type) - return; - - /* - * Because of get_return_for_leaf(), the exception handling - * of access_field() is not work for function_graph. So we need - * to ensure access_field() will not failed for these fields. - * - * I know these will not failed. I just ensure it. - */ - - if (!find_event_field(function_graph_entry_type, "graph_ent.func")) - return; - - if (!find_event_field(function_graph_entry_type, "graph_ent.depth")) - return; - - if (!find_event_field(function_graph_return_type, "ret.func")) - return; - - if (!find_event_field(function_graph_return_type, "ret.calltime")) - return; - - if (!find_event_field(function_graph_return_type, "ret.rettime")) - return; - - if (!find_event_field(function_graph_return_type, "ret.overrun")) - return; - - if (!find_event_field(function_graph_return_type, "ret.depth")) - return; - - cpus_prev_pid = malloc(sizeof(int) * nr_cpu_ids); - if (!cpus_prev_pid) - return; - - max_bytes_for_cpu = snprintf(NULL, 0, "%d", nr_cpu_ids - 1); - - function_graph_entry_id = function_graph_entry_type->id; - function_graph_return_id = function_graph_return_type->id; - - /* OK, set the printer for function_graph. */ - tracer_no_event_context = 1; - function_graph_entry_type->printer = event_fn_entry_print; - function_graph_return_type->printer = event_fn_return_print; -} - -static void event_sched_kthread_stop_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("task %s:%d\n", - (char *)(long)access_field(t, fc->event.data, "comm"), - (int)access_field(t, fc->event.data, "pid")); -} - -static void event_sched_kthread_stop_ret_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("ret %d\n", (int)access_field(t, fc->event.data, "ret")); -} - -static void event_sched_wait_task_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("task %s:%d [%d]\n", - (char *)(long)access_field(t, fc->event.data, "comm"), - (int)access_field(t, fc->event.data, "pid"), - (int)access_field(t, fc->event.data, "prio")); -} - -static void event_sched_wakeup_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("task %s:%d [%d] success=%d\n", - (char *)(long)access_field(t, fc->event.data, "comm"), - (int)access_field(t, fc->event.data, "pid"), - (int)access_field(t, fc->event.data, "prio"), - (int)access_field(t, fc->event.data, "success")); -} - -static void event_sched_wakeup_new_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("task %s:%d [%d] success=%d\n", - (char *)(long)access_field(t, fc->event.data, "comm"), - (int)access_field(t, fc->event.data, "pid"), - (int)access_field(t, fc->event.data, "prio"), - (int)access_field(t, fc->event.data, "success")); -} - -static void event_sched_switch_print(struct event_type *t, - struct format_context *fc) -{ - char *prev_comm = (char *)(long)access_field(t, fc->event.data, - "prev_comm"); - int prev_pid = access_field(t, fc->event.data, "prev_pid"); - int prev_prio = access_field(t, fc->event.data, "prev_prio"); - - int prev_state = access_field(t, fc->event.data, "prev_state"); - - char *next_comm = (char *)(long)access_field(t, fc->event.data, - "next_comm"); - int next_pid = access_field(t, fc->event.data, "next_pid"); - int next_prio = access_field(t, fc->event.data, "next_prio"); - - event_printf("task %s:%d [%d] (", prev_comm, prev_pid, prev_prio); - - if (prev_state == 0) { - event_printf("R"); - } else { - if (prev_state & 1) - event_printf("S"); - if (prev_state & 2) - event_printf("D"); - if (prev_state & 4) - event_printf("T"); - if (prev_state & 8) - event_printf("t"); - if (prev_state & 16) - event_printf("Z"); - if (prev_state & 32) - event_printf("X"); - if (prev_state & 64) - event_printf("x"); - if (prev_state & 128) - event_printf("W"); - } - - event_printf(") ==> %s:%d [%d]\n", next_comm, next_pid, next_prio); -} - -static void event_sched_migrate_task_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("task %s:%d [%d] from: %d to: %d\n", - (char *)(long)access_field(t, fc->event.data, "comm"), - (int)access_field(t, fc->event.data, "pid"), - (int)access_field(t, fc->event.data, "prio"), - (int)access_field(t, fc->event.data, "orig_cpu"), - (int)access_field(t, fc->event.data, "dest_cpu")); -} - -static void event_sched_process_free_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("task %s:%d [%d]\n", - (char *)(long)access_field(t, fc->event.data, "comm"), - (int)access_field(t, fc->event.data, "pid"), - (int)access_field(t, fc->event.data, "prio")); -} - -static void event_sched_process_exit_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("task %s:%d [%d]\n", - (char *)(long)access_field(t, fc->event.data, "comm"), - (int)access_field(t, fc->event.data, "pid"), - (int)access_field(t, fc->event.data, "prio")); -} - -static void event_sched_process_wait_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("task %s:%d [%d]\n", - (char *)(long)access_field(t, fc->event.data, "comm"), - (int)access_field(t, fc->event.data, "pid"), - (int)access_field(t, fc->event.data, "prio")); -} - -static void event_sched_process_fork_print(struct event_type *t, - struct format_context *fc) -{ - char *parent_comm = (char *)(long)access_field(t, fc->event.data, - "parent_comm"); - int parent_pid = access_field(t, fc->event.data, "parent_pid"); - - char *child_comm = (char *)(long)access_field(t, fc->event.data, - "child_comm"); - int child_pid = access_field(t, fc->event.data, "child_pid"); - - event_printf("parent %s:%d child %s:%d\n", parent_comm, parent_pid, - child_comm, child_pid); -} - -static void event_sched_signal_send_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("sig: %d task %s:%d\n", - (int)access_field(t, fc->event.data, "sig"), - (char *)(long)access_field(t, fc->event.data, "comm"), - (int)access_field(t, fc->event.data, "pid")); -} - -static void event_kmalloc_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu " - "gfp_flags=%lx\n", - (long)access_field(t, fc->event.data, "call_site"), - (void *)(long)access_field(t, fc->event.data, "ptr"), - (size_t)access_field(t, fc->event.data, "bytes_req"), - (size_t)access_field(t, fc->event.data, "bytes_alloc"), - (long)access_field(t, fc->event.data, "gfp_flags")); -} - -static void event_kmem_cache_alloc_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu " - "gfp_flags=%lx\n", - (long)access_field(t, fc->event.data, "call_site"), - (void *)(long)access_field(t, fc->event.data, "ptr"), - (size_t)access_field(t, fc->event.data, "bytes_req"), - (size_t)access_field(t, fc->event.data, "bytes_alloc"), - (long)access_field(t, fc->event.data, "gfp_flags")); -} - -static void event_kmalloc_node_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu " - "gfp_flags=%lx node=%d\n", - (long)access_field(t, fc->event.data, "call_site"), - (void *)(long)access_field(t, fc->event.data, "ptr"), - (size_t)access_field(t, fc->event.data, "bytes_req"), - (size_t)access_field(t, fc->event.data, "bytes_alloc"), - (long)access_field(t, fc->event.data, "gfp_flags"), - (int)access_field(t, fc->event.data, "node")); -} - -static void event_kmem_cache_alloc_node_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu " - "gfp_flags=%lx node=%d\n", - (long)access_field(t, fc->event.data, "call_site"), - (void *)(long)access_field(t, fc->event.data, "ptr"), - (size_t)access_field(t, fc->event.data, "bytes_req"), - (size_t)access_field(t, fc->event.data, "bytes_alloc"), - (long)access_field(t, fc->event.data, "gfp_flags"), - (int)access_field(t, fc->event.data, "node")); -} - -static void event_kfree_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("call_site=%lx ptr=%p\n", - (long)access_field(t, fc->event.data, "call_site"), - (void *)(long)access_field(t, fc->event.data, "ptr")); -} - -static void event_kmem_cache_free_print(struct event_type *t, - struct format_context *fc) -{ - event_printf("call_site=%lx ptr=%p\n", - (long)access_field(t, fc->event.data, "call_site"), - (void *)(long)access_field(t, fc->event.data, "ptr")); -} - -static void event_workqueue_insertion_print(struct event_type *t, - struct format_context *fc) -{ - char *thread_comm = (char *)(long)access_field(t, fc->event.data, - "thread_comm"); - int thread_pid = access_field(t, fc->event.data, "thread_pid"); - ulong func = access_field(t, fc->event.data, "func"); - - event_printf("thread=%s:%d func=", thread_comm, thread_pid); - sym_print(func, 1); - event_printf("\n"); -} - -static void event_workqueue_execution_print(struct event_type *t, - struct format_context *fc) -{ - char *thread_comm = (char *)(long)access_field(t, fc->event.data, - "thread_comm"); - int thread_pid = access_field(t, fc->event.data, "thread_pid"); - ulong func = access_field(t, fc->event.data, "func"); - - event_printf("thread=%s:%d func=", thread_comm, thread_pid); - sym_print(func, 1); - event_printf("\n"); -} - -static void event_workqueue_creation_print(struct event_type *t, - struct format_context *fc) -{ - char *thread_comm = (char *)(long)access_field(t, fc->event.data, - "thread_comm"); - int thread_pid = access_field(t, fc->event.data, "thread_pid"); - int cpu = access_field(t, fc->event.data, "cpu"); - - event_printf("thread=%s:%d cpu=%d\n", thread_comm, thread_pid, cpu); -} - -static void event_workqueue_destruction_print(struct event_type *t, - struct format_context *fc) -{ - char *thread_comm = (char *)(long)access_field(t, fc->event.data, - "thread_comm"); - int thread_pid = access_field(t, fc->event.data, "thread_pid"); - - event_printf("thread=%s:%d\n", thread_comm, thread_pid); -} - -static void ftrace_show_trace_event_init(void) -{ -#define init_trace_event(system, name) \ -do { \ - struct event_type *t = find_event_type_by_name(#system, #name); \ - if (t) \ - t->printer = event_ ## name ## _print; \ -} while (0) - - init_trace_event(sched, sched_kthread_stop); - init_trace_event(sched, sched_kthread_stop_ret); - init_trace_event(sched, sched_wait_task); - init_trace_event(sched, sched_wakeup); - init_trace_event(sched, sched_wakeup_new); - init_trace_event(sched, sched_switch); - init_trace_event(sched, sched_migrate_task); - init_trace_event(sched, sched_process_free); - init_trace_event(sched, sched_process_exit); - init_trace_event(sched, sched_process_wait); - init_trace_event(sched, sched_process_fork); - init_trace_event(sched, sched_signal_send); - - init_trace_event(kmem, kmalloc); - init_trace_event(kmem, kmem_cache_alloc); - init_trace_event(kmem, kmalloc_node); - init_trace_event(kmem, kmem_cache_alloc_node); - init_trace_event(kmem, kfree); - init_trace_event(kmem, kmem_cache_free); - - init_trace_event(workqueue, workqueue_insertion); - init_trace_event(workqueue, workqueue_execution); - init_trace_event(workqueue, workqueue_creation); - init_trace_event(workqueue, workqueue_destruction); -#undef init_trace_event -} - -static void ftrace_show_destroy(void) -{ - free(cpus_prev_pid); -} - static char *help_ftrace[] = { "trace", "show or dump the tracing info", @@ -2946,22 +1491,11 @@ static char *help_ftrace[] = { "trace", " shows the current tracer and other informations.", "", -"trace show [ -c <cpulist> ] [ -f [no]<flagename> ]", +"trace show", " shows all events with readability text(sorted by timestamp)", -" -c: only shows specified CPUs' events.", -" ex. trace show -c 1,2 - only shows cpu#1 and cpu#2 's events.", -" trace show -c 0,2-7 - only shows cpu#0, cpu#2...cpu#7's events.", -" -f: set or clear a flag", -" available flags default", -" context_info true", -" sym_offset false", -" sym_addr false", -" graph_print_duration true", -" graph_print_overhead true", -" graph_print_abstime false", -" graph_print_cpu true", -" graph_print_proc false", -" graph_print_overrun false", +"", +"trace report", +" the same as \"trace show\"", "", "trace dump [-sm] <dest-dir>", " dump ring_buffers to dest-dir. Then you can parse it",