通过Ftrace实现高效、精确的内核调试与分析

前言：虽然之前一直听说过ftrace，但从来没将它用在实战中，在一次客户排查问题中，遇到了比较奇怪的现象，一位精通内核的朋友建议使用ftrace来定位一下。虽然那一次并没有使用ftrace，但也让我觉得，后面我们势必要提供ftrace相关的工具帮助我们在线上定位问题，所以自己也决定重新学习使用下ftrace，当然也决定写一系列的相关出来，这里就先简单介绍下ftrace。一、什么是ftrace首先我们需要知道，什么是ftrace？根据LinuxDoc

的介绍，ftrace是一个Linux内部的trace工具，能够帮助开发者和系统设计者知道内核当前正在干啥，从而更好的去分析性能问题。Ftrace能帮我们分析内核特定的事件，譬如调度，中断等，也能帮我们去追踪动态的内核函数，以及这些函数的调用栈还有栈的使用这些。它也能帮我们去追踪延迟，譬如中断被屏蔽，抢占被禁止的时间，以及唤醒一个进程之后多久开始执行的时间。可以看到，使用ftrace真的能做到对系统内核非常系统的剖析，甚至都能通过ftrace来学习Linux内核，不过在更进一步之前，我们需要学会的是-如何使用ftrace。二、如何使用要使用ftrace，首先就是需要将系统的debugfs或者tracefs给挂载到某个地方，幸运的是，几乎所有的Linux发行版，都开启了debugfs/tracefs的支持，所以我们也没必要去重新编译内核了。在比较老的内核版本，譬如CentOS7的上面，debugfs通常被挂载到/sys/kernel/debug上面（debug目录下面有一个tracing目录），而比较新的内核，则是将tracefs挂载到/sys/kernel/tracing，无论是什么，我都喜欢将tracing目录直接link到/tracing。后面都会假设直接进入了/tracing目录，后面，我会使用Ubuntu16.04来举例子，内核版本是4.13来举例子。在使用ftrace之前，需要内核进行支持，也就是内核需要打开编译中的ftrace相关选项，关于怎么激活ftrace选项的问题，可以google之，下面只说明重要的设置步骤：mkdir/debug；mount-tdebugsnodev/debug;/*挂载debugfs到创建的目录中去*/cd/debug;cdtracing;/*如果没有tracing目录，则内核目前还没有支持ftrace，需要配置参数，重新编译*/。echonop>current_tracer;//清空tracerechofunction_graph>current_tracer;//使用图形显示调用关系echoip_rcv>set_graph_function;//设置过滤函数,可以设置多个echo1>tracing_enabled开始追踪传统Tracer的使用使用传统的ftrace需要如下几个步骤：选择一种tracer使能ftrace执行需要trace的应用程序，比如需要跟踪ls，就执行ls关闭ftrace查看trace文件用户通过读写debugfs文件系统中的控制文件完成上述步骤。使用debugfs，首先要挂载她。命令如下：#mkdir/debug

#mount-tdebugfsnodev/debug此时您将在/debug目录下看到tracing目录。Ftrace的控制接口就是该目录下的文件。选择tracer的控制文件叫作current_tracer。选择tracer就是将tracer的名字写入这个文件，比如，用户打算使用functiontracer，可输入如下命令：#echoftrace>/debug/tracing/current_tracer文件tracing_enabled控制ftrace的开始和结束。#echo1>/debug/tracing/tracing_enable上面的命令使能ftrace。同样，将0写入tracing_enable文件便可以停止ftrace。ftrace的输出信息主要保存在3个文件中。Trace，该文件保存ftrace的输出信息，其内容可以直接阅读。latency_trace，保存与trace相同的信息，不过组织方式略有不同。主要为了用户能方便地分析系统中有关延迟的信息。trace_pipe是一个管道文件，主要为了方便应用程序读取trace内容。算是扩展接口吧。我们使用ls来看看目录下面到底有什么：READMEcurrent_tracerhwlat_detectorper_cpuset_event_pidsnapshottrace_markertracing_max_latency

