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;//清空tracerecho 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 | }
