前言：在追蹤內核的網絡棧時，經常會出現復雜的條件分支，導致分不清報文處理的重要流程，本文介紹的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 | }