available_eventsdyn_ftrace_total_infoinstancesprintk_formatsset_ftrace_filterstack_max_sizetrace_marker_rawtracing_on

available_filter_functionsenabled_functionskprobe_eventssaved_cmdlinesset_ftrace_notracestack_tracetrace_optionstracing_thresh

available_tracerseventskprobe_profilesaved_cmdlines_sizeset_ftrace_pidstack_trace_filtertrace_pipeuprobe_events

buffer_size_kbfree_buffermax_graph_depthsaved_tgidsset_graph_functiontracetrace_statuprobe_profile

buffer_total_size_kbfunction_profile_enabledoptionsset_eventset_graph_notracetrace_clocktracing_cpumask可以看到，里面有非常多的文件和目录，具体的含义，大家可以去详细的看官方文档的解释，后面只会重点介绍一些文件。2.1Function我们可以通过available_tracers这个文件知道当前ftrace支持哪些插件。catavailable_tracers

hwlatblkmmiotracefunction_graphwakeup_dlwakeup_rtwakeupfunctionnop通常用的最多的就是function和function_graph，当然，如果我们不想trace了，可以使用nop。我们首先打开function：echofunction>current_tracer

catcurrent_tracer

function上面我们将function写入到了current_tracer来开启function的trace，我通常会在cat下current_tracer这个文件，主要是防止自己写错了。然后ftrace就开始工作了，会将相关的trace信息放到trace文件里面，我们直接读取这个文件就能获取相关的信息。cattrace|head-n15

#tracer:function

#

#_=>irqs-off

#/_=>need-resched

#|/_=>hardirq/softirq

#||/_--=>preempt-depth

#|||/delay

#TASK-PIDCPU#||||TIMESTAMPFUNCTION

#|||||||||

bash-29409[002]16158426.215771:mutex_unlock<-tracing_set_tracer

<idle>-0[039]d...16158426.215771:call_cpuidle<-do_idle

<idle>-0[039]d...16158426.215772:cpuidle_enter<-call_cpuidle

<idle>-0[039]d...16158426.215773:cpuidle_enter_state<-cpuidle_enter

bash-29409[002]16158426.215773:__fsnotify_parent<-vfs_write

<idle>-0[039]d...16158426.215773:sched_idle_set_state<-cpuidle_enter_state我们可以设置只跟踪特定的functionechoschedule>set_ftrace_filter

catset_ftrace_filter

schedule

cattrace|head-n15

#tracer:function

#

#_=>irqs-off

#/_=>need-resched

#|/_=>hardirq/softirq

#||/_--=>preempt-depth

#|||/delay

#TASK-PIDCPU#||||TIMESTAMPFUNCTION

#|||||||||

bash-29409[010]16158462.591708:schedule<-schedule_timeout

kworker/u81:2-29339[008]16158462.591736:schedule<-worker_thread

sshd-29395[012]16158462.591788:schedule<-schedule_hrtimeout_range_clock

rcu_sched-9[010]16158462.595475:schedule<-schedule_timeout

java-23597[006]16158462.600326:schedule<-futex_wait_queue_me

java-23624[020]16158462.600855:schedule<-schedule_hrtimeout_range_clock当然，如果我们不想traceschedule这个函数，也可以这样做：echo'!schedule'>set_ftrace_filter或者也可以这样做：echoschedule>set_ftrace_notraceFunctionfilter的设置也支持*match，match*，*match*这样的正则表达式，譬如我们可以echo'*lock*'<set_ftrace_notrace来禁止跟踪带lock的函数，set_ftrace_notrace文件里面这时候就会显示：catset_ftrace_notrace

xen_pte_unlock

read_hv_clock_msr

read_hv_clock_tsc

update_persistent_clock

read_persistent_clock

set_task_blockstep

user_enable_block_step

...2.2FunctionGraph相比于function，function_graph能让我们更加详细的去知道内核函数的上下文，我们打开function_graph：echofunction_graph>current_tracer

cattrace|head-15

#tracer:function_graph

#

#CPUDURATIONFUNCTIONCALLS

#|||||||

10)0.085us|sched_idle_set_state();

