ftrace跟踪内核_ftrace追踪内核函数调用

前言：在追踪内核的网络栈时，经常会出现复杂的条件分支，导致分不清报文处理的重要流程，本文介绍的ftrace则能够追踪记录函数的调用流程，非常方便的用以分析代码。

一. ftrace简单介绍

​ftrace是内核提供的一种调试工具，可以对内核发生的事件进行记录，比如函数调用，进程切换，中断开关等。他使用debugfs与文本进行交互， 显示的结果非常直观。更多的ftrace是什么的主题，以及如何实现的，可以参考wiki或者kernel自带的Docement/trace/ftrace.txt文档。

​本篇主要介绍其中的一个tracer：function graph tracer，他可以勾勒出函数的调用过程，花费的时间等。

This tracer is useful in several situations:

you want to find the reason of a strange kernel behavior and

need to see what happens in detail on any areas (or specific

ones).

you are experiencing weird latencies but it's difficult to

find its origin.

you want to find quickly which path is taken by a specific

function

you just want to peek inside a working kernel and want to see

what happens there.

这个tracer适用但不局限于以上几种场景。更多的tracer可以自行扩展。毕竟，这里主要是想追踪内核函数调用不是？😃

二. 如何使用ftrace

​在使用ftrace之前，需要内核进行支持，也就是内核需要打开编译中的ftrace相关选项，关于怎么激活ftrace选项的问题，可以google之，下面只说明重要的设置步骤：

mkdir /debug；mount -t debugs nodev /debug; /*挂载debugfs到创建的目录中去*/

cd /debug; cd tracing; /*如果没有tracing目录，则内核目前还没有支持ftrace，需要配置参数，重新编译*/。

echo nop > current_tracer;//清空tracer

echo function_graph > current_tracer;//使用图形显示调用关系

echo ip_rcv > set_graph_function;//设置过滤函数,可以设置多个

echo 1 > tracing_enabled开始追踪

追踪的结果在文件trace中，可以使用cat，vim等工具进行查看，如下图就是在追踪ip_rcv()的调用栈的结果：

34) | ip_rcv() {

34) | ip_rcv_finish() {

34) 0.513 us | ip_route_input();

34) | ip_local_deliver() {

34) | nf_hook_slow() {

34) | nf_iterate() {

34) | ipt_local_in_hook() {

34) | ipt_do_table() {

34) 0.192 us | local_bh_disable();

34) 0.191 us | _spin_lock();

34) 0.237 us | local_bh_enable();

34) 1.651 us | }

34) 2.214 us | }

34) 3.173 us | }

34) 3.667 us | }

34) | ip_local_deliver_finish() {

34) 0.180 us | raw_local_deliver();

34) | tcp_v4_rcv() {

34) 0.391 us | __inet_lookup_established();

34) 0.367 us | xfrm4_policy_check.clone.0();

34) | sk_filter() {

34) | security_sock_rcv_skb() {

34) | selinux_socket_sock_rcv_skb() {

34) 0.195 us | netlbl_enabled();

34) 0.655 us | }

34) 1.061 us | }

34) 0.176 us | local_bh_disable();

34) 0.193 us | local_bh_enable();

34) 2.176 us | }

34) 0.230 us | _spin_lock();

34) | tcp_v4_do_rcv() {

34) 0.200 us | tcp_parse_md5sig_option();

34) | tcp_rcv_established() {

34) 0.359 us | tcp_ack();

34) 0.240 us | tcp_urg();

34) | tcp_data_queue() {

34) | tcp_try_rmem_schedule() {

34) 0.334 us | __sk_mem_schedule();

34) 0.765 us | }

34) 0.212 us | skb_set_owner_r();

34) 0.350 us | tcp_event_data_recv();

34) 0.184 us | tcp_fast_path_on();

34) 0.176 us | sock_flag();

34) | sock_def_readable() {

34) 0.332 us | _read_lock();

34) | __wake_up_sync_key() {

34) 0.346 us | _spin_lock_irqsave();

34) | __wake_up_common() {

34) | pollwake() {

34) | default_wake_function() {

34) | try_to_wake_up() {

34) | task_rq_lock() {

34) 0.302 us | _spin_lock();

34) 0.796 us | }

34) 0.242 us | task_waking_fair();

34) | select_task_rq_fair() {

34) 0.232 us | select_idle_sibling();

34) 1.522 us | }

34) 0.183 us | _spin_lock();

34) | activate_task() {

34) | enqueue_task() {

34) 0.270 us | update_rq_clock();

34) | enqueue_task_fair() {

34) | enqueue_entity() {

34) 0.262 us | update_curr();

34) 0.252 us | update_cfs_load();

34) 0.548 us | account_entity_enqueue();

34) 0.189 us | update_cfs_shares();

34) 0.187 us | place_entity();

34) 0.254 us | task_of();

34) 3.405 us | }

34) 3.841 us | }

34) 4.972 us | }

34) 5.364 us | }

34) | check_preempt_curr() {

34) 0.216 us | resched_task();

34) 0.654 us | }

34) 0.189 us | _spin_unlock_irqrestore();

34) + 11.333 us | }

34) + 11.703 us | }

34) + 12.088 us | }

34) + 12.552 us | }

34) 0.219 us | _spin_unlock_irqrestore();

34) + 14.216 us | }

34) + 15.209 us | }

34) + 18.700 us | }

34) | tcp_data_snd_check() {

34) | tcp_current_mss() {

34) | tcp_established_options() {

34) 0.221 us | tcp_v4_md5_lookup();

34) 0.632 us | }

34) 1.028 us | }

34) 0.182 us | __tcp_push_pending_frames();

34) 1.771 us | }

34) | __tcp_ack_snd_check() {

34) | tcp_send_delayed_ack() {

34) | sk_reset_timer() {

34) | mod_timer() {

34) | lock_timer_base() {

34) 0.217 us | _spin_lock_irqsave();

34) 0.624 us | }

34) 0.247 us | idle_cpu();

34) 0.499 us | get_nohz_timer_target();

34) 0.274 us | internal_add_timer();

34) 0.188 us | _spin_unlock_irqrestore();

34) 3.189 us | }

34) 3.580 us | }

34) 3.985 us | }

34) 4.423 us | }

34) + 26.870 us | }

34) + 27.707 us | }

34) + 32.742 us | }

34) + 33.685 us | }

34) + 38.217 us | }

34) + 40.056 us | }

34) + 41.393 us | }