在软体开发时,通常都会面临到系统效能调教的需求,我们希望知道哪些区块的程式码或函式被执行的次数频繁,或是佔据较高的处理器时间,以便藉此优化程式码撰写的行为,或是改善耗CPU时间的算法,以Linux平台来说,OProfile(http://oprofile.sourceforge.net )会是一个大家常推荐的工具,OProfile支持Time-based透过系统Timer中断蒐集当下执行环境资讯,并加以统计,或基于Event-based,以ARM 来说就是Performance Monitor Unit(CP15)硬体支援的Performance控制单元 (更多资讯可以参考:http://infocenter.arm.com/help/topic/com.arm.doc.dai0195b/index.html),ARM PMU提供例如Instruction/Data Cache 使用状况(miss,write-back,write-buffer..etc)，Memory/MMU 存取的状况, IRQ/FIQ Latency,Branch预测统计,I/D-TCM Status..etc,基于这机制的Profiling可以在影响系统效能最少的情况下,进行System-wide的性能统计资讯. 另一种选择,则是透过ARM接上JTAG介面,藉由ICE软体的Profiling功能进行分析.
然而,如果我们希望更明确的知道每个Function被执行的次数 (OProfile Time-based的统计时间够长就可得出对应的比例,做为决定的依据),执行的流程,与个别时间成本,或是系统在排程 (Scheduling and Wake-up),中断,Block/Net,或Kernel记忆体配置..等,与Linux Kernel核心物件有关资讯的话,其实Ftrace会是另一个可以辅助的资讯来源,不同于OProfile,Ftrace会透过gcc -pg把每个函式前面都插入呼叫mcount函式的动作,在Branch统计部分,也会把if或是透过likely/unlikely巨集,进行植入是的统计,因此,Ftrace相比OProfile虽然可以提供比较完整的Kernel层级统计资讯,但因为OProfile主要是透过ARM或其他处理器平台的Performance Monitor单元,因此,OProfile可以在影响系统效能较低的情况下进行统计(ㄟ...Time-based Function profiling也是会影响到被测端的效能的.),但总体而言,都比mcount植入每个函式中,对系统效能的影响更算是轻量. 如何决定应用哪个模块进行效能分析,还是要依据当下开发时的目的与所遇到的问题来做决定.
Ftrace最应该参考的文件就是Linux Kernel原始码中位于Documentation/ftrace.txt的文件,参考该文件资讯与Google一下,Ftrace作者为在RedHat服务的 Steven Rostedt,主要目的是为Linux Kernel提供一个系统效能分析的工具,以便用以除错或是改善/优化系统效能,Ftrace为一个以Function Trace为基础的工具,并包含了包括行程Context-Switch,Wake-Up/Ready到执行的时间成本,中断关闭的时间,以及是哪些函式呼叫所触发的,这都有助于在複杂的系统执行下,提供必要资讯以便定位问题.
接下来,我们将介绍GCC对于Ftrace Profiling上,在编译器层级的支援,以及有关的builtin函式,让各位清楚这些机制底层运作的原理,最后,并以Ftrace为主,说明个机制的内容,但本文并不会深入探究到各Ftrace模组机制的实作部分,主要只以笔者自己认为值得说明的区块,来加以说明,对各项细节有兴趣的开发者,建议可以自行探究.
GCC “-pg” Profiling 机制与builtin函式对Ftrace Branch Profiling的支援
Ftrace支援在有加入 “likely/unlikely” 条件判断式位置的Brnch Profiling与对整个核心 if 条件判断式的Brnch Profiling (当然,选择后者对效能影响也比较明显...要做记录的地方变多了.).使用者可以透过Kernel hacking --->Tracers --->Branch Profiling ---> 来选择“No branch profiling”,”Trace likely/unlikely profiler” 或 “Profile all if conditionalss”. 对系统进行Branch Profiling的动作. (Ftrace在 config中有这四个设定跟Branch Profiling有关CONFIG_TRACE_BRANCH_PROFILING,CONFIG_BRANCH_PROFILE_NONE,CONFIG_PROFILE_ANNOTATED_BRANCHES 与 CONFIG_PROFILE_ALL_BRANCHES)
参考include/linux/compiler.h中的实作,如果选择“Profile all if conditionalss”,就会把全部的if条件判断字元,透过gcc precompile定义为巨集 __trace_if,如下所示
#define if(cond, ...) __trace_if( (cond , ## __VA_ARGS__) )
#define __trace_if(cond) \
if (__builtin_constant_p((cond)) ? !!(cond) : \
({ \
int ______r; \
static struct 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优化编译阶段的Branch Predition是很有帮助的).
如果是设定为”Trace likely/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__定义如下
#define likely_notrace(x) __builtin_expect(!!(x), 1)
#define unlikely_notrace(x) __builtin_expect(!!(x), 0)
#define __branch_check__(x, expect) ({ \
int ______r; \
static struct 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)实作如下所示,
void ftrace_likely_update(struct ftrace_branch_data *f, int val, int expect)
{
/*
* 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有需要修正的空间(往统计正确的方向去,就可避免处理器Pipeline Flush的机会),以便得到更好的执行效能.
若没有启动任何Branch Profiling的动作,则likely与unlikely就只会透过Builtin函式_builtin_expect (在GCC 2.96版本之后支援)进行编译阶段的Branch Predition优化动作,如下宣告
# 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),若是则可在编译时期安排好对应的执行动作,就不需要把全部的行为,都放到编译后的程式码,透过执行时期才决定.
以如下程式码来验证行为,
#define Y 6
void Func(int Z)
{
int vResult;
vResult=__builtin_constant_p(Z)?(Z*100):-1;
printf("5:Result:%ld\n",vResult);
vResult=(Z*100);
printf("6:Result:%ld\n",vResult);
}
int main()
{
int X=5;
int vResult;
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传递,因为这个值会被放到堆迭(根据每个处理器的Calling Convention,在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变数初始值的指定(文件建议要在GCC 3.0.1版本之后),如下所示,若 EXPRESSION为常数,则table初始值为该常数,反之则初始值为0.
static const int table[] = {
__builtin_constant_p (EXPRESSION) ? (EXPRESSION) : -1,
};
另一个需要介绍的Builtin函式为 __builtin_expect,这函式的功能主要在提供编译器Branch Prediction的能力,如以下的程式码
void FuncA(int X)
{
if(__builtin_expect(X,1))
{
printf("FuncA 1:%ld\n",X*0x100);
}
else
{
printf("FuncA 2:%ld\n",X);
}
}
void FuncB(int X)
{
if(__builtin_expect(X,0))
{
printf("FuncB 1:%ld\n",X*0x100);
}
else
{
printf("FuncB 2:%ld\n",X);
}
}
int main()
{
FuncA(7);
FuncB(8);
return;
}
执行结果为
FuncA 1:700h
FuncB 1:800h
以gcc 4.1.2搭配-O2进行编译(在这验证环境下,使用-O0,函式__builtin_expect会没有效果),执行结果一致,透过反组译程式码结果如下
| FuncA/B (-O0) | FuncA (-O2) - if(__builtin_expect(X,1)) | FuncB(-O2)-if(__builtin_expect(X,0)) |
| push %ebp mov %esp,%ebp sub $0x8,%esp mov 0x8(%ebp),%eax test %eax,%eax je 80483a9 <FuncA+0x25> mov 0x8(%ebp),%eax shl $0x8,%eax mov %eax,0x4(%esp) movl $0x8048500,(%esp) call 8048298 <printf@plt> jmp 80483bc <FuncA+0x38> 80483a9: mov 0x8(%ebp),%eax mov %eax,0x4(%esp) movl $0x804850d,(%esp) call 8048298 <printf@plt> leave ret | push %ebp mov %esp,%ebp sub $0x8,%esp mov 0x8(%ebp),%eax test %eax,%eax je 80483f2 <FuncA+0x22> shl $0x8,%eax mov %eax,0x4(%esp) movl $0x804853a,(%esp) call 8048298 <printf@plt> leave ret 80483f2 : movl $0x0,0x4(%esp) movl $0x8048547,(%esp) call 8048298 <printf@plt> leave ret | push %ebp mov %esp,%ebp sub $0x8,%esp mov 0x8(%ebp),%eax test %eax,%eax jne 80483b3 <FuncB+0x23> movl $0x0,0x4(%esp) movl $0x804852d,(%esp) call 8048298 <printf@plt> leave ret 80483b3 : shl $0x8,%eax mov %eax,0x4(%esp) movl $0x8048520,(%esp) call 8048298 <printf@plt> leave ret |
我们可以看到__builtin_expect(X,1)会优先把if的执行区块放到连续的程式码中,而__builtin_expect(X,0)则是会把 else的执行区块,放到前面连续的程式码中,至于执行时期会执行到if或else的区块,就根据X条件是否为0来决定.参考GCC文件,我们也可以搭配条件判断的写法
可以参考Linux Kernel中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
{….}
处理器本身也有Branch Predition的能力,如果不在有被处理器记忆到的BP Entry中,处理器通常会循序Fetch指令进来,一旦发现分支预测错误,就会Flush Pipeline,透过函式__builtin_expect,我们可以在编译时期,依据传入值的结果,决定 if/else编译为机械码时程式码排列的顺序,减少处理器Pipeline被Flush的机率,这对执行效能也是有很大的帮助.
GCC support for the GNU profiler gprof
有关GNU gprof的介绍, 可以参考网页http://www.cs.utah.edu/dept/old/texinfo/as/gprof.html .基于GCC对Profiling的支援,开发端可以透过 -pg 的编译参数,让gcc 把profiling的功能加入到程式码中,
以如下程式码为例,
int FuncA()
{
int i;
int vRet=0;
for(i=0;i<20000;i++)
{
vRet+=i;
}
return vRet;
}
int FuncB(int I)
{
int i;
int vRet=0;
for(i=0;i<9999;i++)
{
vRet+=I+FuncA();
}
return vRet;
}
int main()
{
int vResult;
vResult=FuncA();
vResult=FuncB(vResult);
printf("Result:%ld\n",vResult);
return 0;
}
透过gcc编译后,有加上 -pg 与没加上的差异如下
| 函式名稱 | 無-pg | 有加上-pg |
| main | lea 0x4(%esp),%ecx and $0xfffffff0,%esp pushl 0xfffffffc(%ecx) push %ebp mov %esp,%ebp push %ecx sub $0x24,%esp call 8048384 <FuncA> mov %eax,0xfffffff8(%ebp) mov 0xfffffff8(%ebp),%eax mov %eax,(%esp) call 80483b2 <FuncB> mov %eax,0xfffffff8(%ebp) mov 0xfffffff8(%ebp),%eax mov %eax,0x4(%esp) movl $0x8048500,(%esp) call 8048298 <printf@plt> mov $0x0,%eax add $0x24,%esp pop %ecx pop %ebp lea 0xfffffffc(%ecx),%esp ret | lea 0x4(%esp),%ecx and $0xfffffff0,%esp pushl 0xfffffffc(%ecx) push %ebp mov %esp,%ebp push %ecx sub $0x24,%esp call 804837c <mcount@plt> =>Glibc提供的mcount函式 call 80484b4 <FuncA> mov %eax,0xfffffff8(%ebp) mov 0xfffffff8(%ebp),%eax mov %eax,(%esp) call 80484e7 <FuncB> mov %eax,0xfffffff8(%ebp) mov 0xfffffff8(%ebp),%eax mov %eax,0x4(%esp) movl $0x8048680,(%esp) call 804835c <printf@plt> mov $0x0,%eax add $0x24,%esp pop %ecx pop %ebp lea 0xfffffffc(%ecx),%esp ret |
| FuncA | push %ebp mov %esp,%ebp sub $0x10,%esp movl $0x0,0xfffffffc(%ebp) movl $0x0,0xfffffff8(%ebp) jmp 80483a4 <FuncA+0x20> mov 0xfffffff8(%ebp),%eax add %eax,0xfffffffc(%ebp) addl $0x1,0xfffffff8(%ebp) cmpl $0x4e1f,0xfffffff8(%ebp) jle 804839a <FuncA+0x16> mov 0xfffffffc(%ebp),%eax leave ret | push %ebp mov %esp,%ebp sub $0x10,%esp call 804837c <mcount@plt> =>Glibc提供的mcount函式 movl $0x0,0xfffffffc(%ebp) movl $0x0,0xfffffff8(%ebp) jmp 80484d9 <FuncA+0x25> mov 0xfffffff8(%ebp),%eax add %eax,0xfffffffc(%ebp) addl $0x1,0xfffffff8(%ebp) cmpl $0x4e1f,0xfffffff8(%ebp) jle 80484cf <FuncA+0x1b> mov 0xfffffffc(%ebp),%eax leave ret |
| FuncB | push %ebp mov %esp,%ebp sub $0x10,%esp movl $0x0,0xfffffffc(%ebp) movl $0x0,0xfffffff8(%ebp) jmp 80483d7 <FuncB+0x25> call 8048384 <FuncA> add 0x8(%ebp),%eax add %eax,0xfffffffc(%ebp) addl $0x1,0xfffffff8(%ebp) cmpl $0x270e,0xfffffff8(%ebp) jle 80483c8 <FuncB+0x16> mov 0xfffffffc(%ebp),%eax leave ret | push %ebp mov %esp,%ebp sub $0x10,%esp call 804837c <mcount@plt> =>Glibc提供的mcount函式 movl $0x0,0xfffffffc(%ebp) movl $0x0,0xfffffff8(%ebp) jmp 8048511 <FuncB+0x2a> call 80484b4 <FuncA> add 0x8(%ebp),%eax add %eax,0xfffffffc(%ebp) addl $0x1,0xfffffff8(%ebp) cmpl $0x270e,0xfffffff8(%ebp) jle 8048502 <FuncB+0x1b> mov 0xfffffffc(%ebp),%eax leave ret |
[root@localhost pg]# gcc -g -pg pg.c -o pg
[root@localhost pg]# ./pg
Result:785467424
[root@localhost pg]# ls -l gmon.out
-rw-r--r-- 1 root root 464 May 13 06:32 gmon.out
[root@localhost pg]# gprof --brief ./pg
[root@localhost pg]# gprof --brief ./pg
Flat profile:
Each sample counts as 0.01 seconds.
| % time | cumulative (seconds) | self (seconds) | calls | Self (ms/call) | Total (ms/call) | name |
| 100.54 | 0.47 | 0.47 | 10000 | 0.05 | 0.05 | FuncA |
| 0 | 0.47 | 0 | 1 | 0 | 472.49 | FuncB |
=>簡要說明: 每次呼叫FuncA需要0.05ms,總共呼叫了10000次,耗時0.47秒 (ㄟ也許應該說每次呼叫FuncA需要0.047ms會比較精確一點),而FnucB被呼叫1次,耗時472.49ms (在funcB中會執行9999次FuncA).
Call graph
granularity: each sample hit covers 2 byte(s) for 2.12% of 0.47 seconds
| index | % time | self | children | called | name |
| 0 | 0 | 1/10000 | main [2] | ||
| 0.47 | 0 | 9999/10000 | FuncB [3] | ||
| [1] | 100 | 0.47 | 0 | 10000 | FuncA [1] |
=>簡要說明: 以FuncA為主體來對比,FuncA執行了10000次共0.47秒的時間,FuncB呼叫了FuncA 9999 (佔總數9999/10000), main呼叫了FuncA 1次 (佔總數1/10000)
| index | % time | self | children | called | name |
| [2] | 100 | 0 | 0.47 | main [2] | |
| 0 | 0.47 | 1 | FuncB [3] | ||
| 0 | 0 | 1/10000 | FuncA [1] |
=>簡要說明: 以main為主體來對比,main呼叫的函式(children)花了 0.47秒,分別呼叫了FuncB 佔了9999/10000(約等於1)的時間,與呼叫了FuncA佔了1/10000的時間.
| index | % time | self | children | called | name |
| 0 | 0.47 | 1 | main [2] | ||
| [3] | 100 | 0 | 0.47 | 1 | FuncB [3] |
| 0.47 | 0 | 9999/10000 | FuncA [1] |
=>簡要說明: 以funcB為主體來對比,main呼叫的函式FuncA 與funcB(children)花了0.47秒,FuncB呼叫的函式FuncA花了0.47秒 (因為最小單位為0.01秒,太接近的兩個數字如果差距是在0.01秒以內,數字就有機會變成一樣),FuncB被呼叫1次,FuncA被FuncB呼叫9999次
Index by function name
[1] FuncA [3] FuncB
Infrastructure for profiling code inserted by 'gcc -pg'.
http://www.network-theory.co.uk/docs/gccintro/gccintro_80.html
在Linux Kernel中Enable Tracer
要在核心中支援Ftrace,除了GCC編譯器要支援-pg外,所採用的C函式庫也要支援相關mcount的函式,筆者用Android SDK帶的arm-eabi-gcc 4.4.0會產生編譯錯誤“undefined reference to `__gnu_mcount_nc' “. 筆者後來是到 Sourcery 網址 http://www.codesourcery.com/sgpp/lite/arm/portal/subscription3053 下載arm-2007q3版本的編譯器與函式庫環境,以此為基礎進行ARM環境Linux Kernel 開啟Ftrace的編譯,就可以解決無法Link '__gnu_mcount_nc'的錯誤了. (有關編譯環境與Kernel Source Code版本的選擇,會隨著版本演進而有所差異,如有遇到編譯錯誤發生時,還請以各位自己所選擇的環境為主來判斷.)
接下來執行 make menuconfig.
如果是在x86的機器上,要Enable “Kernel Function Graph Trace”的功能,就要透過General setup --->Optimize for size ,選擇關閉 “Optimize for size “. 而在ARM平台上,目前沒有“Kernel Function Graph Trace”的選項,所以就不受此限制.
此外,在Linux Kernel 2.6.31 給ARM環境的組態中,目前並不支援Dynamic Ftrace,所以像是set_ftrace_filter與set_ftrace_nontrace這類可以動態設定函式名稱過濾原則的機制,在筆者環境中就無法支援,我在說明時,會以x86版本來替代,後續支援與否請以Linux Kernel版本演進為主.
在選單中進入Kernel hacking ---> 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
最後確認Debug Filesystem是否有被勾選,路徑為Kernel hacking --->-*- Debug Filesystem.
退出選單,由於剛才已經勾選 “CONFIG_FUNCTION_TRACER” 組態,可以參考檔案kernel/trace/Makefile的內容,設定 CONFIG_FUNCTION_TRACER後,就會把KBUILD_CFLAGS加上 -pg ,每個核心函式中都會被置入mcount函式的呼叫
ifdef CONFIG_FUNCTION_TRACER
ORIG_CFLAGS := $(KBUILD_CFLAGS)
KBUILD_CFLAGS = $(subst -pg,,$(ORIG_CFLAGS))
...
endif
Kernel內部有關除錯,或是Ftrace相關的檔案,會移除-pg的編譯參數,避免影響統計的結果,例如在kernel/Makefile檔案中
ifdef CONFIG_FUNCTION_TRACER
# Do not 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
比較一下,有打開 Function Tracer跟沒有打開Function Tracer的核心編譯結果如下所示,可以看到GCC編譯器,對編譯結果的影響.
| 沒有打開Ftracer的do_fork函式 | 打開Ftracer的do_fork函式 |
| 00001458 <do_fork>: push {r4, r5, r6, r7, r8, r9, sl, lr} tst r0, #268435456 ; 0x10000000 sub sp, sp, #32 ; 0x20 mov r5, r0 mov r7, r1 mov r6, r2 mov sl, r3 bne 1688 <do_fork+0x230> ands r4, r5, #33554432 ; 0x2000000 moveq r9, #0 ; 0x0 movne r9, #1 ; 0x1 bne 16c0 <do_fork+0x268> ldr r3, [r6, #64] tst r3, #15 ; 0xf bne 149c <do_fork+0x44> tst r5, #8388608 ; 0x800000 beq 1604 <do_fork+0x1ac> mov r8, #0 ; 0x0 ldr ip, [sp, #68] mov r1, r7 str ip, [sp] mov r2, r6 | 000018b0 <do_fork>: mov ip, sp push {r4, r5, r6, r7, r8, r9, sl, fp, ip, lr, pc} sub fp, ip, #4 ; 0x4 sub sp, sp, #52 ; 0x34 mov ip, lr bl 0 <mcount> .word 0x00000040 tst r0, #268435456 ; 0x10000000 mov r7, r0 mov sl, r1 mov r6, r2 str r3, [fp, #-72] bne 1c7c <do_fork+0x3cc> ands r5, r7, #33554432 ; 0x2000000 moveq r8, #0 ; 0x0 movne r8, #1 ; 0x1 mov r1, r8 ldr r0, [pc, #1060] ; 1d20 <do_fork+0x470> mov r2, #0 ; 0x0 bl 0 <ftrace_likely_update> subs r1, r8, #0 ; 0x0 |
DebugFS FileSystem
Ftrace會使用虛擬的檔案系統debugfs做為設定檔與輸出結果的儲存位置,我們可以先在根目錄產生 /debug檔案 ,然後mount debugfs到/debug目錄下 (Ftrace文件建議可以mount到/sys/kernel/debug目錄下)
# mkdir /debug
# mount -t debugfs nodev /debug
之後進入/debug/tracing目錄下
# cd /debug/tracing
查詢系統中支援哪些Tracer
$ cat available_tracers
function_graph function_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下的檔案
我們以Android ARM平台搭配Linux Kernel 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-x root 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-x root root 1970-01-01 00:00 per_cpu
drwxr-xr-x root 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-x root root 1970-01-01 00:00 trace_stat
-rw-r--r-- root root 0 1970-01-01 00:00 set_ftrace_pid
接下來,筆者以這目錄下的檔案,挑選認為應該說明的部份,如下所示
| 檔案名稱 | 說明 |
| current_tracer | 用來顯示目前被設定的Tracer. 如果沒有任何被設定的Tracer 就會返回nop # cat current_tracer nop 以 sched_switch設定到current_tracer來示範這檔案的功能 # echo > /data/debug/tracing/trace =>清空trace內容 # echo sched_switch > /data/debug/tracing/current_tracer # echo 1 > /data/debug/tracing/tracing_enabled # sleep 1 # echo 0 > /data/debug/tracing/tracing_enabled #cat /data/debug/tracing/trace # tracer: sched_switch # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | bash-9560 [000] 52138.209612: 9560:120:R ==> [000] 9538:120:R kworker/0:1 kworker/0:1-9538 [000] 52138.209903: 9538:120:S ==> [000] 9558:120:R in.telnetd in.telnetd-9558 [000] 52138.211017: 9558:120:S ==> [000] 9560:120:R bash bash-9560 [000] 52138.211412: 9560:120:S + [000] 9560:120:S bash bash-9560 [000] 52138.211613: 9560:120:R + [000] 9538:120:R kworker/0:1 bash-9560 [000] 52138.211820: 9560:120:R ==> [000] 9538:120:R kworker/0:1 kworker/0:1-9538 [000] 52138.211990: 9538:120:R + [000] 9558:120:R in.telnetd kworker/0:1-9538 [000] 52138.212148: 9538:120:S ==> [000] 9558:120:R in.telnetd in.telnetd-9558 [000] 52138.212953: 9558:120:S ==> [000] 9560:120:R bash bash-9560 [000] 52138.213221: 9560:120:S ==> [000] 0:120:R <idle> <idle>-0 [000] 52138.414815: 0:120:R + [000] 9538:120:R kworker/0:1 <idle>-0 [000] 52138.414976: 0:120:R ==> [000] 9538:120:R kworker/0:1 kworker/0:1-9538 [000] 52138.415243: 9538:120:S ==> [000] 0:120:R <idle> <idle>-0 [000] 52138.417111: 0:120:R + [000] 9538:120:R kworker/0:1 <idle>-0 [000] 52138.417312: 0:120:R ==> [000] 9538:120:R kworker/0:1 kworker/0:1-9538 [000] 52138.417541: 9538:120:S ==> [000] 0:120:R <idle> <idle>-0 [000] 52138.448254: 0:120:R + [000] 1811:120:R pcscd <idle>-0 [000] 52138.448547: 0:120:R ==> [000] 1811:120:R pcscd pcscd-1811 [000] 52138.450170: 1811:120:S ==> [000] 0:120:R <idle> <idle>-0 [000] 52138.540657: 0:120:R + [000] 1892:139:R gam_server |
| available_tracers | 列出目前Linux Kernel中在編譯時有被啟用的Tracer. 我們只要把這些對應的名字設定到current_tracer中就可以啟用對應的Tracer. 如下所示為筆者環境中所支持的Tracer. # cat available_tracers blk kmemtrace branch wakeup_rt wakeup irqsoff function sched_switch initcall nop |
| tracing_enabled | 用以控制Tracer的啟動或是停止,當為1時表示Tracer啟動,反之,為0就是停止,如下所示 啟動 Tracer #echo 1 > /data/debug/tracing/tracing_enabled 暫停 Tracer #echo 0 > /data/debug/tracing/tracing_enabled |
| trace | 用以把Tracer的結果呈現出人可閱讀的格式. #more /data/debug/tracing/trace 清空Tracer結果內容 #echo > /data/debug/tracing/trace |
| trace_pipe | 支援以pipe的機制讀取跟trace檔案一樣的內容,並以Block的機制讀取,直到有資料進來後才會返回,每次資料讀取後,下一次讀取,就會讀取到新的資料,適合用來循序讀取,把Trace內容依序讀出來. 如果希望每次都讀取到完整的trace buffer內容,就從trace檔案中讀取,反之,如果是每次都要讀到沒讀取到的資料,就可以從trace_pipe中讀取. |
| trace_options | 可以用來控制trace要顯示的資料內容. (ㄟ 也必須要該Plug-in Tracer有支援對應的Options). #cat trace_options print-parent nosym-offset nosym-addr noverbose noraw nohex nobin noblock nostacktrace nosched-tree trace_printk noftrace_preempt nobranch annotate nouserstacktrace nosym-userobj noprintk-msg-only context-info nolatency-format noglobal-clock sleep-time graph-time 控制方式為,把Option內容選擇加上 no (關閉)或是移除no(開啟), 例如: 關閉print-parent # echo noprint-parent > /data/debug/tracing/trace_options 重新 cat trace_options就會看到print-parent變成noprint-parent 反之,原本設定為nosym-addr,透過 #echo sym-addr > /data/debug/tracing/trace_options 重新 cat trace_options就會看到nosym-addr 變成 sym-addr |
| tracing_max_latency | 用以顯示剛才的Tracer進行Latency統計時(例如: irqsoff 或是 wakeup...etc),最大的 Latency數值為何(單位為 us),以提供核心設計者,找出系統中比較缺乏效率的部份,加以改善.
# echo irqsoff > /data/debug/tracing/current_tracer # echo 1 > /data/debug/tracing/tracing_enabled ….do somehting....sleep.... # echo 0 > /data/debug/tracing/tracing_enabled # more tracing_max_latency 7367 # more /data/debug/tracing/trace # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 2.6.38.6 # -------------------------------------------------------------------- # latency: 7367 us, #58/58, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:1) # ----------------- # | task: bash-1905 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # => started at: apic_timer_interrupt # => ended at: call_on_stack # # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| /_--=> lock-depth # |||||/ delay # cmd pid |||||| time | caller # \ / |||||| \ | / ...etc |
| buffer_size_kb | 用來設定每個處理器要用多少記憶體空間當做Tracer Buffer (單位為kbytes)(一般而言一個Page單位為4kbytes)(每個處理器都會依據此值配置一樣大的空間), 例如: #cat buffer_size_kb 1408 就表示在筆者環境中為每個處理器用 1.408MB當做Tracer Buffer. 這個值只有在current_tracer內容為 “nop”時才可以修改. (也就是說要沒有啟用任何Tracer Plug-in才可以修改這個值) |
| tracing_cpumask | 用來設定Tracer要在哪個處理器上蒐集資訊. 顯示的為字串16進位的字串.在筆者單核ARM的環境中執行如下 #cat tracing_cpumask 1 # |
| set_ftrace_filter | 用在動態Ftrace的組態下,程式碼在編譯過程中被gcc -pg置入呼叫mcount函式的行為,在支援動態Ftrace (Dynamic Ftrace)的環境中,只有在透過這檔案設定的函式,才會被納入Function Trace中. 設定Trace Functon開頭為 account與run的函式呼叫行為,如下指令所示 #echo > /debug/tracing/trace #echo 'account*' 'run*' > /debug/tracing/set_ftrace_filter #echo function > /debug/tracing/current_tracer #echo 1 > /debug/tracing/tracing_enabled #sleep 1 #echo 0 > /debug/tracing/tracing_enabled #cat /debug/tracing/trace # tracer: function # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | bash-1951 [000] 2602.286489: account_process_tick <-update_process_times bash-1951 [000] 2602.286501: account_system_time <-account_process_tick bash-1951 [000] 2602.286510: run_local_timers <-update_process_times bash-1951 [000] 2602.286565: run_posix_cpu_timers <-update_process_times bash-1951 [000] 2602.286605: run_timer_softirq <-__do_softirq kworker/0:0-4 [000] 2602.287494: account_process_tick <-update_process_times kworker/0:0-4 [000] 2602.287503: account_system_time <-account_process_tick kworker/0:0-4 [000] 2602.287509: run_local_timers <-update_process_times kworker/0:0-4 [000] 2602.287565: run_posix_cpu_timers <-update_process_times kworker/0:0-4 [000] 2602.287605: run_timer_softirq <-__do_softirq …. 在筆者的Linux Kernel 2.6.31 ARM的設置中,目前並沒有支援 HAVE_DYNAMIC_FTRACE,也就是說在ARM版本中這個檔案屬性會無法使用. (還請以各位手中的Linux Kernel版本為主,看是否有新的更新.) |
| set_ftrace_notrace | 跟set_ftrace_filter相反,在動態Ftrace(Dynamic Ftrace)的組態下,那設定到這檔案中的函式名稱,都會被取消呼叫mcount的動作,不納入Function Trace的機制中. 如果同一個函式同時被設定到 set_ftrace_filter 與 set_ftrace_notrace,則該函式將會以 set_ftrace_notrace為主,將不納入Trace中. 設定不要Trace有包含cpu與align字元的函式名稱,如下指令所示 # echo '*cpu*' '*align*' > /debug/tracing/set_ftrace_notrace #echo function > /debug/tracing/current_tracer #echo 1 > /debug/tracing/tracing_enabled #sleep 1 #echo 0 > /debug/tracing/tracing_enabled #cat /debug/tracing/trace # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | bash-1951 [000] 2331.630911: calc_global_load <-do_timer bash-1951 [000] 2331.630921: update_process_times <-tick_periodic bash-1951 [000] 2331.630929: account_process_tick <-update_process_times bash-1951 [000] 2331.630937: account_system_time <-account_process_tick bash-1951 [000] 2331.630945: run_local_timers <-update_process_times bash-1951 [000] 2331.630953: hrtimer_run_queues <-run_local_timers bash-1951 [000] 2331.630967: __current_kernel_time <-hrtimer_run_queues bash-1951 [000] 2331.630974: __get_wall_to_monotonic <-hrtimer_run_queues bash-1951 [000] 2331.630984: _raw_spin_lock <-hrtimer_run_queues bash-1951 [000] 2331.630995: raise_softirq <-run_local_timers bash-1951 [000] 2331.631006: rcu_check_callbacks <-update_process_times bash-1951 [000] 2331.631014: rcu_bh_qs <-rcu_check_callbacks bash-1951 [000] 2331.631022: __rcu_pending <-rcu_check_callbacks …. 在筆者的Linux Kernel 2.6.31 ARM的設置中,目前並沒有支援 HAVE_DYNAMIC_FTRACE,也就是說在ARM版本中這個檔案屬性會無法使用. (還請以各位手中的Linux Kernel版本為主,看是否有新的更新.) |
| set_ftrace_pid | 設定Function tracer只針對特定的PID進行蒐集. (如果不設定這個值,而是對全系統蒐集,很有可能會讓系統Hang住=>在我的ARM環境中不設定PID縮小範圍,就會Hang住...@_@) 操作範例如下, #cat /debug/tracing/set_ftrace_pid no pid #ps =>找一個要Trace的Process ID USER PID PPID VSIZE RSS WCHAN PC NAME …. system 65 31 152436 25296 ffffffff afd0db4c S system_server app_23 128 31 111664 20728 ffffffff afd0eb08 S com.android.launcher …. # echo 65 > /data/debug/tracing/set_ftrace_pid # echo function > /data/debug/tracing/current_tracer # echo 1 > /data/debug/tracing/tracing_enabled ….do something.... #cat /data/debug/tracing/trace ….此時 trace中就只會顯示該 PID的tracing結果... |
| available_filter_functions | 這個檔案會列出目前所有可以供"set_ftrace_filter" 或 "set_ftrace_notrace"用來設定過濾條件的函式名稱. 例如: # more /debug/tracing/available_filter_functions _stext do_one_initcall run_init_process init_post name_to_dev_t match_dev_by_uuid thread_saved_pc get_wchan prepare_to_copy release_thread copy_thread start_thread __show_regs cpu_idle setup_sigcontext align_sigframe signal_fault sys_sigaltstack restore_sigcontext sys_sigaction sys_rt_sigreturn do_notify_resume ….etc |
介紹Ftrace每個模組
Ftrace的設計概念為提供Plug-in Framework的機制,隨著核心模組的演進,如果需要針對新的核心模組進行效能上的統計分析時,就可以透過Plug-in的方式,撰寫新的Ftrace模組達成新的tracer目的,作為一個可延展性的Tracer 架構,本段落會介紹Ftrace主要支援的Tracer模組,這些模組的數量或是功能,都有可能隨著Linux Kernel演進而有所改動 (例如:Kernel 2.6.39移除 Kernel Lock),版本的更迭,都請以最新的Linux Kernel Source Code為主要依據.
| 名稱 | 說明 | ||||||||||||||||||||||||||||||||||||||||
| Function tracer | 設定路徑為Kernel hacking --->Tracers --->Kernel Function Tracer 用以顯示,Function呼叫的流程與順序
操作範例如下所示: #echo 1855 > /debug/tracing/set_ftrace_pid =>選擇vsftpd 的PID (=1855) #echo function > /debug/tracing/current_tracer =>選擇Function Tracer #echo 1 > /debug/tracing/tracing_enabled =>之後透過另一台電腦經由FTP連線到這主機來,就可以記錄到這Daemon Function操作的行為 #echo 0 > /debug/tracing/tracing_enabled #cat /debug/tracing/trace > /trace.txt #echo nop > /debug/tracing/current_tracer =>移除Tracer 再來看 trace.txt中結果如下 # tracer: function # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | vsftpd-1964 [000] 272.754213: irq_exit <-smp_apic_timer_interrupt vsftpd-1964 [000] 272.754222: do_softirq <-irq_exit vsftpd-1964 [000] 272.754229: call_on_stack <-do_softirq vsftpd-1964 [000] 272.754235: __do_softirq <-call_on_stack vsftpd-1964 [000] 272.754241: __local_bh_disable <-__do_softirq vsftpd-1964 [000] 272.754279: run_timer_softirq <-__do_softirq vsftpd-1964 [000] 272.754302: hrtimer_run_pending <-run_timer_softirq vsftpd-1964 [000] 272.754324: _raw_spin_lock_irq <-run_timer_softirq vsftpd-1964 [000] 272.754347: rcu_bh_qs <-__do_softirq vsftpd-1964 [000] 272.754378: rcu_process_callbacks <-__do_softirq vsftpd-1964 [000] 272.754400: __rcu_process_callbacks <-rcu_process_callbacks vsftpd-1964 [000] 272.754422: force_quiescent_state <-__rcu_process_callbacks vsftpd-1964 [000] 272.754444: rcu_gp_in_progress <-force_quiescent_state …... 可以看到在vsftpd對應處理Client需求的行程運作時,Linux Kernel這所對應調用的函式行為與時間值. | ||||||||||||||||||||||||||||||||||||||||
| Dynamic selection of functions 設定路徑為Kernel hacking --->Tracers --->enable/disable ftrace tracepoints dynamically 由於對全部Function Tracing的成本很高,以筆者所用的ARM環境而言,幾乎會導致系統無法正常的反應(mmm,如果你是用ARM Cortex A系列的處理器,應該就會很順了...),Ftrace也提供了動態選擇Function(Dynamic selection of functions) 進行Tracing的機制,以筆者所驗證的Linux Kernel 2.6.31而言,目前在ARM平台尚未支援這機制,而X86平台則可以支援. 使用範例如下的寫法,選擇只追蹤函式名稱包含有 spin與process字串的Linux Kernel Function呼叫 #echo '*spin*' '*process*' > /debug/tracing/set_ftrace_filter 執行結果如下所示 # tracer: function # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | vsftpd-1855 [000] 5064.651690: _raw_spin_lock_bh <-lock_sock_nested vsftpd-1855 [000] 5064.651739: _raw_spin_lock_bh <-release_sock vsftpd-1855 [000] 5064.651760: _raw_spin_unlock_bh <-release_sock vsftpd-1855 [000] 5064.651780: _raw_spin_lock_bh <-lock_sock_nested vsftpd-1855 [000] 5064.651800: _raw_spin_lock_bh <-release_sock vsftpd-1855 [000] 5064.651819: _raw_spin_unlock_bh <-release_sock vsftpd-1855 [000] 5064.651840: _raw_spin_lock <-fd_install vsftpd-1855 [000] 5064.651871: _raw_spin_lock_irq <-sigprocmask vsftpd-1855 [000] 5064.651924: _raw_spin_lock_irq <-sigprocmask vsftpd-1855 [000] 5064.651974: _raw_spin_lock <-tick_periodic vsftpd-1855 [000] 5064.652009: update_process_times <-tick_periodic vsftpd-1855 [000] 5064.652017: account_process_tick <-update_process _times vsftpd-1855 [000] 5064.652034: _raw_spin_lock <-hrtimer_run_queues vsftpd-1855 [000] 5064.652082: _raw_spin_lock <-scheduler_tick vsftpd-1855 [000] 5064.652164: _raw_spin_lock_irq <-run_timer_softir q vsftpd-1855 [000] 5064.652241: copy_process <-do_fork vsftpd-1855 [000] 5064.652278: _raw_spin_lock <-cache_alloc_refill ….. 就只會看到有包含 spin與process字串的函式呼叫, 接下來,如果要把有包含 raw 與 times字元的函式過濾掉,可透過如下設定 # echo '*raw*' '*times*' > /debug/tracing/set_ftrace_notrace 執行結果如下所示 # tracer: function # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | vsftpd-2099 [000] 5220.419859: tcp_rcv_state_process <-tcp_v4_do_rcv vsftpd-2099 [000] 5220.419996: account_process_tick <-update_process_times vsftpd-2099 [000] 5220.420520: tcp_child_process <-tcp_v4_do_rcv vsftpd-2099 [000] 5220.420542: tcp_rcv_state_process <-tcp_child_process vsftpd-2099 [000] 5220.420913: wake_up_process <-wake_up_worker vsftpd-2099 [000] 5220.421737: account_process_tick <-update_process_times vsftpd-1855 [000] 5220.422045: account_process_tick <-update_process_times vsftpd-1855 [000] 5220.422358: copy_process <-do_fork vsftpd-1855 [000] 5220.422953: account_process_tick <-update_process_times vsftpd-2099 [000] 5220.423830: tcp_rcv_state_process <-tcp_v4_do_rcv vsftpd-2099 [000] 5220.423903: kick_process <-signal_wake_up vsftpd-2099 [000] 5220.423961: account_process_tick <-update_process_times vsftpd-2099 [000] 5220.424257: kick_process <-signal_wake_up ….. 可以看到最後的結果,就是會包含有 spin與process字串的函式呼叫,並且把其中有包括 raw與times字串的函式呼叫過濾掉. | |||||||||||||||||||||||||||||||||||||||||
| Function graph tracer 設定路徑為Kernel hacking --->Tracers --->Kernel Function Tracer --->Kernel Function Graph Tracer 以筆者所驗證的Linux Kernel 2.6.31而言,目前在ARM平台尚未支援這機制,而X86平台則可以支援. 操作範例如下所示, #echo '*' > /debug/tracing/set_ftrace_filter =>恢復對所有函式的Tracing #echo function_graph > /debug/tracing/current_tracer #echo 1 > /debug/tracing/tracing_enabled =>讓 FTP Client連進來 # echo 0 > /debug/tracing/tracing_enabled 執行結果如下所示 # tracer: function_graph # # TIME CPU DURATION FUNCTION CALLS # | | | | | | | | 0) 7.525 us | } /* idle_cpu */ 0) + 36.032 us | } /* irq_enter */ 0) | tick_handle_periodic() { 0) | tick_periodic() { 0) | do_timer() { 0) + 16.017 us | update_wall_time(); 0) 6.749 us | calc_global_load(); 0) + 43.684 us | } 0) | account_process_tick() { 0) 6.852 us | account_system_time(); 0) + 20.041 us | } 0) | run_local_timers() { 0) | hrtimer_run_queues() { 0) 6.243 us | __current_kernel_time(); 0) 6.183 us | __get_wall_to_monotonic(); 0) + 35.781 us | } 0) 9.591 us | raise_softirq(); 0) + 65.198 us | } 0) | rcu_check_callbacks() { 0) 6.357 us | idle_cpu(); 0) | __rcu_pending() { 0) 6.199 us | rcu_gp_in_progress(); 0) 6.218 us | cpu_has_callbacks_ready_to_invoke(); 0) 6.265 us | cpu_needs_another_gp(); 0) 6.175 us | rcu_gp_in_progress(); 0) + 59.513 us | } 0) 6.867 us | raise_softirq(); 0) + 98.833 us | } 0) 6.292 us | printk_tick(); 0) | scheduler_tick() { 0) + 11.142 us | ktime_get(); 0) 7.172 us | update_rq_clock(); 0) | sched_avg_update() { 0) 6.353 us | sched_avg_period(); 0) + 19.685 us | } 0) | task_tick_fair() { 0) 6.826 us | update_curr(); 0) | sched_slice() { 0) 6.851 us | calc_delta_mine(); 0) + 20.522 us | } 原本結果顯示的是時間差,也可以透過 trace_options選擇顯示絕對時間值 # echo funcgraph-abstime >/debug/tracing/trace_options 執行結果如下所示 # tracer: function_graph # # TIME CPU DURATION FUNCTION CALLS # | | | | | | | | 8919.132197 | 0) ! 201.630 us | } /* __do_softirq */ 8919.132218 | 0) ! 265.733 us | } /* do_softirq */ 8919.132229 | 0) ! 297.422 us | } /* irq_exit */ ------------------------------------------ 0) vsftpd-2125 => <...>-1855 ------------------------------------------ 8919.132798 | 0) + 50.964 us | irq_enter(); 8919.132908 | 0) + 25.462 us | raise_softirq(); 8919.133053 | 0) | irq_exit() { 8919.133076 | 0) | do_softirq() { 8919.133095 | 0) | __do_softirq() { 8919.133153 | 0) + 43.064 us | run_timer_softirq(); 8919.133245 | 0) ! 148.201 us | } 8919.133260 | 0) ! 185.542 us | } 8919.133272 | 0) ! 221.503 us | } 8919.134684 | 0) + 47.945 us | irq_enter(); 8919.134785 | 0) + 19.704 us | raise_softirq(); 8919.134911 | 0) | irq_exit() { 8919.134931 | 0) | do_softirq() { 8919.134949 | 0) | __do_softirq() { 8919.135019 | 0) + 17.437 us | irq_enter(); 8919.135080 | 0) + 18.143 us | raise_softirq(); 8919.135165 | 0) + 19.679 us | irq_exit(); 8919.135230 | 0) + 39.134 us | run_timer_softirq(); 8919.135307 | 0) + 33.181 us | run_timer_softirq(); 8919.135384 | 0) ! 434.587 us | } 8919.135398 | 0) ! 468.233 us | } 8919.135408 | 0) ! 500.772 us | } ------------------------------------------ 0) <...>-1855 => vsftpd-2125 ------------------------------------------ 8919.135778 | 0) + 43.128 us | irq_enter(); 8919.135900 | 0) + 18.773 us | raise_softirq(); 8919.136019 | 0) | irq_exit() { 8919.136037 | 0) | do_softirq() { 8919.136052 | 0) | __do_softirq() { 8919.136100 | 0) + 37.945 us | run_timer_softirq(); 8919.136179 | 0) ! 125.562 us | } 8919.136192 | 0) ! 155.517 us | } 8919.136201 | 0) ! 184.853 us | } | |||||||||||||||||||||||||||||||||||||||||
| Latency Tracing | 1, irqsoff tracer 設定路徑為Kernel hacking --->Tracers --->Interrupts-off Latency Tracer 主要用來Tracing中斷被關閉的行為,並且會把關閉最久的時間與對應的呼叫動作顯示出來,提供系統效能分析的判斷之用,例如:當在中斷中做了過多I/O的行為,就會對系統效能造成影響,透過分析可以把這類設計移到Bottom-Half (HISR)中處理,減少系統把中斷關閉所導致的效能影響. (屬於I/O的等待應該放到系統閒置的時間才處理,在中斷裡要越快結束越好,把處理器執行時間讓給優先級高的Task). 執行範例如下所示 # echo nop > current_tracer # echo irqsoff > current_tracer # echo 1 > tracing_enabled # sleep 3 # echo 0 >tracing_enabled
顯示結果如下
# tracer: irqsoff # # irqsoff latency trace v1.1.5 on 2.6.38.6 # -------------------------------------------------------------------- # latency: 10747 us, #123/123, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:1) # ----------------- # | task: vsftpd-1961 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # => started at: __make_request # => ended at: __blk_run_queue # # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| /_--=> lock-depth # |||||/ delay # cmd pid |||||| time | caller # \ / |||||| \ | / vsftpd-1961 0dN... 23us+: _raw_spin_lock_irq <-__make_request vsftpd-1961 0dN... 103us+: cpu_coregroup_mask <-__make_request vsftpd-1961 0dN... 118us!: elv_queue_empty <-__make_request vsftpd-1961 0dN... 997us+: cfq_queue_empty <-elv_queue_empty vsftpd-1961 0dN... 1055us+: blk_plug_device <-__make_request vsftpd-1961 0dN... 1109us!: mod_timer <-blk_plug_device vsftpd-1961 0dN... 1216us+: lock_timer_base <-mod_timer vsftpd-1961 0dN... 1231us+: _raw_spin_lock_irqsave <-lock_timer_base vsftpd-1961 0dN... 1253us+: internal_add_timer <-mod_timer vsftpd-1961 0dN... 1270us+: _raw_spin_unlock_irqrestore <-mod_timer vsftpd-1961 0dN... 1369us!: drive_stat_acct <-__make_request vsftpd-1961 0dN... 1480us!: disk_map_sector_rcu <-drive_stat_acct vsftpd-1961 0dN... 1713us+: part_round_stats <-drive_stat_acct vsftpd-1961 0dN... 1782us+: part_round_stats_single <-part_round_stats vsftpd-1961 0dN... 1832us!: part_round_stats_single <-part_round_stats vsftpd-1961 0dN... 1938us+: __elv_add_request <-__make_request vsftpd-1961 0dN... 1993us!: elv_insert <-__elv_add_request vsftpd-1961 0dN... 2100us!: elv_rqhash_add <-elv_insert vsftpd-1961 0dN... 2259us+: cfq_insert_request <-elv_insert vsftpd-1961 0dN... 2330us+: cfq_init_prio_data <-cfq_insert_request vsftpd-1961 0dN... 2421us+: cfq_add_rq_rb <-cfq_insert_request vsftpd-1961 0dN... 2489us!: elv_rb_add <-cfq_add_rq_rb vsftpd-1961 0dN... 2637us+: cfq_resort_rr_list <-cfq_add_rq_rb vsftpd-1961 0dN... 2689us+: cfq_service_tree_add <-cfq_resort_rr_list vsftpd-1961 0dN... 2724us+: cfqq_type <-cfq_service_tree_add ….. vsftpd-1961 0dN... 10463us+: _raw_spin_lock_irqsave <-lock_timer_base vsftpd-1961 0dN... 10476us+: internal_add_timer <-mod_timer vsftpd-1961 0dN... 10490us+: _raw_spin_unlock_irqrestore <-mod_timer vsftpd-1961 0dN... 10562us!: _raw_spin_lock <-scsi_request_fn vsftpd-1961 0dN... 10736us+: scsi_request_fn <-__blk_run_queue vsftpd-1961 0dN... 10760us+: trace_hardirqs_on <-__blk_run_queue …. 其中,中間六個屬性數值意義分別為 1,CPU : 該任務所運作的CPU ID 2,irqs-off : 'd'=關閉中斷, '.'=中斷沒關閉,'X'=該平台不支援讀取IRQ Flag 3,need-resched: 'N'=need_resched被設置(表示行程會重新排程), '.'=前項不成立. 4,hardirq/softirq: 'H'=在軟體中斷進行過程中,發生的硬體中斷 , 'h' =正在硬體中斷處理中, 's' =正在軟體中斷處理中, '.' =一般行程運作中 5,preempt-depth: 表示preempt_disabled的Level 6,lock-depth: 接下來屬於 time的欄位,單位為 us,代表的是從呼叫的函式到被呼叫的函式所經過的時間,這段時間如果超過 preempt_mark_thresh (default 100)的值,時間後面就會標示 '!',如果超過1個us,就會標示 '+',如果小於或等於1us則部會標示任何符號. 以這例子來說,起點會在函式__make_request (實作在block/blk-core.c中) 呼叫spin_lock_irq關閉硬體中斷,最後在函式__blk_run_queue(實作在block/blk-core.c中)後,恢復硬體中斷運作. =>恢復中斷的流程,是呼叫函式trace_hardirqs_on(實作在kernel/lockdep.c中),再呼叫到函式trace_hardirqs_on_caller(實作在kernel/lockdep.c中),完成恢復硬體中斷的動作. 2, Wakeup tracer 設定路徑為Kernel hacking --->Tracers --->Scheduling Latency Tracer 可用以顯示 Real-Time Task取得執行權所需等待的時間,操作範例如下所示
# echo wakeup > current_tracer # echo 1 > tracing_enabled # chrt -f 10 ps ==>用real-Time 權限10執行 ps 指令 執行結果如下
# tracer: wakeup # # wakeup latency trace v1.1.5 on 2.6.38.6 # -------------------------------------------------------------------- # latency: 5961 us, #149/149, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:1) # ----------------- # | task: kworker/0:1-9481 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| /_--=> lock-depth # |||||/ delay # cmd pid |||||| time | caller # \ / |||||| \ | / gam_serv-1892 0dNs.. 15us!: 1892:139:R + [000] 9481:120:R kworker/0:1 gam_serv-1892 0dNs.. 171us+: wake_up_process <-wake_up_worker gam_serv-1892 0dNs.. 187us+: check_preempt_curr <-try_to_wake_up gam_serv-1892 0dNs.. 199us+: check_preempt_wakeup <-check_preempt_curr gam_serv-1892 0dNs.. 214us+: update_curr <-check_preempt_wakeup …. gam_serv-1892 0.N... 5392us+: mutex_lock <-inotify_poll gam_serv-1892 0.N... 5416us+: _cond_resched <-mutex_lock gam_serv-1892 0.N... 5431us!: __cond_resched <-_cond_resched gam_serv-1892 0.N... 5668us+: schedule <-__cond_resched gam_serv-1892 0.N... 5697us+: rcu_note_context_switch <-schedule gam_serv-1892 0.N... 5727us+: rcu_sched_qs <-rcu_note_context_switch gam_serv-1892 0.N... 5755us+: _raw_spin_lock_irq <-schedule gam_serv-1892 0dN... 5785us+: update_rq_clock <-schedule gam_serv-1892 0dN... 5798us+: put_prev_task_fair <-schedule gam_serv-1892 0dN... 5805us+: update_curr <-put_prev_task_fair gam_serv-1892 0dN... 5812us+: check_spread <-put_prev_task_fair gam_serv-1892 0dN... 5821us+: __enqueue_entity <-put_prev_task_fair gam_serv-1892 0dN... 5839us+: pick_next_task_fair <-schedule gam_serv-1892 0dN... 5845us+: __pick_next_entity <-pick_next_task_fair gam_serv-1892 0dN... 5853us+: clear_buddies <-pick_next_task_fair gam_serv-1892 0dN... 5862us+: set_next_entity <-pick_next_task_fair gam_serv-1892 0dN... 5869us+: update_stats_wait_end <-set_next_entity gam_serv-1892 0dN... 5880us+: __dequeue_entity <-set_next_entity gam_serv-1892 0d.... 5937us+: schedule <-__cond_resched gam_serv-1892 0d.... 5943us : 1892:139:R ==> [000] 9481:120:R kworker/0:1 根據上述的結果,我們可以看到花了約5961us從由kworker交出執行權到重新取得執行權,上面的列表中,包括了超過 1us的函式呼叫標示為'+',與超過100us的函式呼叫標示為'!',以如下的行為來說,就是從函式set_next_entity呼叫函式 update_stats_wait_end到函式set_next_entity呼叫函式__dequeue_entity ,中間間隔了 5880-5869=11us的時間(因為超過1us所以標示為'+') gam_serv-1892 0dN... 5869us+: update_stats_wait_end <-set_next_entity gam_serv-1892 0dN... 5880us+: __dequeue_entity <-set_next_entity 或是 gam_serv-1892 0.N... 5431us!: __cond_resched <-_cond_resched gam_serv-1892 0.N... 5668us+: schedule <-__cond_resched | ||||||||||||||||||||||||||||||||||||||||
| Task Context-Switch Schedule tracer | 設定路徑為Kernel hacking --->Tracers --->Scheduling Latency Tracer 用以解析Task Context-Switch的資訊,可以參考如下的範例 # echo > /data/debug/tracing/trace =>清空trace內容 # echo sched_switch > /data/debug/tracing/current_tracer # echo 1 > /data/debug/tracing/tracing_enabled # sleep 1 # echo 0 > /data/debug/tracing/tracing_enabled #cat /data/debug/tracing/trace # tracer: sched_switch # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | events/0-4 [000] 1044.598519: 4:115:S ==> [000] 87:120:R AlarmManager AlarmManager-87 [000] 1044.598749: 87:120:R + [000] 69:118:S ActivityManager AlarmManager-87 [000] 1044.599057: 87:120:R ==> [000] 69:118:R ActivityManager ActivityManager-69 [000] 1044.599411: 69:118:S ==> [000] 87:120:R AlarmManager AlarmManager-87 [000] 1044.599643: 87:120:R + [000] 69:118:S ActivityManager AlarmManager-87 [000] 1044.599957: 87:120:R ==> [000] 69:118:R ActivityManager ActivityManager-69 [000] 1044.600498: 69:118:S ==> [000] 87:120:R AlarmManager AlarmManager-87 [000] 1044.600929: 87:120:R + [000] 69:118:S ActivityManager AlarmManager-87 [000] 1044.601509: 87:120:R ==> [000] 69:118:R ActivityManager ActivityManager-69 [000] 1044.602102: 69:118:R + [000] 72:120:S ProcessStats ActivityManager-69 [000] 1044.604484: 69:118:R + [000] 67:118:S er.ServerThread ActivityManager-69 [000] 1044.604661: 69:118:R ==> [000] 67:118:R er.ServerThread er.ServerThread-67 [000] 1044.605145: 67:118:S ==> [000] 72:120:R ProcessStats ProcessStats-72 [000] 1044.611966: 72:120:R ==> [000] 69:118:R ActivityManager 如上所示,所列出的數據分別包含Task ID/Name,運作的處理器ID(供多核心的環境分析),每次觸發的時間值, 如下以上述例子做一些說明 AlarmManager-87 [000] 1044.600929: 87:120:R + [000] 69:118:S ActivityManager =>PID 87,執行優先級120,Task狀態為 Running,運作在處理器0的AlarmManager, 會喚醒 PID 69,執行優先級118,Task狀態為Sleep運作在處理器0的ActivityManager AlarmManager-87 [000] 1044.601509: 87:120:R ==> [000] 69:118:R ActivityManager =>PID 87,執行優先級120,Task狀態為 Running,運作在處理器0的AlarmManager, 會把執行權切換(Context-Switch)到 PID 69,執行優先級118,Task狀態為Running運作在處理器0的ActivityManager ActivityManager-69 [000] 1044.602102: 69:118:R + [000] 72:120:S ProcessStats =>PID 69,執行優先級118,Task狀態為 Running,運作在處理器0的ActivityManager, 會喚醒 PID 72,執行優先級120,Task狀態為Sleep運作在處理器0的ProcessStats ActivityManager-69 [000] 1044.604484: 69:118:R + [000] 67:118:S er.ServerThread =>PID 69,執行優先級118,Task狀態為 Running,運作在處理器0的ActivityManager, 會喚醒 PID 67,執行優先級118,Task狀態為Sleep運作在處理器0的er.ServerThread ActivityManager-69 [000] 1044.604661: 69:118:R ==> [000] 67:118:R er.ServerThread =>PID 69,執行優先級118,Task狀態為 Running,運作在處理器0的ActivityManager , 會把執行權切換(Context-Switch)到 PID 67,執行優先級118,Task狀態為Running運作在處理器0的er.ServerThread 有關Task Priority 參考如下表 (技術部分也可以參考筆者這篇文章 Linux 2.4/2.6 核心排程機制剖析 ”http://loda.hala01.com/2009/04/linux-2426-%e6%a0%b8%e5%bf%83%e6%8e%92%e7%a8%8b%e6%a9%9f%e5%88%b6%e5%89%96%e6%9e%90/”)
有關Task 狀態 參考如下表
| ||||||||||||||||||||||||||||||||||||||||
| Block Device Tracer | 設定路徑為Kernel hacking --->Tracers --->Support for tracing block io actions 可以用來監控儲存裝置的使用狀況,與行為 例如筆者要啟動Block Device 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=1 charge=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 A R 221728392 + 56 <- (253,0) 221728008 cc1-21557 [000] 6663.920576: 8,2 A R 221937237 + 56 <- (8,2) 221728392 cc1-21557 [000] 6663.920577: 8,2 Q R 221937237 + 56 [cc1] cc1-21557 [000] 6663.920751: 8,2 m N cfq21557 alloced cc1-21557 [000] 6663.920816: 8,2 G R 221937237 + 56 [cc1] cc1-21557 [000] 6663.920875: 8,2 P N [cc1] cc1-21557 [000] 6663.921844: 8,2 I R 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 U N [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:0 wl_type:2 ….............. ld-21578 [000] 6665.826767: 8,2 U N [ld] 0 ld-21578 [000] 6665.826865: 8,2 U N [ld] 0 ld-21578 [000] 6665.829130: 8,2 U N [ld] 0 ld-21578 [000] 6665.831853: 8,2 U N [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.920115: 8,2 A R 221728880 + 8 <- (253,0) 221728496 make-21583 [000] 6665.920121: 8,2 A R 221937725 + 8 <- (8,2) 221728880 make-21583 [000] 6665.920123: 8,2 Q R 221937725 + 8 [make] make-21583 [000] 6665.920468: 8,2 m N cfq21583 alloced make-21583 [000] 6665.920646: 8,2 G R 221937725 + 8 [make] make-21583 [000] 6665.920691: 8,2 P N [make] make-21583 [000] 6665.920741: 8,2 I R 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 U N [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:0 wl_type:2 ….............. | ||||||||||||||||||||||||||||||||||||||||
| Branch tracer | 1, Trace likely/unlikely profiler 設定路徑為Kernel hacking --->Tracers --->Branch Profiling --->Trace likely/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 設定路徑為Kernel hacking --->Tracers --->Branch Profiling --->Profile all 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 k.c: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 k.c: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主要用來跟踪slab allocator的分配情況。包括kfree，kmem_cache_alloc 等API 的調用情況，用戶程序可以根據tracer 收集到的信息分析內部碎片情況，找出內存分配最頻繁的代碼片斷，等等 設定路徑為Kernel hacking --->Tracers --->Trace SLAB allocations 操作範例如下所示
# echo 0 > tracing_enabled # echo kmemtrace > current_tracer # echo 1 > tracing_enabled # echo 0 > tracing_enabled ….etc | ||||||||||||||||||||||||||||||||||||||||
| Workqueue statistical tracer | 這是一個statistic tracer，主要用來統計系統所有workqueue現況,可以知道有多少work被插入到queue中,以及有多少被執行,與work的名稱, 可用以提供開發端對於workqueue機制實現的參考. 設定路徑為Kernel hacking --->Tracers --->Trace workqueues,系統啟動後,可以到/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 如下所示 correct incorrect % 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,branche all 可用以顯示所有 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 us 2635264000 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 us 306802216 us core_sys_select 87 25012000 us 287494.2 us 155578451 us do_select 87 24875000 us 285919.5 us 323446561 us smp_apic_timer_interrupt 15677 16056000 us 1024.175 us 76796.05 us do_timer 15677 15677000 us 1000.000 us 0.000 us tick_periodic 15677 15677000 us 1000.000 us 0.000 us 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 3 379054126 us sys_nanosleep 15 13957000 us 930466.6 us 1834329984 us hrtimer_nanosleep 15 13945000 us 929666.6 us 1719729983 us do_nanosleep 15 13944000 us 929600.0 us 1710319131 us sys_read 167 13503000 us 80856.28 us 1298120022 us vfs_read 172 13490000 us 78430.23 us 2981769264 us tty_read 61 13297000 us 217983.6 us 2678381427 us n_tty_read 61 13256000 us 217311.4 us 2834883001 us schedule_timeout 20 12966000 us 648300.0 us 2458710875 us | ||||||||||||||||||||||||||||||||||||||||
| Max Stack Tracer | 可用以顯示核心函式呼叫最深的Stack大小與在該情況下的Call Stack路徑.
設定路徑為Kernel hacking --->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) 2016 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 主要會列出目前最深的Stack Size,與根據該Stack Size發生的情況下,完整的Call Stack流程與每個函式所佔的空間(會包括區域變數與Function Parameters所佔的Stack空間).讓開發者,可以根據這流程去檢討函式與呼叫流程設計的合理性. | ||||||||||||||||||||||||||||||||||||||||
| Event tracing | Event幾乎是整個Ftrace中,各種資訊的集合,瀏覽/debug/tracing/events目錄中的檔案名稱如下所示 drwxr-xr-x 4 root root 0 XXX 20 23:55 bkl drwxr-xr-x 20 root root 0 XXX 20 23:55 block -rw-r--r-- 1 root root 0 XXX 20 23:55 enable drwxr-xr-x 14 root root 0 XXX 20 23:55 ftrace -r--r--r-- 1 root root 0 XXX 20 23:55 header_event -r--r--r-- 1 root root 0 XXX 20 23:55 header_page drwxr-xr-x 7 root root 0 XXX 20 23:55 irq drwxr-xr-x 14 root root 0 XXX 20 23:55 kmem drwxr-xr-x 3 root root 0 XXX 20 23:55 mce drwxr-xr-x 7 root root 0 XXX 20 23:55 module drwxr-xr-x 3 root root 0 XXX 20 23:55 napi drwxr-xr-x 6 root root 0 XXX 20 23:55 net drwxr-xr-x 12 root root 0 XXX 20 23:55 power drwxr-xr-x 4 root root 0 XXX 20 23:55 raw_syscalls drwxr-xr-x 18 root root 0 XXX 20 23:55 sched drwxr-xr-x 7 root root 0 XXX 20 23:55 scsi drwxr-xr-x 6 root root 0 XXX 20 23:55 signal drwxr-xr-x 5 root root 0 XXX 20 23:55 skb drwxr-xr-x 634 root root 0 XXX 20 23:55 syscalls drwxr-xr-x 14 root root 0 XXX 20 23:55 timer drwxr-xr-x 15 root root 0 XXX 20 23:55 vmscan drwxr-xr-x 6 root root 0 XXX 20 23:55 workqueue drwxr-xr-x 23 root root 0 XXX 20 23:55 writeback 除了 enable,header_event與header_page這三個控制檔案外,其他每個目錄都包含一種類別的Event參數,以目前筆者所使用的環境,Event包含了以下的類別
| ||||||||||||||||||||||||||||||||||||||||
結尾,
在平台移植與開發上,效能調教對於產品化的影響很深,本文主要介紹Ftrace的概念與操作範例,對筆者而言,這套工具可以幫助在複雜行為下,去分析系統效能的瓶頸,例如,是否有中斷關閉過長的行為,或是修改過的核心函式,不適當的行為佔據過多的處理器時間. 目前,在Linux平台上,能使用的工具不少(或是也可以使用商業的ICE產品),對這些工具內部運作原理掌握的程度越高,我們就會有足夠的知識背景幫助團隊在問題發生時,借重適當的工具去分析問題的原因,Ftrace只是提供系統問題一部分的資訊,其它可用的工具與分析問題的知識背景,會是有志於在這產業的開發者,需要持續努力的.
扫一扫
520
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