10)|cpuidle_reflect(){

10)0.035us|menu_reflect();

10)0.288us|}

10)|rcu_idle_exit(){

10)0.034us|rcu_dynticks_eqs_exit();

10)0.296us|}

10)0.032us|arch_cpu_idle_exit();

10)|tick_nohz_idle_exit(){

10)0.073us|ktime_get();

10)|update_ts_time_stats(){我们也可以只跟踪某一个函数的堆栈echokfree>set_graph_function

cattrace|head-n15

#tracer:function_graph

#

#CPUDURATIONFUNCTIONCALLS

#|||||||

16)|kfree(){

16)0.147us|__slab_free();

16)1.437us|}

10)0.162us|kfree();

17)@923817.3us|}/*intel_idle*/

17)0.044us|sched_idle_set_state();

17)==========>|

17)|smp_apic_timer_interrupt(){

17)|irq_enter(){

17)|rcu_irq_enter(){

17)0.049us|rcu_dynticks_eqs_exit();2.3Event上面提到了

function

的trace，在ftrace里面，另外用的多的就是

event

的trace，我们可以在

events

目录下面看支持那些事件：lsevents/

alarmtimercmaext4fs_daxi2ckvmmmcnmiprintkregulatorsmbustaskvmscanxdp

blockcompactionfibftraceiommukvmmmumoduleoomrandomrpmsockthermalvsyscallxen

bpfcpuhpfib6gpioirqlibatampxpage_isolationrasschedspithermal_power_allocatorwbtxhci-hcd

btrfsdma_fencefilelockheader_eventirq_vectorsmcemsrpagemapraw_syscallsscsiswiotlbtimerworkqueue

cgroupenablefilemapheader_pagejbd2mdionapipercpurcusignalsync_tracetlbwriteback

clkexceptionsfshuge_memorykmemmigratenetpowerregmapskbsyscallsudpx86_fpu上面列出来的都是分组的，我们可以继续深入下去，譬如下面是查看sched相关的事件：lsevents/sched/

enablesched_migrate_tasksched_process_exitsched_process_waitsched_stat_sleepsched_switchsched_wakeup_new

filtersched_move_numasched_process_forksched_stat_blockedsched_stat_waitsched_wait_tasksched_waking

sched_kthread_stopsched_pi_setpriosched_process_freesched_stat_iowaitsched_stick_numasched_wake_idle_without_ipi

sched_kthread_stop_retsched_process_execsched_process_hangsched_stat_runtimesched_swap_numasched_wakeup对于某一个具体的事件，我们也可以查看：lsevents/sched/sched_wakeup

enablefilterformathistidtrigger不知道大家注意到了没有，上述目录里面，都有一个enable的文件，我们只需要往里面写入1，就可以开始trace这个事件。譬如下面就开始tracesched_wakeup这个事件：echo1>events/sched/sched_wakeup/enable

cattrace|head-15

#tracer:nop

#

#_=>irqs-off

#/_=>need-resched

#|/_=>hardirq/softirq

#||/_--=>preempt-depth

#|||/delay

#TASK-PIDCPU#||||TIMESTAMPFUNCTION

#|||||||||

bash-29409[012]d...16158657.832294:sched_wakeup:comm=kworker/u81:1pid=29359prio=120target_cpu=008

kworker/u81:1-29359[008]d...16158657.832321:sched_wakeup:comm=sshdpid=29395prio=120target_cpu=010

<idle>-0[012]dNs.16158657.835922:sched_wakeup:comm=rcu_schedpid=9prio=120target_cpu=012

<idle>-0[024]dNh.16158657.836908:sched_wakeup:comm=javapid=23632prio=120target_cpu=024

<idle>-0[022]dNh.16158657.839921:sched_wakeup:comm=javapid=23624prio=120target_cpu=022

<idle>-0[016]dNh.16158657.841866:sched_wakeup:comm=javapid=23629prio=120target_cpu=016我们也可以tracesched里面的所有事件：echo1>events/sched/enable

cattrace|head-15

#tracer:nop

#

#_=>irqs-off

#/_=>need-resched

#|/_=>hardirq/softirq

