Ftrace的部分使用方法
2024-10-09 04:21:13
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
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影响了底电流的稳定。
二、trace function 和function_graph
需要使用这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: <stack trace>
=> 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
最新文章
- JavaScript 变量声明提前
- MMORPG大型游戏设计与开发（part6 of net）
- iostat命令详解
- poj1458 Common Subsequence ——最长公共子序列
- table设置滚动条
- CentOS 使用yum命令安装出现错误提示”could not retrieve mirrorlist http://mirrorlist.centos.org ***”
- asp.net错误日志写入
- SpringMVC的@ModelAttribute注解简单使用（用户修改信息）
- iOS实现视频和图片的上传
- 实现基于Keepalived高可用集群网站架构的多种方法
- 详解MySQL表空间以及ibdata1文件过大问题
- selenium如何屏蔽谷歌浏览器弹出的通知
- Constructing Roads-最小生成树(kruskal)
- Python-ccs动画及阴影
- [BZOJ 1652][USACO 06FEB]Treats for the Cows 题解（区间DP）
- 原生JS实现bind()函数
- react事件机制
- Html5学习3（拖放、Video（视频）、Input类型(color、datetime、email、month 、number 、range 、search、Tel、time、url、week )）
- FW: git internal
- 【数论】【组合数】【快速幂】【乘法逆元】洛谷 P2265 路边的水沟
热门文章
- 【Kafka】Kafka集群基础操作！新手上路必备~
- webpack4使用出现ERROR in Template execution failed: ReferenceError: HtmlwebpackPlugin is not defined
- netty零基础入门
- tp5.1的事务操作
- 使用github作为maven仓库存放发布自己的jar包依赖 实现多个项目公共部分代码的集中，避免团队中多个项目之间代码的复制粘贴
- git的日常使用
- ios中fixed元素在滚动布局中的延时渲染问题
- MySQL用户、库、表(单/多)操作
- java 字符串转为list
- Python 图像处理 OpenCV （4）：图像算数运算以及修改颜色空间