trace-cmd - command line reader for ftrace

From:		Steven Rostedt <[e-mail]>
To:		LKML <[e-mail]>
Subject:		[ANNOUNCE][RFC] trace-cmd - command line reader for ftrace
Date:		Fri, 17 Jul 2009 10:50:59 -0400 (EDT)
Message-ID:		<[e-mail]>
Cc:		Ingo Molnar <[e-mail]>, Frederic Weisbecker <[e-mail]>, Thomas Gleixner <[e-mail]>, Peter Zijlstra <[e-mail]>, Arnaldo Carvalho de Melo <[e-mail]>, "Luis Claudio R. Goncalves" <[e-mail]>, Clark Williams <[e-mail]>, Jon Masters <[e-mail]>, Andrew Morton <[e-mail]>, Mathieu Desnoyers <[e-mail]>, Christoph Hellwig <[e-mail]>, Xiao Guangrong <[e-mail]>, Zhaolei <[e-mail]>, [e-mail], Li Zefan <[e-mail]>, Masami Hiramatsu <[e-mail]>, "Frank Ch. Eigler" <[e-mail]>, Tom Zanussi <[e-mail]>, Jason Baron <[e-mail]>, [e-mail]
Archive-link:		Article, Thread

Since using echo and cat can sometimes be annoying to set up the tracer, I've been asked several times if I could come up with a tool to do it for you. For the last few weeks I've been working on one. The most difficult job was to parse out the "print_fmt" of the format files in the event.This code is somewhat a proof of concept and is in alpha form. Although it is still very functional and useful. I can imagine that this could also be sucked into Ingo Molnar's "perf" utility.The code is here:  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.gitJust download it, go into the directory and run "make". Here's some examples of uses:(still need to be root to run the record part, but not the report).To enable all events and run some command: # ./trace-cmd record -e all ls /binThen to see the information: # ./trace-cmd reportversion = 0.5cpus=4       trace-cmd-10995 [003] 235302.428904: kmem_cache_alloc: call_site=ffffffff810df1e4 ptr=0xffff880027585a68 bytes_req=168 bytes_alloc=168 gfp_flags=GFP_KERNEL       trace-cmd-11003 [000] 235302.428909: kmalloc: call_site=ffffffff810a1740 ptr=0xffff880024150b40 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO       trace-cmd-10995 [003] 235302.428912: kmem_cache_free: call_site=ffffffff810de423 ptr=0xffff880027585a68           <...>-11000 [002] 235302.428913: kmalloc: call_site=ffffffff810a1740 ptr=0xffff8800360b9f60 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO       trace-cmd-11003 [000] 235302.428917: kfree: call_site=ffffffff810a1904 ptr=0xffff880024150b40       trace-cmd-10995 [003] 235302.428917: kmem_cache_alloc: call_site=ffffffff81049db7 ptr=0xffff88003f960f00 bytes_req=1696 bytes_alloc=1696 gfp_flags=GFP_KERNEL       trace-cmd-10995 [003] 235302.428921: kmem_cache_alloc: call_site=ffffffff8106d548 ptr=0xffff88003f97b540 bytes_req=192 bytes_alloc=192 gfp_flags=GFP_KERNELTo see just a subsystem: # ./trace-cmd record -e irq ls /binversion = 0.5cpus=4       trace-cmd-11017 [000] 235469.067157: softirq_entry: softirq=1 action=TIMER       trace-cmd-11017 [000] 235469.067161: softirq_exit: softirq=1 action=TIMER       trace-cmd-11017 [000] 235469.067162: softirq_entry: softirq=8 action=RCU       trace-cmd-11017 [000] 235469.067163: softirq_exit: softirq=8 action=RCU       trace-cmd-11016 [001] 235469.067221: softirq_entry: softirq=1 action=TIMER       trace-cmd-11016 [001] 235469.067226: softirq_exit: softirq=1 action=TIMER       trace-cmd-11016 [001] 235469.067226: softirq_entry: softirq=8 action=RCU       trace-cmd-11016 [001] 235469.067228: softirq_exit: softirq=8 action=RCUI'm only cutting the top part of the trace, where it shows the trace-cmd running. This is still alpha, and I plan on adding default code to only trace the current running command, or allow you to trace all (as it does now). But the 'ls' is still in the trace:              ls-11018 [001] 235469.118138: softirq_entry: softirq=1 action=TIMER              ls-11018 [001] 235469.118140: softirq_exit: softirq=1 action=TIMER              ls-11018 [001] 235469.118141: softirq_entry: softirq=8 action=RCU              ls-11018 [001] 235469.118142: softirq_exit: softirq=8 action=RCUTo list the available trace events: # ./trace-cmd list -eskb:kfree_skbblock:block_rq_abortblock:block_rq_insertblock:block_rq_issueblock:block_rq_requeueblock:block_rq_completeblock:block_bio_bounceblock:block_bio_completeblock:block_bio_backmergeblock:block_bio_frontmergeblock:block_bio_queueblock:block_getrqblock:block_sleeprqblock:block_plugblock:block_unplug_timerblock:block_unplug_ioblock:block_splitblock:block_remapkmem:kmallockmem:kmem_cache_allockmem:kmalloc_nodekmem:kmem_cache_alloc_nodekmem:kfreekmem:kmem_cache_freeworkqueue:workqueue_insertionworkqueue:workqueue_executionworkqueue:workqueue_creationworkqueue:workqueue_destructionirq:irq_handler_entryirq:irq_handler_exitirq:softirq_entryirq:softirq_exitsched:sched_kthread_stopsched:sched_kthread_stop_retsched:sched_wait_tasksched:sched_wakeupsched:sched_wakeup_newsched:sched_switchsched:sched_migrate_tasksched:sched_process_freesched:sched_process_exitsched:sched_process_waitsched:sched_process_forksched:sched_signal_sendYou can also trace a single trace point with one of two methods: # ./trace-cmd record -e sched:sched_wakeup ls /binOr simply: # ./trace-cmd record -e sched_wakeup ls /bin # ./trace-cmd reportversion = 0.5cpus=4              ls-11038 [003] 235806.528155: sched_wakeup: task :12 [0] success=1              ls-11038 [000] 235806.532473: sched_wakeup: task :10953 [120] success=1            sshd-10953 [000] 235806.532515: sched_wakeup: task :11038 [120] success=0       trace-cmd-11035 [000] 235806.536280: sched_wakeup: task :10809 [120] success=1       trace-cmd-11037 [001] 235806.541029: sched_wakeup: task :2854 [120] success=1       trace-cmd-11034 [003] 235806.545892: sched_wakeup: task :1 [120] success=1       trace-cmd-11037 [001] 235806.546569: sched_wakeup: task :30521 [120] success=1              ls-11038 [002] 235806.565837: sched_wakeup: task :10953 [120] success=1            sshd-10953 [000] 235806.565950: sched_wakeup: task :11038 [120] success=0            sshd-10953 [000] 235806.566039: sched_wakeup: task :11038 [120] success=0This tool also works with tracers (plugins) as well as events # ./trace-cmd list -psyscall blk kmemtrace power function_graph mmiotrace wakeup_rt wakeup preemptirqsoff preemptoff irqsoff function sched_switch initcall nop # ./trace-cmd record -p sched_switch ls /bin # ./trace-cmd reportversion = 0.5cpus=4CPU 2 is empty       trace-cmd-11054 [001] 235985.996230: wakeup: 11054:120:0  ==+ 11059:120:0 [001]       trace-cmd-11054 [001] 235985.996236: context_switch: 11054:120:0  ==+ 11059:120:0 [001]              ls-11059 [001] 235985.996507: wakeup: 11059:120:0  ==+ 10809:120:1 [001]              ls-11059 [001] 235985.996515: context_switch: 11059:120:0  ==+ 10809:120:0 [001]         emacs-x-10809 [001] 235985.996566: context_switch: 10809:120:1  ==+ 11059:120:0 [001]              ls-11059 [001] 235986.000302: wakeup: 11059:120:1  ==+ 10953:120:1 [000]Even the function graph works: # ./trace-cmd record -p function_graph ls /bin # ./trace-cmd reportversion = 0.5cpus=4236149.191544 |   1) trace-cmd-11120 |   6.295 us   |  fget_light();236149.191544 |   0) trace-cmd-11112 |   6.370 us   |  inotify_inode_queue_event();236149.191544 |   2) trace-cmd-11118 |   6.230 us   |  fget_light();236149.191545 |   3) trace-cmd-11117 |              |  check_preempt_wakeup() {236149.191548 |   3) trace-cmd-11117 |   1.061 us   |    update_curr();236149.191550 |   1) trace-cmd-11120 |              |  do_splice_to() {236149.191550 |   2) trace-cmd-11118 |              |  do_splice_to() {236149.191551 |   0) trace-cmd-11112 |   1.098 us   |  __fsnotify_parent();236149.191551 |   3) trace-cmd-11117 |   0.959 us   |    wakeup_preempt_entity();236149.191551 |   1) trace-cmd-11120 |              |    rw_verify_area() {236149.191552 |   2) trace-cmd-11118 |              |    rw_verify_area() {236149.191552 |   1) trace-cmd-11120 |              |      security_file_permission() {236149.191552 |   3) trace-cmd-11117 |   0.831 us   |    resched_task();I did add one filter to the output. That was --cpu. # ./trace-cmd report --cpu 0version = 0.5cpus=4236149.191544 |   0) trace-cmd-11112 |   6.370 us   |  inotify_inode_queue_event();236149.191551 |   0) trace-cmd-11112 |   1.098 us   |  __fsnotify_parent();236149.191553 |   0) trace-cmd-11112 |   0.946 us   |  inotify_dentry_parent_queue_event();236149.191555 |   0) trace-cmd-11112 |   1.138 us   |  fsnotify();236149.191558 |   0) trace-cmd-11112 |              |  sys_close() {236149.191558 |   0) trace-cmd-11112 |   0.963 us   |    _spin_lock();236149.191560 |   0) trace-cmd-11112 |   0.973 us   |    _spin_unlock();236149.191562 |   0) trace-cmd-11112 |              |    filp_close() {236149.191563 |   0) trace-cmd-11112 |   0.869 us   |      dnotify_flush();236149.191565 |   0) trace-cmd-11112 |   0.991 us   |      locks_remove_posix();236149.191567 |   0) trace-cmd-11112 |              |      fput() {236149.191568 |   0) trace-cmd-11112 |              |        __fput() {Since the latency tracers look for max latencies, I do not use the splice command and create threads to record on the fly. It simply runs the code and then records the trace file directly. The latency tracers are:  irqsoff  preemptoff  preempirqsoff  wakeup  wakeup_rt # ./trace-cmd record -p irqsoff ls /bin# ./trace-cmd report version = 0.5cpus=4# tracer: irqsoff## irqsoff latency trace v1.1.5 on 2.6.30# --------------------------------------------------------------------# latency: 60 us, #88/88, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)#    -----------------##                  _------=> CPU#            #                 / _-----=> irqs-off        #                | / _----=> need-resched    #                || / _---=> hardirq/softirq #                ||| / _--=> preempt-depth   #                |||| /                      #                |||||     delay             #  cmd     pid   ||||| time  |   caller      #     \   /      |||||   \   |   /             <idle>-0       3d..1   10us : trace_hardirqs_off_thunk <-save_args  <idle>-0       3d..1   11us : smp_apic_timer_interrupt <-apic_timer_interrupt  <idle>-0       3d..1   11us : native_apic_mem_write <-smp_apic_timer_interrupt  <idle>-0       3d..1   12us : exit_idle <-smp_apic_timer_interrupt  <idle>-0       3d..1   13us : irq_enter <-smp_apic_timer_interrupt  <idle>-0       3d..1   13us : idle_cpu <-irq_enter  <idle>-0       3d.h1   14us : tick_check_idle <-irq_enter  <idle>-0       3d.h1   14us : tick_check_oneshot_broadcast <-tick_check_idle  <idle>-0       3d.h1   15us : tick_nohz_stop_idle <-tick_check_idle  <idle>-0       3d.h1   15us : ktime_get <-tick_nohz_stop_idle  <idle>-0       3d.h1   16us : ktime_get_ts <-ktime_get  <idle>-0       3d.h1   16us : getnstimeofday <-ktime_get_ts[...]  <idle>-0       3d.h1   58us : irq_exit <-smp_apic_timer_interrupt  <idle>-0       3d..2   59us : do_softirq <-irq_exit  <idle>-0       3d..2   59us : __do_softirq <-call_softirq  <idle>-0       3d..2   60us : __local_bh_disable <-__do_softirq  <idle>-0       3d.s2   61us : __do_softirq <-call_softirq  <idle>-0       3d.s2   61us : trace_hardirqs_on <-call_softirqNote, you can disable the function tracer (which the latency tracers use) # ./trace-cmd record -p irqsoff -d ls /bin # ./trace-cmd report# ./trace-cmd report version = 0.5cpus=4# tracer: irqsoff## irqsoff latency trace v1.1.5 on 2.6.30# --------------------------------------------------------------------# latency: 48 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)#    -----------------#    | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)#    -----------------##                  _------=> CPU#            #                 / _-----=> irqs-off        #                | / _----=> need-resched    #                || / _---=> hardirq/softirq #                ||| / _--=> preempt-depth   #                |||| /                      #                |||||     delay             #  cmd     pid   ||||| time  |   caller      #     \   /      |||||   \   |   /             <idle>-0       1dN.1   38us+: tick_nohz_restart_sched_tick <-cpu_idle  <idle>-0       1dN.1   48us : tick_nohz_restart_sched_tick <-cpu_idle  <idle>-0       1dN.1   49us : trace_hardirqs_on <-cpu_idleAgain, this is very much in alpha form. It may still be very buggy, and the format of the trace.dat file may soon change. Thus it is still in [RFC] release status, and nothing is considered stable.Here's some todo's I have planned. 1) get it in a form to be used by perf (if possible) 2) add many more filters   a) More ways to filter on the report side   b) Add ways to filter on the recording side    This includes:      Using the /debug/tracing/event/*/filter files      Using the set_ftrace_filter/notrace files      Using the set_ftrace_pid      set_graph_function      enabling the backtrace functions      enabling the tracing/optionsAnd I'm sure there are many more.So, please feel free to download this code and play with it. If you find bugs, please report. If you have other ideas that are not listed above, share them.Have fun!-- Steve--To unsubscribe from this list: send the line "unsubscribe linux-kernel" inthe body of a message to [e-mail] majordomo info at  http://vger.kernel.org/majordomo-info.htmlPlease read the FAQ at  http://www.tux.org/lkml/