#||/_--=>preempt-depth

#|||/delay

#TASK-PIDCPU#||||TIMESTAMPFUNCTION

#|||||||||

bash-29409[010]d...16158704.468377:sched_waking:comm=kworker/u81:2pid=29339prio=120target_cpu=008

bash-29409[010]d...16158704.468378:sched_stat_sleep:comm=kworker/u81:2pid=29339delay=164314267[ns]

bash-29409[010]d...16158704.468379:sched_wake_idle_without_ipi:cpu=8

bash-29409[010]d...16158704.468379:sched_wakeup:comm=kworker/u81:2pid=29339prio=120target_cpu=008

bash-29409[010]d...16158704.468382:sched_stat_runtime:comm=bashpid=29409runtime=360343[ns]vruntime=131529875864926[ns]

bash-29409[010]d...16158704.468383:sched_switch:prev_comm=bashprev_pid=29409prev_prio=120prev_state=S==>next_comm=swapper/10next_pid=0next_prio=120当然也可以trace所有的事件：echo1>events/enable

cattrace|head-15

#tracer:nop

#

#_=>irqs-off

#/_=>need-resched

#|/_=>hardirq/softirq

#||/_--=>preempt-depth

#|||/delay

#TASK-PIDCPU#||||TIMESTAMPFUNCTION

#|||||||||

bash-29409[010]16158761.584188:writeback_mark_inode_dirty:bdi(unknown):ino=3089state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGESflags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES

bash-29409[010]16158761.584189:writeback_dirty_inode_start:bdi(unknown):ino=3089state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGESflags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES

bash-29409[010]16158761.584190:writeback_dirty_inode:bdi(unknown):ino=3089state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGESflags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES

bash-29409[010]16158761.584193:do_sys_open:"trace"8241666

bash-29409[010]16158761.584193:kmem_cache_free:call_site=ffffffff8e862614ptr=ffff91d241fa4000

bash-29409[010]16158761.584194:sys_exit:NR2=32.4trace-cmd从上面的例子可以看到，其实使用ftrace并不是那么方便，我们需要手动的去控制多个文件，但幸运的是，我们有trace-cmd，作为ftrace的前端，trace-cmd能够非常方便的让我们进行ftrace的操作，譬如我们可以使用record命令来tracesched事件：trace-cmdrecord-esched然后使用report命令来查看trace的数据：trace-cmdreport|head-10

version=6

CPU27isempty

cpus=40

trace-cmd-29557[003]16159201.985281:sched_waking:comm=kworker/u82:3pid=28507prio=120target_cpu=037

trace-cmd-29557[003]16159201.985283:sched_migrate_task:comm=kworker/u82:3pid=28507prio=120orig_cpu=37dest_cpu=5

trace-cmd-29557[003]16159201.985285:sched_stat_sleep:comm=kworker/u82:3pid=28507delay=137014529[ns]

trace-cmd-29585[023]16159201.985286:sched_stat_runtime:comm=trace-cmdpid=29585runtime=217630[ns]vruntime=107586626253137[ns]

trace-cmd-29557[003]16159201.985286:sched_wake_idle_without_ipi:cpu=5

trace-cmd-29595[037]16159201.985286:sched_stat_runtime:comm=trace-cmdpid=29595runtime=213227[ns]vruntime=105364596011783[ns]

trace-cmd-29557[003]16159201.985287:sched_wakeup:kworker/u82:3:28507[120]success=1CPU:005当然，在report的时候也可以加入自己的filter来过滤数据，譬如下面，我们就过滤出sched_wakeup事件并且是success为1的。trace-cmdreport-F'sched/sched_wakeup:success==1'|head-10

version=6

CPU27isempty

cpus=40

trace-cmd-29557[003]16159201.985287:sched_wakeup:kworker/u82:3:28507[120]success=1CPU:005

trace-cmd-29557[003]16159201.985292:sched_wakeup:trace-cmd:29561[120]success=1CPU:007

<idle>-0[032]16159201.985294:sched_wakeup:qps_json_driver:24669[120]success=1CPU:032

