|
介绍 ?最早ftrace是一个function tracer，仅能够记录内核的函数调用流程。 如今ftrace已经成为一个framework，采用plugin的方式支持开发人员添加更多种类的trace功能。 trace 类型 ?传统 Tracer 对所有的function进行统计，不同的tracer对应不同的分析策略 function ---trace all kernel functions function_graph ---和function类似，但以调用图形式显示 wakeup_rt ---针对rt任务的延时（kernel任务） wakeup ---针对非rt任务延时情况 preemptirqsoff ---关抢占关中断延时 preemptoff ---关抢占延时 irqsoff ---关中断延时 Non-Tracer Tracer 在系统特定流程中增加定制化的trace代码 Max Stack Tracer ---记录一段时间的最大栈深度 Profiling (branches / unlikely / likely / Functions) ---分支性能统计分析 Event tracing ---触发trace的系统特定事件,跟踪event前，需要把current_tracer设置为nop kernel配置 ?Kernel hacking
--->-*- Debug Filesystem
Kernel hacking
--->Tracers
[*] Interrupts-off Latency Tracer ---关中断延时统计
[*] Scheduling Latency Tracer ---调度延时统计
-*- Trace process context switches ---进程context切换
[*] Trace boot initcalls ---根据__init__ function
[*] Trace likely/unlikely profiler ---分支性能统计
[*] Profile all if conditionals ---if分支性能分析
[*] Trace likely/unlikely instances ---likely/unlikely分支性能分析
[*] Trace max stack ---检测最大堆栈
[-] enable/disable ftrace tracepoints dynamically ---全部function的消耗较大,某些cpu上会导致系统瘫痪，dynamic function会减缓影响
ftrace initialization ?mount -t debugfs debugfs /sys/kernel/debug or mount -t debugfs debugfs /d/ (if there is a symbol linking named /d to /sys/kernel/debug) 目录说明 ?available_events ---所有可用的events available_filter_functions ---所有可用的filter_function available_tracers ---可用的tracers buffer_size_kb ---保存trace的buffer current_tracer ---设置或显示当前的tracer dyn_ftrace_total_info ---dyn_ftrace的个数 events ---available_events的具体信息，dir形式 options ---trace_options的具体信息，dir形式 set_event ---设置要监视的event set_ftrace_filter ---设置跟踪的funtion （dynamic ftrace） set_ftrace_notrace ---设置不跟踪的funtion （dynamic ftrace） set_ftrace_pid ---设置要跟踪的单个线程id set_graph_function ---设置function graph tracer的触发函数 trace ---trace输出 trace_options ---trace显示内容控制 trace_pipe ---pipe形式的trace输出 tracing_cpumask ---设定trace在哪个cpu采集 tracing_enabled ---使能trace tracing_max_latency ---刚进行过的Tracer统计中，最大的Latency tracing_on ---trace开始/停止 使用说明 ?trace note: /d is a symbol link to /sys/kernel/debug echo 0 > tracing_on echo > trace echo tracename > /d/tracing/current_tracer echo 1 > /d/tracing/tracing_enabled echo 1 > tracing_on event echo nop > /d/tracing/current_tracer echo 0 > tracing_on echo > trace echo eventname > set_event echo 1 > /d/tracing/tracing_enabled echo 1 > tracing_on Max Stack Tracer
Profiling echo 0 > tracing_on echo > trace echo branch > current_tracer echo 1 > /d/tracing/tracing_enabled echo 1 > tracing_on function_profile usage： echo 1 > function_profile_enabled ---> 开始统计 echo 0 > function_profile_enabled ---> 停止统计 output: root@android:/sys/kernel/debug/tracing/trace_stat # ls function0 function1 function2 function3 root@android:/sys/kernel/debug/tracing/trace_stat # cat function0 Function Hit Time Avg s^2 -------- --- ---- --- --- __schedule 242056 4407687818 us 18209.37 us 44942531 us schedule 237186 4406753390 us 18579.31 us 39064941 us poll_schedule_timeout 110877 2338559630 us 21091.47 us 150541881 us schedule_hrtimeout_range 109471 2338533225 us 21362.12 us 146683831 us schedule_hrtimeout_range_clock 109471 2338505455 us 21361.87 us 146683357 us do_sys_poll 202048 2055973654 us 10175.66 us 65412798 us trace 输出标识说明 ?irqs-off: 'd' --- 关闭中断, '.' --- 没关闭中断, 'X' --- 当前体系不支持识别irqflag need-resched: 'N' --- need_resched被设置, '.' --- need_resched未设置, hardirq/softirq: 'H' --- 软中断过程中发生的硬中断. 'h' --- 硬中断 's' --- 软中断 '.' --- 进程上下文 delay: '!' --- 大于preempt_mark_thresh (default 100us) '+' --- 1us ' ' --- 小于或等于1us. 示例 ?查看中断情况 ?current_tracer: nop set_event:irq #
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [000] d.h2 13868.971337: irq_handler_exit: irq=87 ret=unhandled
<idle>-0 [000] d.h2 13868.971342: irq_handler_entry: irq=87 name=dwc_otg
<idle>-0 [000] dNh2 13868.971358: irq_handler_exit: irq=87 ret=handled
<idle>-0 [000] dNh2 13868.971364: irq_handler_entry: irq=87 name=dwc_otg_hcd:usb1
<idle>-0 [000] dNh2 13868.971368: irq_handler_exit: irq=87 ret=unhandled
<idle>-0 [000] d.h3 13868.971482: irq_handler_entry: irq=87 name=dwc_otg
<idle>-0 [000] d.h3 13868.971486: irq_handler_exit: irq=87 ret=unhandled
<idle>-0 [000] d.h3 13868.971491: irq_handler_entry: irq=87 name=dwc_otg
...
查看调度 ?current_tracer: nop set_event:sched # _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
adbd-379 [000] d..3 14010.891592: sched_switch: prev_comm=adbd prev_pid=379 prev_prio=120 prev_state=S ==> next_comm=adbd next_pid=375 next_prio=120
adbd-375 [000] d..3 14010.891696: sched_stat_runtime: comm=adbd pid=375 runtime=114856 [ns] vruntime=171426970635 [ns]
adbd-375 [000] d..3 14010.891703: sched_switch: prev_comm=adbd prev_pid=375 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
<idle>-0 [000] d.h4 14010.891902: sched_wakeup: comm=engpcclient pid=374 prio=100 success=1 target_cpu=000
<idle>-0 [000] d..3 14010.892013: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=engpcclient next_pid=374 next_prio=100
engpcclient-374 [000] d..3 14010.892081: sched_stat_runtime: comm=engpcclient pid=374 runtime=179336 [ns] vruntime=171423775993 [ns]
engpcclient-374 [000] d..3 14010.892088: sched_switch: prev_comm=engpcclient prev_pid=374 prev_prio=100 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
...
查看延时情况 ?current_tracer:wakeup set_event: # tracer: wakeup # # wakeup latency trace v1.1.5 on 3.4.5-00014-g6b067cd # -------------------------------------------------------------------- # latency: 14558 us, #245/1075250, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:1) # ----------------- # | task: WindowManagerPo-440 (uid:1000 nice:-2 policy:0 rt_prio:0) # ----------------- # => started at: add_preempt_count # => ended at: stop_critical_timings # # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| / delay # cmd pid ||||| time | caller # \ / ||||| \ | / Compiler-416 0d..4 1us+: 416:120:R + [001] 440:118:R WindowManagerPo Compiler-416 0d..4 6us!: probe_wakeup <-probe_wakeup ##### CPU 1 buffer started #### kworker/-32613 1d..1 12460us+: serial_sprd_console_putchar <-uart_console_write kworker/-32613 1d..1 12545us+: serial_sprd_console_putchar <-uart_console_write kworker/-32613 1d..1 12632us+: serial_sprd_console_putchar <-uart_console_write kworker/-32613 1d..1 12719us+: serial_sprd_console_putchar <-uart_console_write kworker/-32613 1d..1 12807us+: serial_sprd_console_putchar <-uart_console_write ... kworker/-32613 1d..1 13936us!: serial_sprd_console_putchar <-uart_console_write kworker/-32613 1d..1 14110us : _raw_spin_unlock <-serial_sprd_console_write kworker/-32613 1d..1 14112us+: sub_preempt_count <-_raw_spin_unlock kworker/-32613 1d... 14114us+: ram_console_write <-__call_console_drivers kworker/-32613 1d... 14181us+: _call_console_drivers <-console_unlock kworker/-32613 1d... 14183us : _raw_spin_lock_irqsave <-console_unlock kworker/-32613 1d... 14184us : __raw_spin_lock_irqsave <-_raw_spin_lock_irqsave kworker/-32613 1d... 14186us+: add_preempt_count <-__raw_spin_lock_irqsave kworker/-32613 1d..1 14188us : _raw_spin_unlock <-console_unlock ... 动态ftrace ?current_tracer: function set_ftrace_filter: 'hrtimer_*' set_event: tracer: function
#
# entries-in-buffer/entries-written: 238/17293 #P:1
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [000] d..2 68326.255274: hrtimer_force_reprogram <-__remove_hrtimer
<idle>-0 [000] d.h1 68326.263364: hrtimer_interrupt <-__gptimer_interrupt
<idle>-0 [000] d.h1 68326.263372: hrtimer_wakeup <-__run_hrtimer
<idle>-0 [000] dN.1 68326.263402: hrtimer_cancel <-tick_nohz_idle_exit
<idle>-0 [000] dN.1 68326.263405: hrtimer_try_to_cancel <-hrtimer_cancel
<idle>-0 [000] dN.2 68326.263409: hrtimer_force_reprogram <-__remove_hrtimer
<idle>-0 [000] dN.1 68326.263451: hrtimer_forward <-tick_nohz_idle_exit
<idle>-0 [000] dN.1 68326.263455: hrtimer_start_range_ns <-tick_nohz_idle_exit
engpcclient-374 [000] .... 68326.263527: hrtimer_cancel <-do_nanosleep
engpcclient-374 [000] .... 68326.263530: hrtimer_try_to_cancel <-hrtimer_cancel
...
查看block设备 ?current_tracer: nop set_event:block # _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
flush-179:0-364 [000] ...1 69812.711927: block_bio_remap: 179,0 W 3449337 + 8 <- (179,25) 285168
flush-179:0-364 [000] ...1 69812.711946: block_bio_queue: 179,0 W 3449337 + 8 [flush-179:0]
flush-179:0-364 [000] ...1 69812.711981: block_getrq: 179,0 W 3449337 + 8 [flush-179:0]
flush-179:0-364 [000] ...1 69812.711992: block_plug: [flush-179:0]
flush-179:0-364 [000] d..2 69812.712024: block_rq_insert: 179,0 W 0 () 3449337 + 8 [flush-179:0]
flush-179:0-364 [000] dN.2 69812.712071: block_unplug: [flush-179:0] 1
mmcqd/0-99 [000] d..2 69812.712115: block_rq_issue: 179,0 W 0 () 3449337 + 8 [mmcqd/0]
flush-179:0-364 [000] ...1 69812.725229: block_bio_remap: 179,0 W 3444665 + 8 <- (179,25) 280496
flush-179:0-364 [000] ...1 69812.725235: block_bio_queue: 179,0 W 3444665 + 8 [flush-179:0]
flush-179:0-364 [000] ...1 69812.725252: block_getrq: 179,0 W 3444665 + 8 [flush-179:0]
flush-179:0-364 [000] ...1 69812.725257: block_plug: [flush-179:0]
flush-179:0-364 [000] d..2 69812.725280: block_rq_insert: 179,0 W 0 () 3444665 + 8 [flush-179:0]
flush-179:0-364 [000] d..2 69812.725289: block_unplug: [flush-179:0] 1
mmcqd/0-99 [000] d..2 69812.730878: block_rq_issue: 179,0 W 0 () 3444665 + 8 [mmcqd/0]
...
查看signal ?current_tracer: nop set_event:signal # _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<...>-5493 [000] dN.3 70613.830631: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=3404 grp=1 res=0
sh-3404 [000] d..2 70613.830667: signal_deliver: sig=17 errno=0 code=262145 sa_handler=b6f2b105 sa_flags=0
<...>-5494 [000] dN.3 70616.399782: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=3404 grp=1 res=0
sh-3404 [000] d..2 70616.399818: signal_deliver: sig=17 errno=0 code=262145 sa_handler=b6f2b105 sa_flags=0
<...>-5496 [000] dN.3 70618.357072: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=5495 grp=1 res=0
<...>-5495 [000] d..2 70618.357123: signal_deliver: sig=17 errno=0 code=262145 sa_handler=b6f87105 sa_flags=0
<...>-5495 [000] d..3 70618.357885: signal_generate: sig=17 errno=0 code=262145 comm=slog pid=165 grp=1 res=1
<...>-5500 [000] dN.3 70623.375711: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=5499 grp=1 res=0
...
查看branch ?current_tracer: bransh set_event: # TASK-PID CPU# TIMESTAMP CORRECT FUNC:FILE:LINE # | | | | | | <idle>-0 [000] 55415.397835: [ ok ] read_seqretry:seqlock.h:110 <idle>-0 [000] 55415.397848: [ ok ] native_sched_clock:tsc.c:55 <idle>-0 [000] 55415.397859: [ ok ] native_sched_clock:tsc.c:55 ... <idle>-0 [000] 55415.398682: [ ok ] __local_bh_enable:softirq.c:138 <idle>-0 [000] 55415.398695: [ ok ] update_wall_time:timekeeping.c:789 <idle>-0 [000] 55415.398710: [ MISS ] timekeeping_adjust:timekeeping.c:711 <idle>-0 [000] 55415.398725: [ ok ] update_wall_time:timekeeping.c:839 案例 ? |
|
|
