from :/hlchou/article/details/6441272
[
ftrace 简介/developerworks/cn/linux/l-cn-ftrace/index.html#author1
android性能测试工具之dumpstate/melody_lu123/article/details/6859879]
在软体开发时,通常都会面临到系统效能调教的需求,我们希望知道哪些区块的程式码或函式被执行的次数频繁,或是占据较高的处理器时间,以便借此优化程式码撰写的行为,或是改善耗CPU时间的算法,以Linux平台来说,OProfile()会是一个大家常推荐的工具,OProfile支持Time-based透过系统Timer中断搜集当下执行环境资讯,并加以统计,或基于Event-based,以ARM来说就是PerformanceMonitor Unit(CP15)硬体支援的Performance控制单元(更多资讯可以参考:/help/ topic/com.arm.doc.dai0195b/index.html),ARMPMU提供例如Instruction/DataCache使用状况(miss,write-back,write-buffer..etc)，Memory/MMU存取的状况,IRQ/FIQ Latency ,Branch预测统计,I/D-TCMStatus..etc,基于这机制的Profiling可以在影响系统效能最少的情况下,进行System-wide的性能统计资讯.另一种选择,则是透过ARM接上JTAG介面,藉由ICE软体的Profiling功能进行分析.
然而,如果我们希望更明确的知道每个Function被执行的次数(OProfileTime-based的统计时间够长就可得出对应的比例,做为决定的依据),执行的流程,与个别时间成本,或是系统在排程(Scheduling andWake-up),中断,Block/Net,或Kernel记忆体配置..等,与LinuxKernel核心物件有关资讯的话,其实Ftrace会是另一个可以辅助的资讯来源,不同于OProfile ,Ftrace会透过gcc-pg把每个函式前面都插入呼叫mcount函式的动作,在Branch统计部分,也会把if或是透过likely/unlikely巨集,进行植入是的统计,因此,Ftrace相比OProfile虽然可以提供比较完整的Kernel层级统计资讯,但因为OProfile主要是透过ARM或其他处理器平台的PerformanceMonitor单元,因此,OProfile可以在影响系统效能较低的情况下进行统计(ㄟ... Time-basedFunctionprofiling也是会影响到被测端的效能的.),但总体而言,都比mcount植入每个函式中,对系统效能的影响更算是轻量.如何决定应用哪个模块进行效能分析,还是要依据当下开发时的目的与所遇到的问题来做决定.
Ftrace最应该参考的文件就是LinuxKernel原始码中位于Documentation/ftrace.txt的文件,参考该文件资讯与Google一下,Ftrace作者为在RedHat服务的Steven Rostedt,主要目的是为LinuxKernel提供一个系统效能分析的工具,以便用以除错或是改善/优化系统效能,Ftrace为一个以FunctionTrace为基础的工具,并包含了包括行程Context-Switch,Wake-Up/Ready到执行的时间成本,中断关闭的时间,以及是哪些函式呼叫所触发的,这都有助于在复杂的系统执行下,提供必要资讯以便定位问题.
接下来,我们将介绍GCC对于FtraceProfiling上,在编译器层级的支援,以及有关的builtin函式,让各位清楚这些机制底层运作的原理,最后,并以Ftrace为主,说明个机制的内容,但本文并不会深入探究到各Ftrace模组机制的实作部分,主要只以笔者自己认为值得说明的区块,来加以说明,对各项细节有兴趣的开发者,建议可以自行探究.
GCC“-pg” Profiling机制与builtin函式对FtraceBranch Profiling的支援
Ftrace支援在有加入“likely/unlikely”条件判断式位置的BrnchProfiling与对整个核心if条件判断式的BrnchProfiling (当然,选择后者对效能影响也比较明显...要做记录的地方变多了.) .使用者可以透过Kernelhacking --->Tracers --->Branch Profiling --->来选择“Nobranch profiling”,”Trace likely/unlikely profiler”或“Profile all ifconditionalss”.对系统进行BranchProfiling的动作.( Ftrace在config中有这四个设定跟BranchProfiling有关CONFIG_TRACE_BRANCH_PROFILING,CONFIG_BRANCH_PROFILE_NONE,CONFIG_PROFILE_ANNOTATED_BRANCHES与CONFIG_PROFILE_ALL_BRANCHES)
参考include/linux/compiler.h中的实作,如果选择“Profileall if conditionalss”,就会把全部的if条件判断字元,透过gccprecompile定义为巨集__trace_if,如下所示
#defineif(cond, ...) __trace_if( (cond , ## __VA_ARGS__) )
#define__trace_if(cond) /
if(__builtin_constant_p((cond)) ? !!(cond) : /
({ /
int______r; /
staticstruct ftrace_branch_data /
__attribute__((__aligned__(4))) /
__attribute__((section("_ftrace_branch"))) /
______f= { /
.func= __func__, /
.file= __FILE__, /
.line= __LINE__, /
}; /
______r= !!(cond); /
______f.miss_hit[______r]++; /
______r; /
}))
如果if条件式为常数(也就是说编译器可以在编译阶段就决定好if/else路径了),就不纳入统计,反之,就会根据条件式的结果(______r=0 or 1)统计命中的次数,作为if/else条件设计的参考.(其实,透过likely/unlikely优化编译阶段的BranchPredition是很有帮助的).
如果是设定为”Tracelikely/unlikely profiler”,就会把likely与unlikely巨集定义如下所示
/*
*Using __builtin_constant_p(x) to ignore cases where the return
*value is always the same. This idea is taken from a similar patch
*written by Daniel Walker.
*/
#ifndef likely
# define likely(x) (__builtin_constant_p(x) ? !!(x) :__branch_check__(x, 1))
#endif
#ifndef unlikely
# define unlikely(x) (__builtin_constant_p(x) ? !!(x) :__branch_check__(x, 0))
#endif
其中__branch_check__定义如下
#definelikely_notrace(x) __builtin_expect(!!(x), 1)
#defineunlikely_notrace(x) __builtin_expect(!!(x), 0)
#define__branch_check__(x, expect) ({ /
int______r; /
staticstruct ftrace_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(位置在kernel/trace/trace_branch.c)实作如下所示,
voidftrace_likely_update(struct ftrace_branch_data *f, int val, intexpect)
{
/*
*I would love to have a trace point here instead, but the
*trace point code is so inundated with unlikely and likely
*conditions that the recursive nightmare that exists is too
*much to try to get working. At least for now.
*/
trace_likely_condition(f,val, expect);
/*FIXME: Make this atomic! */
if(val == expect)
f->correct++;
else
f->incorrect++;
}
有关函式trace_likely_condition的行为在此就不追踪,只谈函式ftrace_likely_update,这函式会统计开发者使用likely/unlikely定义好的if/else区块顺序,跟实际执行时,if/else执行的结果,透过correct/incorrect累加,我们可以根据Run-Time实际统计的结果,看是否原本likely/unlikely有需要修正的空间(往统计正确的方向去,就可避免处理器PipelineFlush的机会),以便得到更好的执行效能.
若没有启动任何BranchProfiling的动作,则likely与unlikely就只会透过Builtin函式_builtin_expect(在GCC2.96版本之后支援)进行编译阶段的BranchPredition优化动作,如下宣告
#define likely(x) __builtin_expect(!!(x), 1)
#define unlikely(x) __builtin_expect(!!(x), 0)
编译器支援的Builtin函式__builtin_constant_p,主要的功能为判断所给予的值是否为常数(__builtin_constant_p会返回1,若不是常数__builtin_constant_p会返回0),若是则可在编译时期安排好对应的执行动作,就不需要把全部的行为,都放到编译后的程式码,透过执行时期才决定.
以如下程式码来验证行为,
#defineY 6
voidFunc(int Z)
{
intvResult;
vResult=__builtin_constant_p(Z)?(Z*100):-1;
printf("5:Result:%ld/n",vResult);
vResult=(Z*100);
printf("6:Result:%ld/n",vResult);
}
intmain()
{
intX=5;
intvResult;
vResult=__builtin_constant_p(X)?(X*100):-1;
printf("1:Result:%ld/n",vResult);
vResult=(X*100);
printf("2:Result:%ld/n",vResult);
vResult=__builtin_constant_p(Y)?(Y*100):-1;
printf("3:Result:%ld/n",vResult);
vResult=(Y*100);
printf("4:Result:%ld/n",vResult);
Func(7);
return;
}
以gcc版本4.1.2来验证,若以-O0编译,X为一个区域变数,__builtin_constant_p(X)会返回0,反之,Y为一个定义的常数,__builtin_constant_p(Y)会返回1,而如果把一个常数透过函式参数Z传递,因为这个值会被放到堆叠(根据每个处理器的CallingConvention,在ARM上会先放到暂存器R0-R3),导致__builtin_constant_p(Z)返回0,若是以-O1或-O2编译,则编译器可以判断区域变数X的值,__builtin_constant_p(X)会返回1,若是函式函式传递的参数Z,_builtin_constant_p(Z)还是会传回0.优化的区块还是以Function本身为单位,并且有打开优化选项,可以让Builtin函式发挥更好的效能.
参考GCC文件,__builtin_constant_p也可以作为Constant变数初始值的指定(文件建议要在GCC3.0.1版本之后),如下所示,若EXPRESSION为常数,则table初始值为该常数,反之则初始值为0.
staticconst int table[] = {
__builtin_constant_p(EXPRESSION) ? (EXPRESSION) : -1,
};
另一个需要介绍的Builtin函式为__builtin_expect,这函式的功能主要在提供编译器BranchPrediction的能力,如以下的程式码
voidFuncA(int X)
{
if(__builtin_expect(X,1))
{
printf("FuncA1:%ld/n",X*0x100);
}
else
{
printf("FuncA2:%ld/n",X);
}
}
voidFuncB(int X)
{
if(__builtin_expect(X,0))
{
printf("FuncB1:%ld/n",X*0x100);
}
else
{
printf("FuncB2:%ld/n",X);
}
}
intmain()
{
FuncA(7);
FuncB(8);
return;
}
执行结果为
FuncA1:700h
FuncB1:800h
以gcc4.1.2搭配-O2进行编译(在这验证环境下,使用-O0,函式__builtin_expect会没有效果),执行结果一致,透过反组译程式码结果如下
我们可以看到__builtin_expect(X,1)会优先把if的执行区块放到连续的程式码中,而__builtin_expect(X,0)则是会把else的执行区块,放到前面连续的程式码中,至于执行时期会执行到if或else的区块,就根据X条件是否为0来决定.参考GCC文件,我们也可以搭配条件判断的写法
可以参考LinuxKernel中include/linux/compiler.h中的实作,如下所示
#define likely(x) __builtin_expect(!!(x), 1)
#define unlikely(x) __builtin_expect(!!(x), 0)
如果开发者判断,if的区块是较常被执行到的,那就应该用likely,例如
if(likely(success))
{….}
else//else区块可能为error处理逻辑,多数的情况应该希望走的是if的逻辑
{….}
如果开发者判断else区块,是希望较常被执行到的,就可以使用unlikely,例如
if(unlikely(error))
{….}
else//success
{….}
处理器本身也有BranchPredition的能力,如果不在有被处理器记忆到的BPEntry中,处理器通常会循序Fetch指令进来,一旦发现分支预测错误,就会FlushPipeline,透过函式__builtin_expect,我们可以在编译时期,依据传入值的结果,决定if/else编译为机械码时程式码排列的顺序,减少处理器Pipeline被Flush的机率,这对执行效能也是有很大的帮助.
GCCsupport for the GNU profiler gprof
有关GNUgprof的介绍,可以参考网页http://www.cs.utah.edu/dept/old/texinfo/as/gprof.html.基于GCC对Profiling的支援,开发端可以透过-pg的编译参数,让gcc把profiling的功能加入到程式码中,
以如下程式码为例,
intFuncA()
{
inti;
intvRet=0;
for(i=0;i<20000;i++)
{
vRet+=i;
}
returnvRet;
}
intFuncB(int I)
{
inti;
intvRet=0;
for(i=0;i<9999;i++)
{
vRet+=I+FuncA();
}
returnvRet;
}
intmain()
{
intvResult;
vResult=FuncA();
vResult=FuncB(vResult);
printf("Result:%ld/n",vResult);
return0;
}
透过gcc编译后,有加上-pg与没加上的差异如下
[root@localhostpg]# gcc -g -pg pg.c -o pg
[root@localhostpg]# ./pg
Result:785467424
[root@localhostpg]# ls -l gmon.out
-rw-r--r--1 root root 464 May 13 06:32 gmon.out
[root@localhostpg]# gprof --brief ./pg
[root@localhostpg]# gprof --brief ./pg
Flatprofile:
Eachsample counts as 0.01 seconds.
=>简要说明:每次呼叫FuncA需要0.05ms,总共呼叫了10000次,耗时0.47秒(ㄟ也许应该说每次呼叫FuncA需要0.047ms会比较精确一点),而FnucB被呼叫1次,耗时472.49ms(在funcB中会执行9999次FuncA).
Callgraph
granularity:each sample hit covers 2 byte(s) for 2.12% of 0.47 seconds
=>简要说明:以FuncA为主体来对比,FuncA执行了10000次共0.47秒的时间,FuncB呼叫了FuncA9999 (占总数9999/10000),main呼叫了FuncA1次(占总数1/10000)
=>简要说明:以main为主体来对比,main呼叫的函式(children)花了0.47秒,分别呼叫了FuncB占了9999/10000(约等于1)的时间,与呼叫了FuncA占了1/ 10000的时间.
=>简要说明:以funcB为主体来对比,main呼叫的函式FuncA与funcB(children)花了0.47秒,FuncB呼叫的函式FuncA花了0.47秒(因为最小单位为0.01秒,太接近的两个数字如果差距是在0.01秒以内,数字就有机会变成一样),FuncB被呼叫1次,FuncA被FuncB呼叫9999次
Indexby function name
[1]FuncA [3] FuncB
Infrastructurefor profiling code inserted by 'gcc -pg'.
work-theory.co.uk/docs/gccintro/gccintro_80.html
在LinuxKernel中EnableTracer
要在核心中支援Ftrace,除了GCC编译器要支援-pg外,所采用的C函式库也要支援相关mcount的函式,笔者用AndroidSDK带的arm-eabi-gcc4.4.0会产生编译错误“undefinedreference to `__gnu_mcount_nc' “.笔者后来是到Sourcery网址/sgpp/lite/arm/portal/subscription3053下载arm-q3版本的编译器与函式库环境,以此为基础进行ARM环境LinuxKernel开启Ftrace的编译,就可以解决无法Link'__gnu_mcount_nc'的错误了.(有关编译环境与KernelSource Code版本的选择,会随着版本演进而有所差异,如有遇到编译错误发生时,还请以各位自己所选择的环境为主来判断.)
接下来执行make menuconfig.
如果是在x86的机器上,要Enable“Kernel Function Graph Trace”的功能,就要透过Generalsetup --->Optimize for size ,选择关闭“Optimize for size “.而在ARM平台上,目前没有“KernelFunction Graph Trace”的选项,所以就不受此限制.
此外,在LinuxKernel 2.6.31给ARM环境的组态中,目前并不支援DynamicFtrace,所以像是set_ftrace_filter与set_ftrace_nontrace这类可以动态设定函式名称过滤原则的机制,在笔者环境中就无法支援,我在说明时,会以x86版本来替代,后续支援与否请以LinuxKernel版本演进为主.
在选单中进入Kernelhacking ---> Tracers --->就可以选择要开启哪些Tracers功能,以笔者手中针对ARM版本的Config内容如下(我是都勾选了...)
-*-Kernel Function Tracer
[*]Interrupts-off Latency Tracer
[*]Scheduling Latency Tracer
-*-Trace process context switches
[*]Trace boot initcalls
[*]Trace likely/unlikely profiler
[*] Profile all if conditionals
[*]Trace likely/unlikely instances
[*]Trace max stack
最后确认DebugFilesystem是否有被勾选,路径为Kernelhacking --->-*- Debug Filesystem.
退出选单,由于刚才已经勾选“CONFIG_FUNCTION_TRACER”组态,可以参考档案kernel/trace/Makefile的内容,设定CONFIG_FUNCTION_TRACER后,就会把KBUILD_CFLAGS加上-pg,每个核心函式中都会被置入mcount函式的呼叫
ifdefCONFIG_FUNCTION_TRACER
ORIG_CFLAGS:= $(KBUILD_CFLAGS)
KBUILD_CFLAGS= $(subst -pg,,$(ORIG_CFLAGS))
...
endif
Kernel内部有关除错,或是Ftrace相关的档案,会移除-pg的编译参数,避免影响统计的结果,例如在kernel/Makefile档案中
ifdefCONFIG_FUNCTION_TRACER
# Donot trace debug files and internal ftrace files
CFLAGS_REMOVE_lockdep.o= -pg
CFLAGS_REMOVE_lockdep_proc.o= -pg
CFLAGS_REMOVE_mutex-debug.o= -pg
…............
endif
比较一下,有打开FunctionTracer跟没有打开FunctionTracer的核心编译结果如下所示,可以看到GCC编译器,对编译结果的影响.
DebugFSFileSystem
Ftrace会使用虚拟的档案系统debugfs做为设定档与输出结果的储存位置,我们可以先在根目录产生/debug档案,然后mountdebugfs到/debug目录下(Ftrace文件建议可以mount到/sys/kernel/debug目录下)
#mkdir /debug
#mount -t debugfs nodev /debug
之后进入/debug/tracing目录下
# cd/debug/tracing
查询系统中支援哪些Tracer
$ catavailable_tracers
function_graphfunction_duration function sched_switch nop
选择sched_switch作为目前运作的Tracer
#echo sched_switch > current_tracer
可以检视目录下的trace档案,观察sched_switch输出的结果
#cat trace
#tracer: sched_switch
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<idle>-0 [000] 745.934676: 0:140:R ==> [000] 2892:120:R
gnome-terminal-2892 [000] 745.934770: 2892:120:S ==> [000] 0:140:R
<idle>-0 [000] 745.934861: 0:140:R ==> [000] 2892:120:R
gnome-terminal-2892 [000] 745.934937: 2892:120:S ==> [000] 0:140:R
bash-5175 [001] 745.934960: 5175:120:S + [000] 2892:120:S
bash-5175 [001] 745.935149: 5175:120:S + [000] 2892:120:S
暂停Ftrace的运作,
#echo nop > current_tracer
上述步骤,为透过debugfs操作Ftrace的基本行为,接下来让我们初步认识Ftrace相关的控制档案
介绍Ftrace目录tracing下的档案
我们以AndroidARM平台搭配LinuxKernel 2.6.31为例子,首先建立/data/debug目录,并且把debugfs虚拟档案系统载入
# mkdir/data/debug
# mount-t debugfs nodev /data/debug
# cd/data/debug
浏览目录下的内容,
# ls
sched_features
mmc0
tracing
bdi
#
进入目录tracing后,ls浏览该目录的结果
# cd/data/debug
# ls -l
-r--r--r--root root 0 1970-01-01 00:00 stack_trace
-rw-r--r--root root 0 1970-01-01 00:00 stack_max_size
drwxr-xr-xroot root 1970-01-01 00:00 events
-rw-r--r--root root 0 1970-01-01 00:00 set_event
-r--r--r--root root 0 1970-01-01 00:00 available_events
-r--r--r--root root 0 1970-01-01 00:00 printk_formats
drwxr-xr-xroot root 1970-01-01 00:00 per_cpu
drwxr-xr-xroot root 1970-01-01 00:00 options
-r--r--r--root root 0 1970-01-01 00:00 saved_cmdlines
--w--w----root root 0 1970-01-01 00:00 trace_marker
-rw-r--r--root root 0 1970-01-01 00:00 buffer_size_kb
-r--r--r--root root 0 1970-01-01 00:00 trace_pipe
-r--r--r--root root 0 1970-01-01 00:00 README
-rw-r--r--root root 0 1970-01-01 00:00 tracing_thresh
-rw-r--r--root root 0 1970-01-01 00:00 tracing_max_latency
-rw-r--r--root root 0 1970-01-01 00:00 current_tracer
-r--r--r--root root 0 1970-01-01 00:00 available_tracers
-rw-r--r--root root 0 1970-01-01 00:00 trace
-rw-r--r--root root 0 1970-01-01 00:00 tracing_cpumask
-rw-r--r--root root 0 1970-01-01 00:00 trace_options
-rw-r--r--root root 0 1970-01-01 00:00 tracing_enabled
-rw-r--r--root root 0 1970-01-01 00:00 tracing_on
-rw-r--r--root root 0 1970-01-01 00:00 function_profile_enabled
drwxr-xr-xroot root 1970-01-01 00:00 trace_stat
-rw-r--r--root root 0 1970-01-01 00:00 set_ftrace_pid
接下来,笔者以这目录下的档案,挑选认为应该说明的部份,如下所示
介绍Ftrace每个模组
Ftrace的设计概念为提供Plug-inFramework的机制,随着核心模组的演进,如果需要针对新的核心模组进行效能上的统计分析时,就可以透过Plug-in的方式,撰写新的Ftrace模组达成新的tracer目的,作为一个可延展性的Tracer架构,本段落会介绍Ftrace主要支援的Tracer模组,这些模组的数量或是功能,都有可能随着LinuxKernel演进而有所改动(例如:Kernel2.6.39移除KernelLock),版本的更迭,都请以最新的LinuxKernel Source Code为主要依据.
有关Task状态参考如下表
Block Device Tracer
设定路径为Kernelhacking --->Tracers --->Support for tracing block ioactions
可以用来监控储存装置的使用状况,与行为
例如笔者要启动BlockDevice Tracer监控目前正在编译程式码的储存装置sda2,如下操作指令
#echo 0 >/debug/tracing/tracing_enabled
#echo 1>/sys/block/sda/sda2/trace/enable
# echo blk >current_tracer
#echo 1 >/debug/tracing/tracing_enabled
…..执行编译的行为....
#echo 0 >/debug/tracing/tracing_enabled
#echo 0>/sys/block/sda/sda2/trace/enable
再来检视trace中的结果如下所示,
#tracer: blk
#
mv-21550[000] 6663.719323: 8,2 m N cfq21550 sl_used=4 disp=1charge=4 iops=0 sect=8
mv-21550[000] 6663.719341: 8,2 m N cfq21550 del_from_rr
mv-21550[000] 6663.719367: 8,2 m N cfq21550 put_queue
cc1-21557[000] 6663.920569: 8,2 AR 221728392 + 56 <- (253,0)221728008
cc1-21557[000] 6663.920576: 8,2 AR 221937237 + 56 <- (8,2)221728392
cc1-21557[000] 6663.920577: 8,2 QR 221937237 + 56 [cc1]
cc1-21557[000] 6663.920751: 8,2 m N cfq21557 alloced
cc1-21557[000] 6663.920816: 8,2 GR 221937237 + 56 [cc1]
cc1-21557[000] 6663.920875: 8,2 PN [cc1]
cc1-21557[000] 6663.921844: 8,2 IR 221937237 + 56 [cc1]
cc1-21557[000] 6663.921870: 8,2 m N cfq21557 insert_request
cc1-21557[000] 6663.921906: 8,2 m N cfq21557 add_to_rr
as-21558[000] 6663.923906: 8,2 UT N [as] 1
kworker/0:1-16318[000] 6663.924047: 8,2 UN [kworker/0:1] 1
kworker/0:1-16318[000] 6663.924102: 8,2 m N cfq workload slice:100
kworker/0:1-16318[000] 6663.924146: 8,2 m N cfq21557 set_active wl_prio:0wl_type:2
…..............
ld-21578[000] 6665.826767: 8,2 UN [ld] 0
ld-21578[000] 6665.826865: 8,2 UN [ld] 0
ld-21578[000] 6665.829130: 8,2 UN [ld] 0
ld-21578[000] 6665.831853: 8,2 UN [ld] 0
ld-21578[000] 6665.839538: 8,2 m N cfq21578 put_queue
<...>-21532[000] 6665.902373: 8,2 m N cfq21532 put_queue
make-21583[000] 6665.95: 8,2 AR 221728880 + 8 <- (253,0)221728496
make-21583[000] 6665.91: 8,2 AR 221937725 + 8 <- (8,2)221728880
make-21583[000] 6665.93: 8,2 QR 221937725 + 8 [make]
make-21583[000] 6665.920468: 8,2 m N cfq21583 alloced
make-21583[000] 6665.920646: 8,2 GR 221937725 + 8 [make]
make-21583[000] 6665.920691: 8,2 PN [make]
make-21583[000] 6665.920741: 8,2 IR 221937725 + 8 [make]
make-21583[000] 6665.920770: 8,2 m N cfq21583 insert_request
make-21583[000] 6665.920800: 8,2 m N cfq21583 add_to_rr
make-21583[000] 6665.920861: 8,2 UN [make] 1
make-21583[000] 6665.920897: 8,2 m N cfq workload slice:100
make-21583[000] 6665.920923: 8,2 m N cfq21583 set_active wl_prio:0wl_type:2
…..............
Branch tracer
1,Trace likely/unlikely profiler
设定路径为Kernelhacking --->Tracers --->Branch Profiling --->Tracelikely/unlikely profiler
用以显示Kernel基于likely/unlikely的Run-Time统计结果
操作范例如下所示
#echo 0 >tracing_enabled
# echo branch >current_tracer
#echo 1 >tracing_enabled
…..do something.....
#echo 0 >tracing_enabled
查看结果如下
#tracer: branch
#
# TASK-PID CPU# TIMESTAMP CORRECT FUNC:FILE:LINE
# | | | | | |
<idle>-0 [000] 55415.397835: [ ok ] read_seqretry:seqlock.h:110
<idle>-0 [000] 55415.397848: [ ok ] native_sched_clock:tsc.c:55
<idle>-0 [000] 55415.397859: [ ok ] native_sched_clock:tsc.c:55
….
<idle>-0 [000] 55415.398682: [ ok ] __local_bh_enable:softirq.c:138
<idle>-0 [000] 55415.398695: [ ok ]update_wall_time:timekeeping.c:789
<idle>-0 [000] 55415.398710: [ MISS ]timekeeping_adjust:timekeeping.c:711
<idle>-0 [000] 55415.398725: [ ok ]update_wall_time:timekeeping.c:839
<idle>-0 [000] 55415.398734: [ ok ]update_wall_time:timekeeping.c:859
…..
<idle>-0 [000] 55415.401654: [ ok ]update_wall_time:timekeeping.c:789
<idle>-0 [000] 55415.401668: [ MISS ]timekeeping_adjust:timekeeping.c:711
<idle>-0 [000] 55415.401677: [ ok ]update_wall_time:timekeeping.c:839
<idle>-0 [000] 55415.401687: [ ok ]update_wall_time:timekeeping.c:859
…..
针对MISS比较多的段落写法,我们可以透过修改likely/unlikely的配置,让gcc__builtin_expect的函式发挥作用,把真正的热区放在循序的执行过程中,非热区放在需要Jump/Branch的位址,减少处理器Pipeline被Flush的机会,从而也可以让系统的运作效率更佳.
2,Profile all if conditionals
设定路径为Kernelhacking --->Tracers --->Branch Profiling --->Profileall if conditionals
操作范例如下所示
#echo 0 >tracing_enabled
# echo branch >current_tracer
#echo 1 >tracing_enabled
…..do something.....
#echo 0 >tracing_enabled
查看结果如下
#tracer: branch
#
# TASK-PID CPU# TIMESTAMP CORRECT FUNC:FILE:LINE
# | | | | | |
<...>-1806 [000] 297.131833: [ ok ] native_sched_clock:tsc.c:55
<...>-1806 [000] 297.131843: [ ok ] native_sched_clock:tsc.c:55
<...>-1806 [000] 297.131850: [ ok ] sched_clock_local:sched_cloc
kc:149
<...>-1806 [000] 297.131860: [ ok ] sched_clock_cpu:sched_clock.
c:219
<...>-1806 [000] 297.131866: [ ok ] sched_clock_cpu:sched_clock.
c:219
<...>-1806 [000] 297.131873: [ ok ] sched_clock_cpu:sched_clock.
c:224
<...>-1806 [000] 297.131879: [ ok ] native_sched_clock:tsc.c:55
<...>-1806 [000] 297.131886: [ ok ] sched_clock_local:sched_cloc
kc:149
<...>-1806 [000] 297.131896: [ ok ] update_curr:sched_fair.c:576
<...>-1806 [000] 297.131903: [ ok ] calc_delta_fair:sched_fair.c
:477
<...>-1806 [000] 297.131913: [ ok ] trace_sched_stat_runtime:sch
ed.h:363:
<...>-1806 [000] 297.131922: [ ok ] __sched_period:sched_fair.c:496
<...>-1806 [000] 297.131928: [ ok ] sched_slice:sched_fair.c:521
<...>-1806 [000] 297.131935: [ MISS ] calc_delta_mine:sched.c:1327
<...>-1806 [000] 297.131942: [ ok ] resched_task:sched.c:1158
<...>-1806 [000] 297.131949: [ MISS ] test_tsk_need_resched:sched.h:2378
<...>-1806 [000] 297.131956: [ ok ]perf_event_task_tick:perf_event.c:1828
<...>-1806 [000] 297.131963: [ ok ]perf_event_task_tick:perf_event.c:1828
<...>-1806 [000] 297.131970: [ MISS ]trigger_load_balance:sched_fair.c:3989
<...>-1806 [000] 297.131978: [ ok ]run_posix_cpu_timers:posix-cpu-timers.c:1312
<...>-1806 [000] 297.131995: [ ok ] __local_bh_disable:softirq.c:98
<...>-1806 [000] 297.132002: [ ok ] __local_bh_disable:softirq.c:98
<...>-1806 [000] 297.132032: [ ok ] trace_softirq_entry:irq.h:117
<...>-1806 [000] 297.132054: [ ok ] trace_softirq_exit:irq.h:131
Kernel memory tracer
内存tracer主要用来跟踪slaballocator的分配情况。包括kfree，kmem_cache_alloc等API的调用情况，用户程序可以根据tracer收集到的信息分析内部碎片情况，找出内存分配最频繁的代码片断，等等
设定路径为Kernelhacking --->Tracers --->Trace SLAB allocations
操作范例如下所示
# echo 0 > tracing_enabled
# echo kmemtrace >current_tracer
# echo 1 > tracing_enabled
# echo 0 > tracing_enabled
….etc
Workqueue statisticaltracer
这是一个statistictracer，主要用来统计系统所有workqueue现况,可以知道有多少work被插入到queue中,以及有多 少被执行,与work的名称,可用以提供开发端对于workqueue机制实现的参考.
设定路径为Kernelhacking --->Tracers --->Traceworkqueues,系统启动后,可以到/data/debug/tracing/trace_stat/workqueues下,查看内容,如下所示
# CPU INSERTED EXECUTED NAME
# | | | |
0 2139 2139 events/0
0 0 0 khelper
0 0 0 suspend
0 1 1 kblockd/0
0 1 1 kmmcd
0 0 0 aio/0
0 0 0 crypto/0
0 0 0 rpciod/0
Profiling
1,unlikely/likely
可用以显示likely/unlikely条件判断式的统计结果
统计结果位于/debug/tracing/trace_stat/branch_annotated
如下所示
correctincorrect % Function File Line
---------------- - -------- ---- ----
0 1 100 tcp_synack_options tcp_output.c 535
0 1 100 tcp_synack_options tcp_output.c 529
0 1 100 tcp_synack_options tcp_output.c 524
0 9 100 tcp_options_write tcp_output.c 397
0 3622 100 tcp_established_options tcp_output.c 562
0 7 100 sys_inotify_add_watch inotify_user.c 750
0 7 100 fput_light file.h 29
0 17920 100 get_futex_key futex.c 269
0 28 100 clocksource_adjust timekeeping.c 472
0 4 100 blocking_notifier_chain_regist notifier.c 220
0 1 100 signal_pending sched.h 2251
0 6849 100 trace_workqueue_execution workqueue.h 53
0 8 100 trace_workqueue_creation workqueue.h 76
0 6849 100 trace_workqueue_insertion workqueue.h 31
0 38 100 yield_task_fair sched_fair.c 1016
0 25617 100 _pick_next_task_rt sched_rt.c 1041
0 92856 100 sched_info_switch sched_stats.h 269
0 85509 100 sched_info_queued sched_stats.h 222
0 54733 100 sched_info_dequeued sched_stats.h 177
0 1 100 consistent_init dma-mapping.c 470
9 1710 99 tcp_options_write tcp_output.c 396
2 354 99 disk_put_part genhd.h 209
606 67234 99 fput_light file.h 29
35 9260 99 trace_kmalloc kmem.h 79
313 12957 97 fput_light file.h 29
542 10337 95 sys_gettimeofday time.c 111
70 770 91 blk_update_request blk-core.c 1968
28116 135585 82 fget_light file_table.c 332
2 8 80 trace_kmalloc kmem.h 79
24893 53424 68 fput_light file.h 29
4547 8951 66 need_resched sched.h 2273
750 1338 64 fput_light file.h 29
15323 25008 62 wakeup_gran sched_fair.c 1382
44 61 58 mmdrop sched.h 2024
821 1006 55 pskb_trim_rcsum skbuff.h 1690
84797 95325 52 calc_delta_fair sched_fair.c 400
1 1 50 remap_pte_range memory.c 1634
270 270 50 isolate_lru_pages vmscan.c 926
32028 27195 45 rmqueue_bulk page_alloc.c 907
1970 1505 43 copy_pte_range memory.c 618
24549 17984 42 trace_kfree kmem.h 208
2,brancheall
可用以显示所有if条件判断式的统计结果
统计结果位于/debug/tracing/trace_stat/branch_all
如下所示
miss hit % Function File Line
---------------- - -------- ---- ----
0 1 100 i386_start_kernel head32.c 50
1 0 0 reserve_ebda_region head.c 51
1 0 0 reserve_ebda_region head.c 47
0 1 100 reserve_ebda_region head.c 42
0 0 X nrcpus main.c 167
0 0 X maxcpus main.c 178
1098 0 0 do_one_initcall main.c 773
1098 0 0 do_one_initcall main.c 769
1098 0 0 do_one_initcall main.c 765
1098 0 0 do_one_initcall main.c 762
1098 0 0 do_one_initcall main.c 755
1 0 0 start_kernel main.c 682
0 1 100 start_kernel main.c 675
1 0 0 start_kernel main.c 661
1 0 0 start_kernel main.c 647
1 0 0 start_kernel main.c 630
1 0 0 start_kernel main.c 611
1 0 0 kernel_init main.c 914
0 1 100 kernel_init main.c 911
1 0 0 kernel_init main.c 901
1 0 0 smp_init main.c 399
1 0 0 smp_init main.c 397
1 1 50 cpumask_next cpumask.h 172
0 0 X init_post main.c 850
0 1 100 init_post main.c 838
0 0 X unknown_bootoption main.c 321
0 0 X unknown_bootoption main.c 313
0 0 X unknown_bootoption main.c 309
0 0 X unknown_bootoption main.c 305
0 0 X unknown_bootoption main.c 302
0 0 X unknown_bootoption main.c 299
0 2 100 unknown_bootoption main.c 295
0 0 X unknown_bootoption main.c 286
0 1 100 unknown_bootoption main.c 284
1 1 50 unknown_bootoption main.c 282
0 2 100 obsolete_checksetup main.c 235
2 0 0 obsolete_checksetup main.c 231
0 0 X obsolete_checksetup main.c 229
2 0 0 obsolete_checksetup main.c 224
28 2 6 obsolete_checksetup main.c 223
1 1 50 parse_early_param main.c 496
0 0 X do_early_param main.c 476
368 0 0 do_early_param main.c 475
1 0 0 readonly do_mounts.c 44
3,Functions
可用以显示所有函式执行次数与时间的统计结果.
操作范例如下所示
# echo 1 >/debug/tracing/function_profile_enabled
…..do something.....
# echo 0 >/debug/tracing/function_profile_enabled
#cat/debug/tracing/trace_stat/function0
可看到如下结果
Function Hit Time Avg s^2
-------- --- ---- ------
schedule 752 99800000 us 132712.7 us2635264000 us
poll_schedule_timeout 57 37432000 us 656701.7 us 2143996599 us
schedule_hrtimeout_range 55 37429000 us 680527.2 us 339918459 us
schedule_hrtimeout_range_clock 55 37424000 us 680436.3 us 237544596 us
sys_select 87 25028000 us 287678.1 us306802216 us
core_sys_select 87 25012000 us 287494.2 us155578451 us
do_select 87 24875000 us 285919.5 us323446561 us
smp_apic_timer_interrupt 15677 16056000 us 1024.175 us 76796.05 us
do_timer 15677 15677000 us 1000.000 us0.000 us
tick_periodic 15677 15677000 us 1000.000 us 0.000us
tick_handle_periodic 15677 15677000 us 1000.000 us 0.000 us
sys_poll 14 14227000 us 1016214 us 3 503583162 us
do_sys_poll 14 14217000 us 1015500 us 3379054126 us
sys_nanosleep 15 13957000 us 930466.6 us1834329984 us
hrtimer_nanosleep 15 13945000 us 929666.6 us 1719729983us
do_nanosleep 15 13944000 us 929600.0 us1710319131 us
sys_read 167 13503000 us 80856.28 us1298120022 us
vfs_read 172 13490000 us 78430.23 us2981769264 us
tty_read 61 13297000 us 217983.6 us2678381427 us
n_tty_read 61 13256000 us 217311.4 us2834883001 us
schedule_timeout 20 12966000 us 648300.0 us2458710875 us
Max Stack Tracer
可用以显示核心函式呼叫最深的Stack大小与在该情况下的CallStack路径.
设定路径为Kernelhacking --->Tracers --->Trace max stack
# echo 1 >/proc/sys/kernel/stack_tracer_enabled
# sleep 10
# echo 0 >/proc/sys/kernel/stack_tracer_enabled
# cat stack_max_size
2152
# cat stack_trace
Depth Size Location (22 entries)
----- ---- --------
0) 2084 68 update_curr+0x100/0x210
1) 56 enqueue_task_fair+0x90/0x4e0
2) 1960 24 enqueue_task+0x8d/0xb0
3) 1936 12 activate_task+0x25/0x50
4) 1924 88 try_to_wake_up+0x24a/0x5f0
5) 1836 8 wake_up_process+0x14/0x20
6) 1828 8 hrtimer_wakeup+0x2c/0x30
7) 1820 80 hrtimer_run_queues+0x1d4/0x480
8) 1740 8 run_local_timers+0xd/0x20
9) 1732 20 update_process_times+0x34/0x90
10) 1712 8 tick_periodic+0x7a/0x90
11) 1704 32 tick_handle_periodic+0x1e/0xb0
12) 1672 8 smp_apic_timer_interrupt+0x9c/0x9e
13) 1664 108 apic_timer_interrupt+0x2f/0x34
14) 1556 232 schedule+0x62b/0x10f0
15) 1324 76 schedule_hrtimeout_range_clock+0x14b/0x170
16) 1248 12 schedule_hrtimeout_range+0x17/0x20
17) 1236 20 poll_schedule_timeout+0x4c/0x70
18) 1216 764 do_select+0x789/0x7c0
19) 452 332 core_sys_select+0x27d/0x460
20) 120 40 sys_select+0x40/0xe0
21) 80 80 syscall_call+0x7/0xb
主要会列出目前最深的StackSize,与根据该StackSize发生的情况下,完整的CallStack流程与每个函式所占的空间(会包括区域变数与FunctionParameters所占的Stack空间).让开发者,可以根据这流程去检讨函式与呼叫流程设计的合理性.
Event tracing
Event几乎是整个Ftrace中,各种资讯的集合,浏览/debug/tracing/events目录中的档案名称如下所示
drwxr-xr-x 4 root root 0XXX 20 23:55 bkl
drwxr-xr-x 20 root root 0XXX 20 23:55 block
-rw-r--r-- 1 root root 0XXX 20 23:55 enable
drwxr-xr-x 14 root root 0XXX 20 23:55 ftrace
-r--r--r-- 1 root root 0XXX 20 23:55 header_event
-r--r--r-- 1 root root 0XXX 20 23:55 header_page
drwxr-xr-x 7 root root 0XXX 20 23:55 irq
drwxr-xr-x 14 root root 0XXX 20 23:55 kmem
drwxr-xr-x 3 root root 0XXX 20 23:55 mce
drwxr-xr-x 7 root root 0XXX 20 23:55 module
drwxr-xr-x 3 root root 0XXX 20 23:55 napi
drwxr-xr-x 6 root root 0XXX 20 23:55 net
drwxr-xr-x 12 root root 0XXX 20 23:55 power
drwxr-xr-x 4 root root 0XXX 20 23:55 raw_syscalls
drwxr-xr-x 18 root root 0XXX 20 23:55 sched
drwxr-xr-x 7 root root 0XXX 20 23:55 scsi
drwxr-xr-x 6 root root 0XXX 20 23:55 signal
drwxr-xr-x 5 root root 0XXX 20 23:55 skb
drwxr-xr-x 634 root root 0XXX 20 23:55 syscalls
drwxr-xr-x 14 root root 0XXX 20 23:55 timer
drwxr-xr-x 15 root root 0XXX 20 23:55 vmscan
drwxr-xr-x 6 root root 0XXX 20 23:55 workqueue
drwxr-xr-x 23 root root 0XXX 20 23:55 writeback
除了enable,header_event与header_page这三个控制档案外,其他每个目录都包含一种类别的Event参数,以目前笔者所使用的环境,Event包含了以下的类别
结尾,
在平台移植与开发上,效能调教对于产品化的影响很深,本文主要介绍Ftrace的概念与操作范例,对笔者而言,这套工具可以帮助在复杂行为下,去分析系统效能的瓶颈,例如,是否有中断关闭过长的行为,或是修改过的核心函式,不适当的行为占据过多的处理器时间.目前,在Linux平台上,能使用的工具不少(或是也可以使用商业的ICE产品),对这些工具内部运作原理掌握的程度越高,我们就会有足够的知识背景帮助团队在问题发生时,借重适当的工具去分析问题的原因,Ftrace只是提供系统问题一部分的资讯,其它可用的工具与分析问题的知识背景,会是有志于在这产业的开发者,需要持续努力的.