<idle>-0[032]16159201.985298:sched_wakeup:trace-cmd:29590[120]success=1CPU:026

<idle>-0[010]16159201.985300:sched_wakeup:trace-cmd:29563[120]success=1CPU:010

trace-cmd-29597[037]16159201.985302:sched_wakeup:trace-cmd:29595[120]success=1CPU:039

<idle>-0[010]16159201.985302:sched_wakeup:sshd:29395[120]success=1CPU:010大家可以注意下success==1，这其实是一个对事件里面field进行的表达式运算了，对于不同的事件，我们可以通过查看起format来知道它的实际fields是怎样的，譬如：catevents/sched/sched_wakeup/format

name:sched_wakeup

ID:294

format:

field:unsignedshortcommon_type;offset:0;size:2;signed:0;

field:unsignedcharcommon_flags;offset:2;size:1;signed:0;

field:unsignedcharcommon_preempt_count;offset:3;size:1;signed:0;

field:intcommon_pid;offset:4;size:4;signed:1;

field:charcomm[16];offset:8;size:16;signed:1;

field:pid_tpid;offset:24;size:4;signed:1;

field:intprio;offset:28;size:4;signed:1;

field:intsuccess;offset:32;size:4;signed:1;

field:inttarget_cpu;offset:36;size:4;signed:1;

printfmt:"comm=%spid=%dprio=%dtarget_cpu=%03d",REC->comm,REC->pid,REC->prio,REC->target_cpu三、ftrace的实现研究tracer的实现是非常有乐趣的。理解ftrace的实现能够启发我们在自己的系统中设计更好的trace功能。3.1ftrace的整体构架Ftrace有两大组成部分，一是framework，另外就是一系列的tracer。每个tracer完成不同的功能，它们统一由framework管理。ftrace的trace信息保存在ringbuffer中，由framework负责管理。Framework利用debugfs系统在/debugfs下建立tracing目录，并提供了一系列的控制文件。一句话总结：各类tracer往ftrace主框架注册，不同的trace则在不同的probe点把信息通过probe函数给送到ringbuffer中，再由暴露在用户态debufs实现相关控制。对不同tracer来说：1）需要实现probe点（需要跟踪的代码侦测点），有的probe点需要静态代码实现，有的probe点借助编译器在运行时动态替换，eventtracing属于前者；2）还要实现具体的probe函数，把需要记录的信息送到ringbuffer中；3）增加debugfs相关的文件，实现信息的解析和控制。而ringbuffer和debugfs的通用部分的管理由框架负责。3.2Functiontracer的实现Ftrace采用GCC的profile特性在所有内核函数的开始部分加入一段stub代码，ftrace重载这段代码来实现trace功能。gcc的-pg选项将在每个函数入口处加入对mcount的调用代码。比如下面的C代码。清单1.test.c//test.c

voidfoo(void)

{

printf(“foo”);

}用gcc编译：gcc–Stest.c反汇编如下：清单2.test.c不加入pg选项的汇编代码_foo:

pushl%ebp

movl%esp,%ebp

subl$8,%esp

movl$LC0,(%esp)

call_printf

leave

ret再加入-gp选项编译：gcc–pg–Stest.c得到的汇编如下：清单3.test.c加入pg选项后的汇编代码_foo:

pushl%ebp

movl%esp,%ebp

subl$8,%esp

LP3:

movl$LP3,%edx

call_mcount

movl$LC0,(%esp)

call_printf

leave

ret增加pg选项后，gcc在函数foo的入口处加入了对mcount的调用：call_mcount。原本mcount由libc实现，但您知道内核不会连接libc库，因此ftrace编写了自己的mcountstub函数，并借此实现trace功能。在每个内核函数入口加入trace代码，必然会影响内核的性能，为了减小对内核性能的影响，ftrace支持动态trace功能。当CONFIG_DYNAMIC_FTRACE被选中后，内核编译时会调用一个perl脚本：recordmcount.pl将每个函数的地址写入一个特殊的段：__mcount_loc在内核初始化的初期，ftrace查询__mcount_loc段，得到每个函数的入口地址，并将mcount替换为nop指令。这样在默认情况下，ftrace不会对内核性能产生影响。当用户打开ftrace功能时，ftrace将这些nop指令动态替换为ftrace_caller，该函数将调用用户注册的trace函数。其具体的实现在相应arch的汇编代码中，以x86为例，在entry_32.s中：清单4.entry_32.sENTRY(ftrace_caller)

