ftrace主要是用于调试linux kernel调度相关的一个工具，也可用于分析部分kernel性能问题。

相关ftrace的介绍可以参考：kernel/msm-4.9/Documentation/trace/ftrace.txt 以及同级目录下的其他介绍文件。

kernel.org的ftrace文档也可以参考（信息较多）：https://www.kernel.org/doc/html/latest/trace/ftrace.html

谷歌官网的ftrace使用教程（请自带梯子）：https://source.android.google.cn/devices/tech/debug/ftrace

IBM developer的blog（介绍每个跟踪器，并且写了如何看ftrace的log，很有用，很有用，很有用）：https://www.ibm.com/developerworks/cn/linux/l-cn-ftrace2/index.html

trace event作为ftrace的一部分，它主要通过已有函数插桩的tracepoint，来跟踪相关事件。

例如，在进程调度关键函数：__schedule()中：

static void __sched notrace __schedule(bool preempt)
{
…
if (likely(prev != next)) {
if (!prev->on_rq)
prev->last_sleep_ts = wallclock;

    update\_task\_ravg(prev, rq, PUT\_PREV\_TASK, wallclock, );  
    update\_task\_ravg(next, rq, PICK\_NEXT\_TASK, wallclock, );  
    rq->nr\_switches++;  
    rq->curr = next;  
    ++\*switch\_count;

    **trace\_sched\_switch(preempt, prev, next);**  
    rq = context\_switch(rq, prev, next, cookie); /\* unlocks the rq \*/  
} else {  
    update\_task\_ravg(prev, rq, TASK\_UPDATE, wallclock, );  
    lockdep\_unpin\_lock(&rq->lock, cookie);  
    raw\_spin\_unlock\_irq(&rq->lock);  
}  

…
}

利用trace event，我们能够监控某些事件，是否发生；或者在某段时间内，发生了什么。

案例：在dim idle下，耗流偏大约10mA。

dim idle是屏幕亮着，但亮度最低，系统进入idle状态，而未进入深度休眠的状态。

1、在抓取了power waveform对比正常的机器，发生耗流波形的bottom与正常的相似。但是耗流bottom很不稳定。

（异常）

（正常）

2、在检查所有外设后，并未发现有明显漏电。

3、此时，就利用ftrace的trace event，抓取在此情况下，系统到底在运行什么。

抓取方法：

Step

Connect USB and execute below commands one by one , some times all commands in batch may not work due to adb file system issues
Verify Buffer size is reflected as the one that is set

adb shell "echo 0 > /sys/kernel/debug/tracing/tracing_on"
adb shell "cat /sys/kernel/debug/tracing/tracing_on"
adb shell "echo 150000 > /sys/kernel/debug/tracing/buffer_size_kb"
adb shell "cat /sys/kernel/debug/tracing/buffer_size_kb"

adb shell "echo > /sys/kernel/debug/tracing/set_event"
adb shell cat /sys/kernel/debug/tracing/set_event
adb shell "echo > /sys/kernel/debug/tracing/trace"
adb shell cat /sys/kernel/debug/tracing/trace
adb shell sync

Step

Enable below trace events

adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/cpu_idle/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/cpu_frequency/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/cpu_frequency_switch_start/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/*/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_enq_deq_task/enable"

adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_bus/bus_update_request/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/clk/clk_set_rate/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/clk/clk_enable/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/clk/clk_disable/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/bw_hwmon_update/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/bw_hwmon_meas/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/memlat_dev_meas/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/memlat_dev_update/enable"

adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/cpu_idle/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/cpu_frequency/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/power/cpu_frequency_switch_start/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/*/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/sched/sched_enq_deq_task/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/cluster_enter/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/cluster_exit/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/cluster_pred_hist/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/cluster_pred_select/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/cpu_idle_enter/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/cpu_idle_exit/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/cpu_power_select/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/cpu_pred_hist/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/msm_low_power/cpu_pred_select/enable"

adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/adreno_cmdbatch_queued/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/adreno_cmdbatch_submitted/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/adreno_cmdbatch_retired/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_gpubusy/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_pwr_request_state/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_pwr_set_state/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_pwrstats/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_buslevel/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_pwrlevel/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_clk/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_bus/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_rail/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/dispatch_queue_context/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_user_pwrlevel_constraint/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_clock_throttling/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_constraint/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/adreno_gpu_fault/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/adreno_cmdbatch_fault/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/adreno_cmdbatch_sync/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_issueibcmds/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_context_create/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_context_destroy/enable"
adb shell "echo 1 > /sys/kernel/debug/tracing/events/kgsl/kgsl_context_detach/enable"
adb shell "echo 1 > /d/tracing/events/msm_bus/bus_update_request/enable"
adb shell "echo 1 > /d/tracing/events/msm_bus/bus_agg_bw/enable"

Step Verify the trace events and also remove any previous trace file
adb shell cat /sys/kernel/debug/tracing/set_event
adb shell rm /data/local/trace.txt

Step : Start Usecase, Execute below commands with usb and disconnect usb within seconds

adb shell
cd /d/tracing
sleep && echo > tracing_on && echo "" > trace && echo > tracing_on && sleep && echo > tracing_on && cat trace > /data/local/trace.txt &

Step : After seconds, re-connect usb and pull the trace file

adb pull /data/local/trace.txt

4、我们找到了qsee_logger在每60ms，就会运行一次。这个是一个debug qsee的log工具，应该在版本中剔除。

     <idle>-     \[\] dns3 17167.350289: sched\_wakeup: comm=qsee\_logger pid= prio= target\_cpu=  
      <idle>-     \[\] dns3 17167.410357: sched\_wakeup: comm=qsee\_logger pid= prio= target\_cpu=  
      <idle>-     \[\] dns3 17167.470370: sched\_wakeup: comm=qsee\_logger pid= prio= target\_cpu=  
      <idle>-     \[\] dns3 17167.538874: sched\_wakeup: comm=qsee\_logger pid= prio= target\_cpu=  
      <idle>-     \[\] dns3 17167.608888: sched\_wakeup: comm=qsee\_logger pid= prio= target\_cpu=  
      <idle>-     \[\] dns3 17167.671269: sched\_wakeup: comm=qsee\_logger pid= prio= target\_cpu=

5、最后使用performance ROM，验证pass。再安装qsee_logger，又出现bottom耗流不稳定的waveform。但是平均耗流仍然会比之前差的时候好。

所以，得出结论：1. qsee_logger导致bottom耗流不稳定，影响耗流

　　　　　　　　2. 非performance ROM也影响了耗流

在此案例中，我们利用了trace event查看了系统非休眠情况下，cpu调度的相关事件，并且找出了qsee_logger影响了底电流的稳定。

需要使用这2个功能，内核配置中需要添加以下内容：CONFIG_DYNAMIC_FTRACE=y、CONFIG_FUNCTION_TRACER=y、CONFIG_IRQSOFF_TRACER=y、CONFIG_FUNCTION_PROFILER=y 和 CONFIG_PREEMPT_TRACER=y

1）trace function可以设定自己需要监测的函数，并且可以打印出其调用栈。

查看tracer，验证是否生效。

cat /d/tracing/available_tracers
blk function_graph preemptirqsoff preemptoff irqsoff function nop

1. 由于编译器有时会对函数进行重命名，因此通过使用以下命令确认（这里用例为：htc_batt_schedule_batt_info_update，看到确实后缀加了.part.8）：

cat /d/tracing/available_filter_functions | grep htc_batt_schedule_batt_info_update
htc_batt_schedule_batt_info_update.part.

2. 确认存在之后，将其用作 ftrace 过滤器：

echo htc_batt_schedule_batt_info_update.part. > /d/tracing/set_ftrace_filter

3. 开启函数分析器：

echo function > /d/tracing/current_tracer

4. 开启堆栈跟踪：

echo func_stack_trace > /d/tracing/trace_options

5. 增加缓冲区大小：

echo > /d/tracing/buffer_size_kb

6. 最后开启抓取，抓完后关闭，并获取记录文件：

