ftrace中tracepoint和event trace的使用

例子

这篇文章https://www.ibm.com/developerworks/cn/linux/1609_houp_ftrace/index.html 对tracepoint和event trace都说的很清晰了，这里就不做赘述了，主要来看一下kernel里的一个例子。

先看一下抓的log和命令
命令：分别用3个bat完成

1. 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
   

2. cat trace

   set tracing_dir=/sys/kernel/debug
   adb wait-for-device
   adb pull %tracing_dir%/tracing/trace %CD%
   pause
   

3. 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