cmpl$0,function_trace_stop

jneftrace_stub

pushl%eax

pushl%ecx

pushl%edx

movl0xc(%esp),%eax

movl0x4(%ebp),%edx

subl$MCOUNT_INSN_SIZE,%eax

.globlftrace_call

ftrace_call:

callftrace_stubline10popl%edx

popl%ecx

popl%eax

.globlftrace_stub

ftrace_stub:

ret

END(ftrace_caller)Functiontracer将line10这行代码替换为function_trace_call()。这样每个内核函数都将调用function_trace_call()。在function_trace_call()函数内，ftrace记录函数调用堆栈信息，并将结果写入ringbuffer，稍后，用户可以通过debugfs的trace文件读取该ringbuffer中的内容。3.3Irqsofftracer的实现Irqsofftracer的实现依赖于IRQ-Flags。IRQ-Flags是IngoMolnar维护的一个内核特性。使得用户能够在中断关闭和打开时得到通知，ftrace重载了其通知函数，从而能够记录中断禁止时间。即，中断被关闭时，记录下当时的时间戳。此后，中断被打开时，再计算时间差，由此便可得到中断禁止时间。IRQ-Flags封装开关中断的宏定义：清单5.IRQ-Flags中断代码#definelocal_irq_enable()\

do{trace_hardirqs_on();raw_local_irq_enable();}while(0)ftrace在文件ftrace_irqsoff.c中重载了trace_hardirqs_on。具体代码不再罗列，主要是使用了sched_clock（）函数来获得时间戳。3.4hw-branch的实现Hw-branch只在IA处理器上实现，依赖于x86的BTS功能。BTS将CPU实际执行到的分支指令的相关信息保存下来，即每个分支指令的源地址和目标地址。软件可以指定一块buffer，处理器将每个分支指令的执行情况写入这块buffer，之后，软件便可以分析这块buffer中的功能。Linux内核的DS模块封装了x86的BTS功能。DebugSupport模块封装了和底层硬件的接口，主要支持两种功能：Branchtracestore(BTS)和precise-eventbasedsampling(PEBS)。ftrace主要使用了BTS功能。3.5branchtracer的实现内核代码中常使用likely和unlikely提高编译器生成的代码质量。Gcc可以通过合理安排汇编代码最大限度的利用处理器的流水线。合理的预测是likely能够提高性能的关键，ftrace为此定义了branchtracer，跟踪程序中likely预测的正确率。为了实现branchtracer，重新定义了likely和unlikely。具体的代码在compiler.h中。清单6.likely/unlikely的trace实现#ifndeflikely

#definelikely(x)(__builtin_constant_p(x)?!!(x):__branch_check__(x,1))

#endif

#ifndefunlikely

#defineunlikely(x)(__builtin_constant_p(x)?!!(x):__branch_check__(x,0))

#endif其中__branch_check的实现如下：清单7._branch_check_的实现#define__branch_check__(x,expect)({\

int______r;\

staticstructftrace_branch_data\

__attribute__((__aligned__(4)))\

__attribute__((section("_ftrace_annotated_branch")))\

______f={\

.func=__func__,\

.file=__FILE__,\

.line=__LINE__,\

};\

______r=likely_notrace(x);\

ftrace_likely_update(&______f,______r,expect);\

______r;\

})ftrace_likely_update()将记录likely判断的正确性，并将结果保存在ringbuffer中，之后用户可以通过ftrace的debugfs接口读取分支预测的相关信息。从而调整程序代码，优化性能。四、实战案列：隐藏的电灯开关4.1iosnoop首先，Gregg使用

iosnoop

工具进行检查，iosnoop

用来跟踪I/O的详细信息，当然也包括latency，结果如下：#./iosnoop-ts