echo > /d/tracing/trace_on
执行复现问题的动作
echo > /d/tracing/trace_on
cat /d/tracing/trace > /data/local/tmp/trace

我们可以从抓取的文件中可以看到什么时刻会调用到监测的函数，并会打印出调用栈：

       <...>-  \[\] ...  6384.885600: htc\_batt\_schedule\_batt\_info\_update.part. <-htc\_battery\_info\_update  
       <...>-  \[\] ...  6384.885612: <stack trace>  

=> smb2_batt_get_prop
=> power_supply_get_property
=> status_change_work
=> process_one_work
=> worker_thread
=> kthread
=> ret_from_fork
…
…
kworker/:- [] … 6395.535869: htc_batt_schedule_batt_info_update.part. <-htc_battery_info_update kworker/:- [] … 6395.535880:
=> smb2_usb_set_prop
=> power_supply_set_property
=> dwc3_msm_gadget_vbus_draw
=> dwc3_msm_vbus_draw_work
=> process_one_work
=> worker_thread
=> kthread
=> ret_from_fork

2）function_graph 是将调用栈打印出来，并且会显示每个阶段的运行的用时。这对于分析一些内核造成的卡顿问题有所帮助。

在上面那些config基础上，还需要打开配置：CONFIG_FUNCTION_GRAPH_TRACER=y

1. 设置tracer：

echo function_graph > /d/tracing/current_tracer

2. 最后开启抓取，抓完后关闭，并获取记录文件（设置buffer等和上面类似，不赘述）：

echo > /d/tracing/trace_on
执行复现问题的动作
echo > /d/tracing/trace_on
cat /d/tracing/trace > /data/local/tmp/trace

如下，我们可以看到每天函数的执行用时，这个时间是包含了sleep time的，所以可以用来定位系统延迟发生在哪个函数中。：

# tracer: function_graph

CPU DURATION FUNCTION CALLS

| | | | | | |

) + 76.615 us | } /* vfs_open */
) 0.156 us | open_check_o_direct();
) | terminate_walk() {
) 0.104 us | drop_links.isra.();
) | dput() {
) | __might_sleep() {
) 0.156 us | ___might_sleep();
) 3.750 us | }
) 0.105 us | __rcu_read_lock();
) 0.156 us | __rcu_read_unlock();
) + 17.396 us | }
) | mntput() {
) | mntput_no_expire() {
) 0.156 us | __rcu_read_lock();
) 0.833 us | preempt_count_add();
) 0.208 us | preempt_count_sub();
) 0.157 us | __rcu_read_unlock();
) + 18.229 us | }
) + 21.875 us | }
) | dput() {
) | __might_sleep() {
) 0.157 us | ___might_sleep();
) 3.854 us | }
) 0.104 us | __rcu_read_lock();
) 0.156 us | __rcu_read_unlock();
) + 15.990 us | }

其中计时前面的符号是一种提醒，让我们能注意到哪些地方的用时比较长，可能存在问题：

• means that the function exceeded usecs.
  ! means that the function exceeded usecs.
  # means that the function exceeded usecs.
  * means that the function exceeded msecs.
  @ means that the function exceeded msecs.
  $ means that the function exceeded sec.

3）动态ftrace

由于上面两种方法都会监测很多其他函数，会对系统造成较大负担。所以，需要使用动态过滤监测函数的方式。

如果我们想只跟踪特定函数，可以把需要配置跟踪的函数写入到节点：

echo htc_batt_schedule_batt_info_update.part. > /d/tracing/set_ftrace_filter ------- function tracer
echo htc_batt_schedule_batt_info_update.part. > /d/tracing/set_graph_function ------ function_graph tracer

或者想把一些函数排除在外，可以写入如下节点：

/sys/kernel/debug/tracing/set_ftrace_notrace ------- function tracer
/sys/kernel/debug/tracing/set_graph_notrace ------ function_graph tracer

BTW，trace抓取之后，想再次抓取，默认是会把上次抓取的也包含在内的。所以，如果不需要上一次的信息，需要清空trace之后，重新再开始抓取：

echo '' > /d/tracing/trace