On Mon, Aug 03, 2009 at 10:48:01PM +0800, Lai Jiangshan wrote: Nice! Now the only thing missing is gettind kdb in mainline and a trace reader in kdb ;-) Any idea how easy it is to reuse the crash/gdb code for looking at crash dumps through kgdb? Btw, the Cc list here seems to be a very strong indicator that we should have a linux-trace@vger list, I already noticed this for tons of other tracing patches.

Peter Zijlstra wrote: With respect to kdb for the mainline, this is still largely a work in progress, but there is a prototype implementation of kdb which is hooked up to the kdb backend. There is a new prototype pushed to the kgdb development tree every couple of weeks. The prototype #4 will be pushed sometime this week. If there is a nice API to call for the trace piece, it is pretty trivial to add additional kdb commands which would allow you to print your trace buffers as needed. The unified kdb/kgdb prototype also supports calling kdb commands through gdb's "monitor" command. It is not clear if that satisfies the need that Christoph asked about, or if he had some other data analysis in mind. In no particular order, tracing, kernel probes, profiling data display, kdump, disassembly and kernel mode setting were some of the pieces that are on the wish list for integration with the kdb prototype. Kernel mode setting is presently the highest priority on the wish list for a new feature. I will gladly accept patches into the kdb prototype if people have any. :-) Jason. Prototype #3 is at: http://git.kernel.org/?p=linux/kernel/git/jwessel/linux-2.6-kgdb.git;a=sh... There had not been any further posts about the kdb -> kgdb integration outside the first because the project is still pretty young and there is a significant amount of clean up required to the original kdb code base in order bring it closer to consideration for any kind of lkml scrutiny. The nice thing about the kdb prototype is that it is almost entirely arch independent. The goal of this project is to make such that any arch that makes use of the kgdb core today, could make use of the generic kdb interface.

On Mon, 2009-08-03 at 22:48 +0800, Lai Jiangshan wrote: doesn't crash have a vmlinux around to look at? (well-defined) That would require the running kernel to be the same as the one that generated the core file -- not very usable imho.