STARTsENDsCOMMPIDTYPEDEVBLOCKBYTESLATms

13370264.61426513370264.614844java8248R202,321431244248450560.58

13370264.61426913370264.614852java8248R202,321431244336450560.58

13370264.61427113370264.614857java8248R202,321431244424450560.59

13370264.61427313370264.614868java8248R202,321431244512450560.59

[...]

#./iosnoop-Qts

STARTsENDsCOMMPIDTYPEDEVBLOCKBYTESLATms

13370410.92733113370410.931182java8248R202,321596381840450563.85

13370410.92733213370410.931200java8248R202,321596381928450563.87

13370410.92733213370410.931215java8248R202,321596382016450563.88

13370410.92733213370410.931226java8248R202,321596382104450563.89

[...]上面看不出来啥，一个繁忙的I/O，势必会带来高的latency。我们来说说iosnoop是如何做的。

iosnoop主要是处理的block相关的event，主要是：block:block_rq_issue-I/O发起的时候的事件block:block_rq_complete-I/O完成事件block:block_rq_insert-I/O加入队列的时间如果使用了-Q参数，我们对于I/O开始事件就用block:block_rq_insert，否则就用的block:block_rq_issue。下面是我用FIO测试trace的输出：

fio-30749[036]5651360.257707:block_rq_issue:8,0WS4096()1367650688+8[fio]

<idle>-0[036]5651360.257768:block_rq_complete:8,0WS()1367650688+8[0]我们根据1367650688+8能找到对应的I/Oblocksector，然后根据issue和complete的时间就能知道latency了。4.2tpoint为了更好的定位I/O问题，Gregg使用tpoint来追踪block_rq_insert，如下：#./tpoint-Hblock:block_rq_insert

Tracingblock:block_rq_insert.Ctrl-Ctoend.

#tracer:nop

#

#TASK-PIDCPU#TIMESTAMPFUNCTION

#|||||

java-16035[000]13371565.253582:block_rq_insert:202,16WS0()550505336+88[java]

java-16035[000]13371565.253582:block_rq_insert:202,16WS0()550505424+56[java]

java-8248[007]13371565.278372:block_rq_insert:202,32R0()660621368+88[java]

java-8248[007]13371565.278373:block_rq_insert:202,32R0()660621456+88[java]

java-8248[007]13371565.278374:block_rq_insert:202,32R0()660621544+24[java]

java-8249[007]13371565.311507:block_rq_insert:202,32R0()660666416+88[java]

[...]然后也跟踪了实际的堆栈：#./tpoint-sblock:block_rq_insert'rwbs~"*R*"'|head-1000

Tracingblock:block_rq_insert.Ctrl-Ctoend.

java-8248[005]13370789.973826:block_rq_insert:202,16R0()1431480000+8[java]

java-8248[005]13370789.973831:<stacktrace>

=>blk_flush_plug_list

=>blk_queue_bio

=>generic_make_request.part.50

=>generic_make_request

=>submit_bio

=>do_mpage_readpage

=>mpage_readpages

=>xfs_vm_readpages

=>read_pages

=>__do_page_cache_readahead

=>ra_submit

=>do_sync_mmap_readahead.isra.24

=>filemap_fault

=>__do_fault

=>handle_pte_fault

=>handle_mm_fault

=>do_page_fault

=>page_fault

java-8248[005]13370789.973831:block_rq_insert:202,16R0()1431480024+32[java]

java-8248[005]13370789.973836:<stacktrace>

=>blk_flush_plug_list

=>blk_queue_bio

=>generic_make_request.part.50

[...]tpoint的实现比较简单，譬如上面的block:block_rq_insert，它直接会找events/block/block_rq_insert是否存在，如果存在，就是找到了对应的event。然后给这个event的enable文件写入1，如果我们要开启堆栈，就往options/stacktrace里面也写入1。从上面的堆栈可以看到，有readahead以及pagefault了。在Netflix新升级的Ubuntu系统里面，默认的directmappagesize是2MB，而之前的系统是4KB，另外就是默认的readahead是2048KB，老的系统是128KB。看起来慢慢找到问题了。4.3funccount为了更好的看函数调用的次数，Gregg使用了

