例子
这篇文章https://www.ibm.com/developerworks/cn/linux/1609_houp_ftrace/index.html 对tracepoint和event trace都说的很清晰了,这里就不做赘述了,主要来看一下kernel里的一个例子。
先看一下抓的log和命令
命令:分别用3个bat完成
-
enable trace
set tracing_dir=/sys/kernel/debug/tracing adb wait-for-device rem adb shell "echo ftrace > %tracing_dir%/current_tracer" adb shell "echo 1 > %tracing_dir%/tracing_on" pause
-
cat trace
set tracing_dir=/sys/kernel/debug adb wait-for-device adb pull %tracing_dir%/tracing/trace %CD% pause
-
disable ftrace
set tracing_dir=/sys/kernel/debug/tracing adb wait-for-device adb shell "echo 0 > %tracing_dir%/tracing_on" pause
log 部分
# tracer: nop
#
# entries-in-buffer/entries-written: 44493/44493 #P:8
# enabled events: ipi:ipi_exit ipi:ipi_entry ipi:ipi_raise irq:softirq_raise irq:softirq_exit irq:softirq_entry workqueue:workqueue_execute_end workqueue:workqueue_execute_start sched:sched_migrate_task sched:sched_switch sched:sched_wakeup_new sched:sched_wakeup mtk_events:sspm_ipi mtk_events:sched_update mtk_events:hps_update mtk_events:ppm_limit_callback_update mtk_events:ppm_overutil_update mtk_events:ppm_hica mtk_events:ppm_update mtk_events:gpu_freq mtk_events:irq_exit mtk_events:irq_entry mtk_events:cpu_hotplug mtk_events:tracing_on power:cpu_frequency block:block_bio_frontmerge block:block_bio_backmerge block:block_rq_issue block:block_rq_insert block:block_rq_complete block:block_rq_requeue
# kernel time now: 951651.297449
# UTC time: 2018-09-25 06:35:54.112033
# android time: 2018-09-25 06:35:54.112033
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
sh-9697 [001] ...1 951603.118943: tracing_on: ftrace is enabled caller=__vfs_write
sh-9697 [001] d..4 951603.119468: sched_update: (0)(0x7cd)
sh-9697 [001] d..4 951603.119481: ipi_raise: target_mask=00000000,00000004 (Rescheduling interrupts)
sh-9697 [001] d..4 951603.119491: sched_wakeup: comm=adbd pid=393 prio=120 success=1 target_cpu=002 state=R overutil=0
<idle>-0 [002] dn.2 951603.119677: ipi_entry: (Rescheduling interrupts)
<idle>-0 [002] dn.2 951603.119687: ipi_exit: (Rescheduling interrupts)
<idle>-0 [002] dn.3 951603.119741: sched_update: (0)(0x7dd)
<idle>-0 [002] d..3 951603.119758: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=adbd next_pid=393 next_prio=120 prev->cgrp=1 next->cgrp=1
adbd-393 [002] d..4 951603.120392: sched_update: (0)(0x7ed)
adbd-393 [002] d..4 951603.120402: ipi_raise: target_mask=00000000,00000001 (Rescheduling interrupts)
adbd-393 [002] d..4 951603.120407: sched_wakeup: comm=->transport pid=24433 prio=120 success=1 target_cpu=000 state=R overutil=0
<idle>-0 [000] dn.2 951603.120577: ipi_entry: (Rescheduling interrupts)
<idle>-0 [000] dn.2 951603.120585: ipi_exit: (Rescheduling interrupts)
<idle>-0 [000] dn.3 951603.120630: sched_update: (0)(0x7fd)
<idle>-0 [000] d..3 951603.120647: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=->t