[ been away for a bit, so I'm catching up on email ] On Tue, 2009-08-04 at 14:52 +0800, Lai Jiangshan wrote: This format patch will soon be in (if not already) with some updates. -- Steve

This extension module enables crash to analyze tracing from core-file and make tracing can act as a flight recorder. It helps us find what have happen from the sequence of events before panic. It makes the core-file is not just a system snapshot on panic time. The codes is still not mature, comments are welcome. Update: - Implement it as a crash(8) extension module. - robuster exception handling Lai. ----------- Use this module: 1) Put the trace.c(attached) file in the "extensions" subdirectory which is in the crash source directory. 2) Enter "make extensions" from the top-level to build it. It creates "trace.so" in the "extensions" subdirectory. 3) (when you are using crash and you need this module) Use the "extend" command to load the "trace.so" extension module: crash> extend <path-to>/trace.so A command "trace" will be added after loaded. 4) Use the "extend -u" to unload it when you don't need it: crash> extend -u <path-to>/trace.so ---------- Use "trace" command: crash> help trace NAME trace - show or dump the tracing info SYNOPSIS trace [ <show [-c <cpulist>] [-f [no]<flagname>]> | <dump [-sm] <dest-dir>> ] DESCRIPTION trace shows the current tracer and other informations. trace show [ -c <cpulist> ] [ -f [no]<flagename> ] 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 dump [-sm] <dest-dir> dump ring_buffers to dest-dir. Then you can parse it by other tracing tools. The dirs and files are generated the same as debugfs/tracing. -m: also dump metadata of ftrace. -s: also dump symbols of the kernel <not implemented>. EXAMPLE, dump ring_buffer: crash > trace dump -m dumped_tracing (quit crash) # ls -R dumped_tracing dumped_tracing: events per_cpu saved_cmdlines dumped_tracing/events: block ftrace irq kmem sched skb workqueue dumped_tracing/events/block: block_bio_backmerge block_bio_frontmerge block_plug block_rq_complete block_rq_requeue block_unplug_io block_bio_bounce block_bio_queue block_remap block_rq_insert block_sleeprq block_unplug_timer block_bio_complete block_getrq block_rq_abort block_rq_issue block_split dumped_tracing/events/block/block_bio_backmerge: format dumped_tracing/events/block/block_bio_bounce: format .... dumped_tracing/per_cpu: cpu0 cpu1 dumped_tracing/per_cpu/cpu0: trace_pipe_raw dumped_tracing/per_cpu/cpu1: trace_pipe_raw EXAMPLE, shows function tracer crash > trace show <...>-3677 [001] 6094.628402: pick_next_task_fair <-schedule <...>-3677 [001] 6094.628403: pick_next_task_rt <-schedule <...>-3677 [001] 6094.628404: pick_next_task_fair <-schedule <...>-3677 [001] 6094.628405: pick_next_task_idle <-schedule <...>-3677 [001] 6094.628406: calc_load_account_active <-pick_next_task_idle <...>-3677 [001] 6094.628407: perf_counter_task_sched_out <-schedule <swapper>-0 [001] 6094.628437: finish_task_switch <-schedule <swapper>-0 [001] 6094.628438: perf_counter_task_sched_in <-finish_task_switch <swapper>-0 [001] 6094.628439: _spin_unlock_irq <-finish_task_switch <swapper>-0 [001] 6094.628440: kretprobe_table_lock_ptr <-kretprobe_table_lock <swapper>-0 [001] 6094.628442: _spin_lock_irqsave <-kretprobe_table_lock .... bash-3580 [000] 6119.756585: native_apic_mem_read <-default_get_apic_id bash-3580 [000] 6119.756616: crash_save_cpu <-native_machine_crash_shutdown bash-3580 [000] 6119.756687: append_elf_note <-crash_save_cpu bash-3580 [000] 6119.756688: strlen <-append_elf_note bash-3580 [000] 6119.756712: final_note <-crash_save_cpu bash-3580 [000] 6119.756776: machine_kexec <-crash_kexec bash-3580 [000] 6119.756824: page_address <-machine_kexec EXAMPLE, shows function_graph tracer crash > trace show 1) 1.187 us | } 1) | hrtimer_forward() { 1) 1.018 us | ktime_add_safe(); 1) 0.953 us | ktime_add_safe(); 1) 5.419 us | } 1) + 87.322 us | } 1) 1.028 us | _spin_lock(); 1) 1.779 us | enqueue_hrtimer(); 1) ! 100.743 us | } 1) 1.043 us | _spin_unlock(); 1) | tick_program_event() { 1) | tick_dev_program_event() { 1) 1.148 us | ktime_get(); EXAMPLE, shows various events crash > trace show <swapper>-0 [001] 9349.585217: softirq_exit: vec=1 <swapper>-0 [001] 9349.585218: softirq_entry: vec=8 <swapper>-0 [001] 9349.585226: kmem_cache_free: call_site=c015a221 ptr=0xcfb16200 <swapper>-0 [001] 9349.585228: kmem_cache_free: call_site=c0151c32 ptr=0xcfb438c0 <swapper>-0 [001] 9349.585230: sched_process_free: task dhclient-script:3749 [120] <swapper>-0 [001] 9349.585237: kfree: call_site=c017f13a ptr=(nil) <swapper>-0 [001] 9349.585239: kmem_cache_free: call_site=c013b8f1 ptr=0xcf056ed0 <swapper>-0 [001] 9349.585241: softirq_exit: vec=8 <...>-3752 [000] 9349.585717: kmem_cache_alloc: call_site=c01b6a34 ptr=0xcf2c50b0 bytes_req=88 bytes_alloc=88 gfp_flags=80d0 <...>-3752 [000] 9349.585732: kmem_cache_alloc: call_site=c01b95fa ptr=0xcf2c61e0 bytes_req=12 bytes_alloc=16 gfp_flags=d0 Signed-off-by: Lai Jiangshan <laijs(a)cn.fujitsu.com&gt; /* * trace extension module for crash * * Copyright (C) 2009 FUJITSU LIMITED * Author: Lai Jiangshan <laijs(a)cn.fujitsu.com&gt; * * This program is free software; you can redistribute it and/or modify * it under the terms of the GNU General Public License as published by * the Free Software Foundation; either version 2, or (at your option) * any later version. */ #define _GNU_SOURCE #include "defs.h" #include <stdio.h> #include <ctype.h> #include <setjmp.h> static int verbose = 0; static int nr_cpu_ids; /* * lockless ring_buffer and old non-lockless ring_buffer are both supported. */ static int lockless_ring_buffer; #define koffset(struct, member) struct##_##member##_offset static int koffset(trace_array, buffer); static int koffset(tracer, name); static int koffset(ring_buffer, pages); static int koffset(ring_buffer, flags); static int koffset(ring_buffer, cpus); static int koffset(ring_buffer, buffers); static int koffset(ring_buffer_per_cpu, cpu); static int koffset(ring_buffer_per_cpu, pages); static int koffset(ring_buffer_per_cpu, head_page); static int koffset(ring_buffer_per_cpu, tail_page); static int koffset(ring_buffer_per_cpu, commit_page); static int koffset(ring_buffer_per_cpu, reader_page); static int koffset(ring_buffer_per_cpu, overrun); static int koffset(ring_buffer_per_cpu, entries); static int koffset(buffer_page, read); static int koffset(buffer_page, list); static int koffset(buffer_page, page); static int koffset(list_head, next); static int koffset(ftrace_event_call, list); static int koffset(ftrace_event_call, name); static int koffset(ftrace_event_call, system); static int koffset(ftrace_event_call, id); static int koffset(ftrace_event_call, fields); static int koffset(ftrace_event_field, link); static int koffset(ftrace_event_field, name); static int koffset(ftrace_event_field, type); static int koffset(ftrace_event_field, offset); static int koffset(ftrace_event_field, size); static int koffset(ftrace_event_field, is_signed); static int koffset(POINTER_SYM, POINTER) = 0; struct ring_buffer_per_cpu { ulong kaddr; ulong head_page; ulong tail_page; ulong commit_page; ulong reader_page; ulong real_head_page; ulong *pages; int head_page_index; ulong overrun; ulong entries; }; static ulong global_trace; static ulong global_ring_buffer; static unsigned global_pages; static struct ring_buffer_per_cpu *global_buffers; static ulong max_tr_trace; static ulong max_tr_ring_buffer; static unsigned max_tr_pages; static struct ring_buffer_per_cpu *max_tr_buffers; static ulong ftrace_events; static ulong current_trace; 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) \ do { \ if (!readmem(ptr + koffset(struct, member), KVADDR, \ &at, sizeof(at), #struct "'s " #member, \ RETURN_ON_ERROR)) \ goto out_fail;\ } while (0) /* Remove the "const" qualifiers for ptr */ #define free(ptr) free((void *)(ptr)) #ifndef PATH_MAX #define PATH_MAX 4096 #endif static void init_offsets(void) { #define init_offset(struct, member) \ koffset(struct, member) = MEMBER_OFFSET(#struct, #member); init_offset(trace_array, buffer); init_offset(tracer, name); init_offset(ring_buffer, pages); init_offset(ring_buffer, flags); init_offset(ring_buffer, cpus); init_offset(ring_buffer, buffers); if (MEMBER_SIZE("ring_buffer_per_cpu", "pages") == sizeof(ulong)) { lockless_ring_buffer = 1; if (verbose) fprintf(fp, "lockless\n"); } init_offset(ring_buffer_per_cpu, cpu); init_offset(ring_buffer_per_cpu, pages); init_offset(ring_buffer_per_cpu, head_page); init_offset(ring_buffer_per_cpu, tail_page); init_offset(ring_buffer_per_cpu, commit_page); init_offset(ring_buffer_per_cpu, reader_page); init_offset(ring_buffer_per_cpu, overrun); init_offset(ring_buffer_per_cpu, entries); init_offset(buffer_page, read); init_offset(buffer_page, list); init_offset(buffer_page, page); init_offset(list_head, next); init_offset(ftrace_event_call, list); init_offset(ftrace_event_call, name); init_offset(ftrace_event_call, system); init_offset(ftrace_event_call, id); init_offset(ftrace_event_call, fields); init_offset(ftrace_event_field, link); init_offset(ftrace_event_field, name); init_offset(ftrace_event_field, type); init_offset(ftrace_event_field, offset); init_offset(ftrace_event_field, size); init_offset(ftrace_event_field, is_signed); #undef init_offset } static void print_offsets(void) { if (!verbose) return; #define print_offset(struct, member) fprintf(fp, \ "koffset(" #struct ", " #member ") = %d\n", koffset(struct, member)) print_offset(trace_array, buffer); print_offset(tracer, name); print_offset(ring_buffer, pages); print_offset(ring_buffer, flags); print_offset(ring_buffer, cpus); print_offset(ring_buffer, buffers); print_offset(ring_buffer_per_cpu, cpu); print_offset(ring_buffer_per_cpu, pages); print_offset(ring_buffer_per_cpu, head_page); print_offset(ring_buffer_per_cpu, tail_page); print_offset(ring_buffer_per_cpu, commit_page); print_offset(ring_buffer_per_cpu, reader_page); print_offset(ring_buffer_per_cpu, overrun); print_offset(ring_buffer_per_cpu, entries); print_offset(buffer_page, read); print_offset(buffer_page, list); print_offset(buffer_page, page); print_offset(list_head, next); print_offset(ftrace_event_call, list); print_offset(ftrace_event_call, name); print_offset(ftrace_event_call, system); print_offset(ftrace_event_call, id); print_offset(ftrace_event_call, fields); print_offset(ftrace_event_field, link); print_offset(ftrace_event_field, name); print_offset(ftrace_event_field, type); print_offset(ftrace_event_field, offset); print_offset(ftrace_event_field, size); print_offset(ftrace_event_field, is_signed); #undef print_offset } static int ftrace_init_pages(struct ring_buffer_per_cpu *cpu_buffer, unsigned nr_pages) { unsigned j = 0; ulong head, page; ulong real_head_page = cpu_buffer->head_page; cpu_buffer->pages = calloc(sizeof(ulong), nr_pages); if (cpu_buffer->pages == NULL) return -1; if (lockless_ring_buffer) { read_value(head, cpu_buffer->kaddr, ring_buffer_per_cpu, pages); cpu_buffer->pages[j++] = head - koffset(buffer_page, list); } else head = cpu_buffer->kaddr + koffset(ring_buffer_per_cpu, pages); page = head; for (;;) { read_value(page, page, list_head, next); if (page & 3) { /* lockless_ring_buffer */ page &= ~3; real_head_page = page - koffset(buffer_page, list); } if (j == nr_pages) break; if (page == head) { error(INFO, "Num of pages is less than %d\n", nr_pages); goto out_fail; } cpu_buffer->pages[j++] = page - koffset(buffer_page, list); } if (page != head) { error(INFO, "Num of pages is larger than %d\n", nr_pages); goto out_fail; } cpu_buffer->real_head_page = real_head_page; cpu_buffer->head_page_index = -1; for (j = 0; j < nr_pages; j++) { if (cpu_buffer->pages[j] == real_head_page) { cpu_buffer->head_page_index = j; break; } } if (cpu_buffer->head_page_index == -1) { error(INFO, "error for resolve head_page_index\n"); goto out_fail; } return 0; out_fail: free(cpu_buffer->pages); return -1; } static void ftrace_destroy_buffers(struct ring_buffer_per_cpu *buffers) { int i; for (i = 0; i < nr_cpu_ids; i++) free(buffers[i].pages); } static int ftrace_init_buffers(struct ring_buffer_per_cpu *buffers, ulong ring_buffer, unsigned pages) { int i; ulong buffers_array; read_value(buffers_array, ring_buffer, ring_buffer, buffers); for (i = 0; i < nr_cpu_ids; i++) { if (!readmem(buffers_array + sizeof(ulong) * i, KVADDR, &buffers[i].kaddr, sizeof(ulong), "ring_buffer's cpu buffer", RETURN_ON_ERROR)) goto out_fail; if (!buffers[i].kaddr) continue; #define buffer_read_value(member) read_value(buffers[i].member, \ buffers[i].kaddr, ring_buffer_per_cpu, member) buffer_read_value(head_page); buffer_read_value(tail_page); buffer_read_value(commit_page); buffer_read_value(reader_page); buffer_read_value(overrun); buffer_read_value(entries); #undef buffer_read_value if (ftrace_init_pages(buffers + i, pages) < 0) goto out_fail; if (verbose) { fprintf(fp, "overrun=%lu\n", buffers[i].overrun); fprintf(fp, "entries=%lu\n", buffers[i].entries); } } return 0; out_fail: ftrace_destroy_buffers(buffers); return -1; } static int ftrace_int_global_trace(void) { read_value(global_ring_buffer, global_trace, trace_array, buffer); read_value(global_pages, global_ring_buffer, ring_buffer, pages); global_buffers = calloc(sizeof(*global_buffers), nr_cpu_ids); if (global_buffers == NULL) goto out_fail; if (ftrace_init_buffers(global_buffers, global_ring_buffer, global_pages) < 0) goto out_fail; return 0; out_fail: free(global_buffers); return -1; } static int ftrace_int_max_tr_trace(void) { read_value(max_tr_ring_buffer, max_tr_trace, trace_array, buffer); if (!max_tr_ring_buffer) return 0; read_value(max_tr_pages, max_tr_ring_buffer, ring_buffer, pages); max_tr_buffers = calloc(sizeof(*max_tr_buffers), nr_cpu_ids); if (max_tr_buffers == NULL) goto out_fail; if (ftrace_init_buffers(max_tr_buffers, max_tr_ring_buffer, max_tr_pages) < 0) goto out_fail; return 0; out_fail: free(max_tr_buffers); max_tr_ring_buffer = 0; return -1; } static int ftrace_init_current_tracer(void) { ulong addr; char tmp[128]; /* Get current tracer name */ read_value(addr, current_trace, POINTER_SYM, POINTER); read_value(addr, addr, tracer, name); read_string(addr, tmp, 128); current_tracer_name = strdup(tmp); if (current_tracer_name == NULL) goto out_fail; return 0; out_fail: return -1; } static int ftrace_init(void) { struct syment *sym_global_trace; struct syment *sym_max_tr_trace; struct syment *sym_ftrace_events; struct syment *sym_current_trace; sym_global_trace = symbol_search("global_trace"); sym_max_tr_trace = symbol_search("max_tr"); sym_ftrace_events = symbol_search("ftrace_events"); sym_current_trace = symbol_search("current_trace"); if (sym_global_trace == NULL || sym_max_tr_trace == NULL || sym_ftrace_events == NULL || sym_current_trace == NULL) return -1; global_trace = sym_global_trace->value; max_tr_trace = sym_max_tr_trace->value; ftrace_events = sym_ftrace_events->value; current_trace = sym_current_trace->value; if (!try_get_symbol_data("nr_cpu_ids", sizeof(int), &nr_cpu_ids)) nr_cpu_ids = 1; init_offsets(); print_offsets(); if (ftrace_int_global_trace() < 0) goto out_0; ftrace_int_max_tr_trace(); if (ftrace_init_event_types() < 0) goto out_1; 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: if (max_tr_ring_buffer) { ftrace_destroy_buffers(max_tr_buffers); free(max_tr_buffers); } ftrace_destroy_buffers(global_buffers); free(global_buffers); out_0: return -1; } static void ftrace_destroy(void) { ftrace_show_destroy(); free(current_tracer_name); ftrace_destroy_event_types(); if (max_tr_ring_buffer) { ftrace_destroy_buffers(max_tr_buffers); free(max_tr_buffers); } ftrace_destroy_buffers(global_buffers); free(global_buffers); } static int ftrace_dump_page(FILE *out, ulong page, void *page_tmp) { ulong raw_page; read_value(raw_page, page, buffer_page, page); if (!readmem(raw_page, KVADDR, page_tmp, PAGESIZE(), "get page context", RETURN_ON_ERROR)) goto out_fail; fwrite(page_tmp, 1, PAGESIZE(), out); return 0; out_fail: return -1; } static void ftrace_dump_buffer(FILE *out, struct ring_buffer_per_cpu *cpu_buffer, unsigned pages, void *page_tmp) { unsigned i; if (ftrace_dump_page(out, cpu_buffer->reader_page, page_tmp) < 0) return; if (cpu_buffer->reader_page == cpu_buffer->commit_page) return; i = cpu_buffer->head_page_index; for (;;) { if (ftrace_dump_page(out, cpu_buffer->pages[i], page_tmp) < 0) break; if (cpu_buffer->pages[i] == cpu_buffer->commit_page) break; i++; if (i == pages) i = 0; if (i == cpu_buffer->head_page_index) { /* cpu_buffer->commit_page may be corrupted */ break; } } } static int try_mkdir(const char *pathname, mode_t mode) { int ret; ret = mkdir(pathname, mode); if (ret < 0) { if (errno == EEXIST) return 0; error(INFO, "mkdir failed\n"); return -1; } return 0; } static int ftrace_dump_buffers(const char *per_cpu_path) { int i; void *page_tmp; char path[PATH_MAX]; FILE *out; page_tmp = malloc(PAGESIZE()); if (page_tmp == NULL) return -1; for (i = 0; i < nr_cpu_ids; i++) { struct ring_buffer_per_cpu *cpu_buffer = &global_buffers[i]; if (!cpu_buffer->kaddr) continue; snprintf(path, sizeof(path), "%s/cpu%d", per_cpu_path, i); if (try_mkdir(path, 0755) < 0) goto out_fail; snprintf(path, sizeof(path), "%s/cpu%d/trace_pipe_raw", per_cpu_path, i); out = fopen(path, "wb"); if (out == NULL) goto out_fail; ftrace_dump_buffer(out, cpu_buffer, global_pages, page_tmp); fclose(out); } free(page_tmp); return 0; out_fail: free(page_tmp); 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; struct ftrace_field *fields; }; static struct event_type *event_type_cache[MAX_CACHE_ID]; static struct event_type **event_types; static int nr_event_types; /* * 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 ftrace_init_event_type(ulong call, struct event_type *aevent_type) { ulong fields_addr, pos; int nfields = 0, max_fields = 16; struct ftrace_field *fields = NULL; fields_addr = call + koffset(ftrace_event_call, fields); read_value(pos, fields_addr, list_head, next); if (pos == 0) { if (verbose) fprintf(fp, "no field %lu\n", call); return 0; } fields = malloc(sizeof(*fields) * max_fields); if (fields == NULL) return -1; while (pos != fields_addr) { ulong field; ulong name_addr, type_addr; char field_name[128], field_type[128]; int offset, size, is_signed; field = pos - koffset(ftrace_event_field, link); /* Read a field from the core */ read_value(name_addr, field, ftrace_event_field, name); read_value(type_addr, field, ftrace_event_field, type); read_value(offset, field, ftrace_event_field, offset); read_value(size, field, ftrace_event_field, size); read_value(is_signed, field, ftrace_event_field, is_signed); if (!read_string(name_addr, field_name, 128)) goto out_fail; if (!read_string(type_addr, field_type, 128)) goto out_fail; /* Enlarge fields array when need */ if (nfields >= max_fields) { void *tmp; max_fields = nfields * 2; tmp = realloc(fields, sizeof(*fields) * max_fields); if (tmp == NULL) goto out_fail; fields = tmp; } /* Set up and Add a field */ fields[nfields].offset = offset; fields[nfields].size = size; fields[nfields].is_signed = is_signed; fields[nfields].name = strdup(field_name); if (fields[nfields].name == NULL) goto out_fail; fields[nfields].type = strdup(field_type); if (fields[nfields].type == NULL) { free(fields[nfields].name); goto out_fail; } ftrace_field_access_init(&fields[nfields]); nfields++; /* Advance to the next field */ read_value(pos, pos, list_head, next); } aevent_type->nfields = nfields; aevent_type->fields = fields; return 0; out_fail: for (nfields--; nfields >= 0; nfields--) { free(fields[nfields].name); free(fields[nfields].type); } free(fields); return -1; } static void ftrace_destroy_event_types(void) { int i, j; for (i = 0; i < nr_event_types; i++) { for (j = 0; j < event_types[i]->nfields; j++) { free(event_types[i]->fields[j].name); free(event_types[i]->fields[j].type); } free(event_types[i]->fields); free(event_types[i]->system); free(event_types[i]->name); free(event_types[i]); } free(event_types); } static int ftrace_init_event_types(void) { ulong event; struct event_type *aevent_type; int max_types = 128; event_types = malloc(sizeof(*event_types) * max_types); if (event_types == NULL) return -1; read_value(event, ftrace_events, list_head, next); while (event != ftrace_events) { ulong call; ulong name_addr, system_addr; char name[128], system[128]; int id; call = event - koffset(ftrace_event_call, list); /* Read a event type from the core */ read_value(id, call, ftrace_event_call, id); read_value(name_addr, call, ftrace_event_call, name); read_value(system_addr, call, ftrace_event_call, system); if (!read_string(name_addr, name, 128)) goto out_fail; if (!read_string(system_addr, system, 128)) goto out_fail; /* Enlarge event types array when need */ if (nr_event_types >= max_types) { void *tmp; max_types = 2 * nr_event_types; tmp = realloc(event_types, sizeof(*event_types) * max_types); if (tmp == NULL) goto out_fail; event_types = tmp; } /* Create a event type */ aevent_type = malloc(sizeof(*aevent_type)); if (aevent_type == NULL) goto out_fail; aevent_type->system = strdup(system); aevent_type->name = strdup(name); aevent_type->id = id; aevent_type->nfields = 0; aevent_type->fields = NULL; if (aevent_type->system == NULL || aevent_type->name == NULL) goto out_fail_free_aevent_type; if (ftrace_init_event_type(call, aevent_type) < 0) goto out_fail_free_aevent_type; if (!strcmp("ftrace", aevent_type->system)) 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; if ((unsigned)id < MAX_CACHE_ID) event_type_cache[id] = aevent_type; /* Advance to the next event type */ read_value(event, event, list_head, next); } return 0; out_fail_free_aevent_type: free(aevent_type->system); free(aevent_type->name); free(aevent_type); out_fail: ftrace_destroy_event_types(); 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 < 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; } static int ftrace_dump_event_type(struct event_type *t, const char *path) { char format_path[PATH_MAX]; FILE *out; int i; snprintf(format_path, sizeof(format_path), "%s/format", path); out = fopen(format_path, "w"); if (out == NULL) return -1; fprintf(out, "name: %s\n", t->name); fprintf(out, "ID: %d\n", t->id); fprintf(out, "format:\n"); for (i = 0; i < t->nfields; i++) { struct ftrace_field *f = &t->fields[i]; fprintf(out, "\tfield:%s %s;\toffset:%d;\tsize:%d;\n", f->type, f->name, f->offset, f->size); } /* TODO */ fprintf(out, "\nprint fmt: \"unknow fmt from dump\"\n"); fclose(out); return 0; } static int ftrace_dump_event_types(const char *events_path) { int i; for (i = 0; i < nr_event_types; i++) { char path[PATH_MAX]; struct event_type *t = event_types[i]; snprintf(path, sizeof(path), "%s/%s", events_path, t->system); if (try_mkdir(path, 0755) < 0) return -1; snprintf(path, sizeof(path), "%s/%s/%s", events_path, t->system, t->name); if (try_mkdir(path, 0755) < 0) return -1; if (ftrace_dump_event_type(t, path) < 0) return -1; } return 0; } struct ring_buffer_per_cpu_stream { ulong *pages; void *curr_page; int available_pages; 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) { unsigned i, count = 0; s->curr_page = malloc(PAGESIZE()); if (s->curr_page == NULL) return -1; s->pages = malloc(sizeof(ulong) * (pages + 1)); if (s->pages == NULL) { free(s->curr_page); return -1; } s->pages[count++] = cpu_buffer->reader_page; if (cpu_buffer->reader_page == cpu_buffer->commit_page) goto pages_done; i = cpu_buffer->head_page_index; for (;;) { s->pages[count++] = cpu_buffer->pages[i]; if (cpu_buffer->pages[i] == cpu_buffer->commit_page) break; i++; if (i == pages) i = 0; if (i == cpu_buffer->head_page_index) { /* cpu_buffer->commit_page may be corrupted */ break; } } pages_done: s->available_pages = count; 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); free(s->pages); } 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->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->available_pages) return -1; again: if ((s->curr_page_indx == -1) || (s->offset >= s->commit)) { s->curr_page_indx++; if (s->curr_page_indx == s->available_pages) return -1; if (ring_buffer_per_cpu_stream_get_page(s) < 0) { s->curr_page_indx = s->available_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 (!global_buffers[cpu].kaddr) continue; if (cpulist && !cpulist[cpu]) 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->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 (!global_buffers[cpu].kaddr) 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); } static int dump_saved_cmdlines(const char *dump_tracing_dir) { char path[PATH_MAX]; FILE *out; int i; struct task_context *tc; snprintf(path, sizeof(path), "%s/saved_cmdlines", dump_tracing_dir); out = fopen(path, "w"); if (out == NULL) return -1; tc = FIRST_CONTEXT(); for (i = 0; i < RUNNING_TASKS(); i++) fprintf(out, "%d %s\n", (int)tc[i].pid, tc[i].comm); fclose(out); return 0; } static void ftrace_dump(int argc, char *argv[]) { int c; int dump_meta_data = 0; int dump_symbols = 0; char *dump_tracing_dir; char path[PATH_MAX]; int ret; while ((c = getopt(argc, argv, "sm")) != EOF) { switch(c) { case 's': dump_symbols = 1; break; case 'm': dump_meta_data = 1; break; default: cmd_usage(pc->curcmd, SYNOPSIS); return; } } if (argc - optind == 0) { dump_tracing_dir = "dump_tracing_dir"; } else if (argc - optind == 1) { dump_tracing_dir = argv[optind]; } else { cmd_usage(pc->curcmd, SYNOPSIS); return; } ret = mkdir(dump_tracing_dir, 0755); if (ret < 0) { if (errno == EEXIST) error(INFO, "mkdir: %s exists\n", dump_tracing_dir); return; } snprintf(path, sizeof(path), "%s/per_cpu", dump_tracing_dir); if (try_mkdir(path, 0755) < 0) return; if (ftrace_dump_buffers(path) < 0) return; if (dump_meta_data) { /* Dump event types */ snprintf(path, sizeof(path), "%s/events", dump_tracing_dir); if (try_mkdir(path, 0755) < 0) return; if (ftrace_dump_event_types(path) < 0) return; /* Dump pids with corresponding cmdlines */ if (dump_saved_cmdlines(dump_tracing_dir) < 0) return; } if (dump_symbols) { /* Dump all symbols of the kernel */ fprintf(fp, "\n-s option hasn't been implemented.\n"); fprintf(fp, "symbols is not dumpped.\n"); fprintf(fp, "You can use `sym -l > %s/kallsyms`\n\n", dump_tracing_dir); } } 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) { u64 value = f->op(f, data); 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); else event_printf("%llu", (unsigned long long)value); } else if (f->op == access_string_local) { int size = 0; if (f->size == 4) size = *(int32_t *)(data + f->offset) >> 16; 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 */ } } 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) { if (argcnt == 1) show_basic_info(); else if (!strcmp(args[1], "dump")) ftrace_dump(argcnt - 1, args + 1); else if (!strcmp(args[1], "show")) 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", "[ <show [-c <cpulist>] [-f [no]<flagname>]> | <dump [-sm] <dest-dir>> ]", "trace", " shows the current tracer and other informations.", "", "trace show [ -c <cpulist> ] [ -f [no]<flagename> ]", " 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 dump [-sm] <dest-dir>", " dump ring_buffers to dest-dir. Then you can parse it", " by other tracing tools. The dirs and files are generated", " the same as debugfs/tracing.", " -m: also dump metadata of ftrace.", " -s: also dump symbols of the kernel <not implemented>.", NULL }; static struct command_table_entry command_table[] = { { "trace", cmd_ftrace, help_ftrace, 0 }, { NULL, 0, 0, 0 } }; static int ftrace_initialized; int _init(void) { if (ftrace_init() < 0) return 0; ftrace_initialized = 1; register_extension(command_table); return 1; } int _fini(void) { if (ftrace_initialized) ftrace_destroy(); return 1; }