funccount

函数，譬如检查

submit_bio

：#./funccount-i1submit_bio

Tracing"submit_bio"...Ctrl-Ctoend.

FUNCCOUNT

submit_bio27881

FUNCCOUNT

submit_bio28478

#./funccount-i1filemap_fault

Tracing"filemap_fault"...Ctrl-Ctoend.

FUNCCOUNT

filemap_fault2203

FUNCCOUNT

filemap_fault3227

[...]上面可以看到，有10倍的膨胀。对于funccount脚本，主要是需要开启functionprofile功能，也就是给function_profile_enabled文件写入1，当打开之后，就会在trace_stat目录下面对相关的函数进行统计，可以看到function0，function1这样的文件，0和1就是对应的CPU。cat一个文件:catfunction0

FunctionHitTimeAvgs^2

schedule5612603274us225058.4us4156108562us

do_idle514750521us93147.47us5947176878us

call_cpuidle514748981us93117.27us5566277250us就能知道各个函数的count了。4.4funcslower为了更加确定系统的延迟是先前堆栈上面看到的函数引起的，Gregg使用了

funcslower

来看执行慢的函数：#./funcslower-Pfilemap_fault1000

Tracing"filemap_fault"slowerthan1000us...Ctrl-Ctoend.

0)java-8210|!5133.499us|}/*filemap_fault*/

0)java-8258|!1120.600us|}/*filemap_fault*/

0)java-8235|!6526.470us|}/*filemap_fault*/

2)java-8245|!1458.30us|}/*filemap_fault*/

[...]可以看到，filemap_fault

这个函数很慢。对于

funcslower，我们主要是用

tracing_thresh

来进行控制，给这个文件写入threshold，如果函数的执行时间超过了threshold，就会记录。4.5funccount(again)Gregg根据堆栈的情况，再次对

readpage

和

readpages

进行统计：#./funccount-i1'*mpage_readpage*'

Tracing"*mpage_readpage*"...Ctrl-Ctoend.

FUNCCOUNT

mpage_readpages364

do_mpage_readpage122930

FUNCCOUNT

mpage_readpages318

do_mpage_readpage110344

[...]仍然定位到是readahead的写放大引起，但他们已经调整了readahead的值，但并没有起到作用。4.6kprobe因为readahead并没有起到作用，所以Gregg准备更进一步，使用dynamictracing。他注意到上面堆栈的函数__do_page_cache_readahead()有一个nr_to_read的参数，这个参数表明的是每次read需要读取的pages的个数，使用kprobe：#./kprobe-H'p:do__do_page_cache_readaheadnr_to_read=%cx'

Tracingkprobem.Ctrl-Ctoend.

#tracer:nop

#

#TASK-PIDCPU#TIMESTAMPFUNCTION

#|||||

java-8714[000]13445354.703793:do:(__do_page_cache_readahead+0x0/0x180)nr_to_read=200

java-8716[002]13445354.819645:do:(__do_page_cache_readahead+0x0/0x180)nr_to_read=200

java-8734[001]13445354.820965:do:(__do_page_cache_readahead+0x0/0x180)nr_to_read=200

java-8709[000]13445354.825280:do:(__do_page_cache_readahead+0x0/0x180)nr_to_read=200

[...]可以看到，每次nr_to_read读取了512（200的16进制）个pages。在上面的例子，他并不知道nr_to_read实际的符号是多少，于是用%cx来猜测的，也真能蒙对，太猛了。关于kprobe的使用，具体可以参考

kprobetrace

文档，kprobe解析需要trace的event之后，会将其写入到kprobe_events里面，然后在events/kprobes/<EVENT>/进行对应的enable和filter操作。4.7funcgraph为了更加确认，Gregg使用

funcgraph

来看

filemap_fault

的实际堆栈，来看

nr_to_read

到底是从哪里传进来的。#./funcgraph-Pfilemap_fault|head-1000

2)java-8248||filemap_fault(){

2)java-8248|0.568us|find_get_page();

2)java-8248||do_sy