Android筆記-LinuxKernel Ftrace (Function Trace)解析
hlchou@mail2000.com.tw
byloda
Android/Linux Source Code Tags
App BizOrz
BizOrz.COM
BizOrz Blog
在軟體開發時,通常都會面臨到系統效能調教的需求,我們希望知道哪些區塊的程式碼或函式被執行的次數頻繁,或是佔據較高的處理器時間,以便藉此優化程式碼撰寫的行為,或是改善耗CPU時間的算法,以Linux平台來說,OProfile(http://oprofile.sourceforge.net)會是一個大家常推薦的工具,OProfile支持Time-based透過系統Timer中斷蒐集當下執行環境資訊,並加以統計,或基於Event-based,以ARM來說就是PerformanceMonitor Unit(CP15)硬體支援的Performance控制單元(更多資訊可以參考:http://infocenter.arm.com/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會沒有效果),執行結果一致,透過反組譯程式碼結果如下
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 je80483a9<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 je80483f2<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 jne80483b3<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文件,我們也可以搭配條件判斷的寫法
可以參考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與沒加上的差異如下
函式名稱 |
無-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@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.
% 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).
Callgraph
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呼叫了FuncA9999 (佔總數9999/10000),main呼叫了FuncA1次(佔總數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次
Indexby function name
[1]FuncA [3] FuncB
Infrastructurefor profiling code inserted by 'gcc -pg'.
http://www.network-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網址http://www.codesourcery.com/sgpp/lite/arm/portal/subscription3053下載arm-2007q3版本的編譯器與函式庫環境,以此為基礎進行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編譯器,對編譯結果的影響.
沒有打開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 |
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
接下來,筆者以這目錄下的檔案,挑選認為應該說明的部份,如下所示
檔案名稱 |
說明 |
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:Rkworker/0:1 kworker/0:1-9538 [000] 52138.209903: 9538:120:S ==> [000] 9558:120:Rin.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:Rkworker/0:1 bash-9560 [000] 52138.211820: 9560:120:R ==> [000] 9538:120:Rkworker/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:Rin.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:Rkworker/0:1 <idle>-0 [000] 52138.414976: 0:120:R ==> [000] 9538:120:Rkworker/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:Rkworker/0:1 <idle>-0 [000] 52138.417312: 0:120:R ==> [000] 9538:120:Rkworker/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:Rpcscd pcscd-1811 [000] 52138.450170: 1811:120:S ==> [000] 0:120:R <idle> <idle>-0 [000] 52138.540657: 0:120:R + [000] 1892:139:Rgam_server
|
available_tracers |
列出目前LinuxKernel中在編譯時有被啟用的Tracer.我們只要把這些對應的名字設定到current_tracer中就可以啟用對應的Tracer.如下所示為筆者環境中所支持的Tracer.
# cat available_tracers blk kmemtrace branchwakeup_rt wakeup irqsoff function sched_switch initcall nop
|
tracing_enabled |
用以控制Tracer的啟動或是停止,當為1時表示Tracer啟動,反之,為0就是停止,如下所示
啟動 Tracer #echo1 > /data/debug/tracing/tracing_enabled
暫停 Tracer #echo0 > /data/debug/tracing/tracing_enabled |
trace |
用以把Tracer的結果呈現出人可閱讀的格式. #more/data/debug/tracing/trace
清空Tracer結果內容 #echo >/data/debug/tracing/trace |
trace_pipe |
支援以pipe的機制讀取跟trace檔案一樣的內容,並以Block的機制讀取,直到有資料進來後才會返回,每次資料讀取後,下一次讀取,就會讀取到新的資料,適合用來循序讀取,把Trace內容依序讀出來.
如果希望每次都讀取到完整的tracebuffer內容,就從trace檔案中讀取,反之,如果是每次都要讀到沒讀取到的資料,就可以從trace_pipe中讀取. |
trace_options |
可以用來控制trace要顯示的資料內容.(ㄟ 也必須要該Plug-inTracer有支援對應的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
重新 cattrace_options就會看到print-parent變成noprint-parent 反之,原本設定為nosym-addr,透過 #echosym-addr > /data/debug/tracing/trace_options
重新 cattrace_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 ….dosomehting....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 |
用來設定每個處理器要用多少記憶體空間當做TracerBuffer (單位為kbytes)(一般而言一個Page單位為4kbytes)(每個處理器都會依據此值配置一樣大的空間), 例如: #cat buffer_size_kb 1408 就表示在筆者環境中為每個處理器用1.408MB當做TracerBuffer. 這個值只有在current_tracer內容為“nop”時才可以修改.(也就是說要沒有啟用任何TracerPlug-in才可以修改這個值)
|
tracing_cpumask |
用來設定Tracer要在哪個處理器上蒐集資訊.顯示的為字串16進位的字串.在筆者單核ARM的環境中執行如下 #cat tracing_cpumask 1 # |
set_ftrace_filter |
用在動態Ftrace的組態下,程式碼在編譯過程中被gcc-pg置入呼叫mcount函式的行為,在支援動態Ftrace(Dynamic Ftrace)的環境中,只有在透過這檔案設定的函式,才會被納入FunctionTrace中.
設定TraceFuncton開頭為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 ….
在筆者的LinuxKernel 2.6.31 ARM的設置中,目前並沒有支援HAVE_DYNAMIC_FTRACE,也就是說在ARM版本中這個檔案屬性會無法使用.(還請以各位手中的LinuxKernel版本為主,看是否有新的更新.) |
set_ftrace_notrace |
跟set_ftrace_filter相反,在動態Ftrace(DynamicFtrace)的組態下,那設定到這檔案中的函式名稱,都會被取消呼叫mcount的動作,不納入FunctionTrace的機制中.如果同一個函式同時被設定到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 ….
在筆者的LinuxKernel 2.6.31 ARM的設置中,目前並沒有支援HAVE_DYNAMIC_FTRACE,也就是說在ARM版本中這個檔案屬性會無法使用.(還請以各位手中的LinuxKernel版本為主,看是否有新的更新.)
|
set_ftrace_pid |
設定Functiontracer只針對特定的PID進行蒐集.(如果不設定這個值,而是對全系統蒐集,很有可能會讓系統Hang住=>在我的ARM環境中不設定PID縮小範圍,就會Hang住...@_@)
操作範例如下, #cat/debug/tracing/set_ftrace_pid no pid #ps =>找一個要Trace的ProcessID 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 ….dosomething.... #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-inFramework的機制,隨著核心模組的演進,如果需要針對新的核心模組進行效能上的統計分析時,就可以透過Plug-in的方式,撰寫新的Ftrace模組達成新的tracer目的,作為一個可延展性的Tracer架構,本段落會介紹Ftrace主要支援的Tracer模組,這些模組的數量或是功能,都有可能隨著LinuxKernel演進而有所改動(例如:Kernel2.6.39移除KernelLock),版本的更迭,都請以最新的LinuxKernel Source Code為主要依據.
名稱 |
說明 |
||||||||||||||||||||||||||||||||||||||||
|
Function tracer
|
設定路徑為Kernelhacking --->Tracers --->Kernel Function Tracer 用以顯示,Function呼叫的流程與順序
操作範例如下所示: #echo 1855 >/debug/tracing/set_ftrace_pid =>選擇vsftpd的PID(=1855) #echo function >/debug/tracing/current_tracer =>選擇FunctionTracer #echo 1 >/debug/tracing/tracing_enabled =>之後透過另一台電腦經由FTP連線到這主機來,就可以記錄到這DaemonFunction操作的行為 #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需求的行程運作時,LinuxKernel這所對應調用的函式行為與時間值.
|
||||||||||||||||||||||||||||||||||||||||
|
Dynamicselection of functions
設定路徑為Kernelhacking --->Tracers --->enable/disable ftrace tracepointsdynamically
由於對全部FunctionTracing的成本很高,以筆者所用的ARM環境而言,幾乎會導致系統無法正常的反應(mmm,如果你是用ARMCortex A系列的處理器,應該就會很順了...),Ftrace也提供了動態選擇Function(Dynamicselection of functions) 進行Tracing的機制,以筆者所驗證的LinuxKernel 2.6.31而言,目前在ARM平台尚未支援這機制,而X86平台則可以支援.
使用範例如下的寫法,選擇只追蹤函式名稱包含有spin與process字串的LinuxKernel 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字串的函式呼叫過濾掉. |
|||||||||||||||||||||||||||||||||||||||||
|
Functiongraph tracer
設定路徑為Kernelhacking --->Tracers --->Kernel Function Tracer --->KernelFunction Graph Tracer
以筆者所驗證的LinuxKernel 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
設定路徑為Kernelhacking --->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:0HP: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 : 該任務所運作的CPUID 2,irqs-off : 'd'=關閉中斷,'.'=中斷沒關閉,'X'=該平台不支援讀取IRQFlag 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
設定路徑為Kernelhacking --->Tracers --->Scheduling Latency Tracer
可用以顯示Real-TimeTask取得執行權所需等待的時間,操作範例如下所示
# 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:0HP: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:Rkworker/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-SwitchSchedule tracer |
設定路徑為Kernelhacking --->Tracers --->Scheduling Latency Tracer
用以解析TaskContext-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:RAlarmManager AlarmManager-87 [000] 1044.598749: 87:120:R + [000] 69:118:SActivityManager AlarmManager-87 [000] 1044.599057: 87:120:R ==> [000] 69:118:RActivityManager ActivityManager-69 [000] 1044.599411: 69:118:S ==> [000] 87:120:RAlarmManager AlarmManager-87 [000] 1044.599643: 87:120:R + [000] 69:118:SActivityManager AlarmManager-87 [000] 1044.599957: 87:120:R ==> [000] 69:118:RActivityManager ActivityManager-69 [000] 1044.600498: 69:118:S ==> [000] 87:120:RAlarmManager AlarmManager-87 [000] 1044.600929: 87:120:R + [000] 69:118:SActivityManager AlarmManager-87 [000] 1044.601509: 87:120:R ==> [000] 69:118:RActivityManager ActivityManager-69 [000] 1044.602102: 69:118:R + [000] 72:120:SProcessStats ActivityManager-69 [000] 1044.604484: 69:118:R + [000] 67:118:Ser.ServerThread ActivityManager-69 [000] 1044.604661: 69:118:R ==> [000] 67:118:Rer.ServerThread er.ServerThread-67 [000] 1044.605145: 67:118:S ==> [000] 72:120:RProcessStats ProcessStats-72 [000] 1044.611966: 72:120:R ==> [000] 69:118:RActivityManager
如上所示,所列出的數據分別包含TaskID/Name,運作的處理器ID(供多核心的環境分析),每次觸發的時間值,如下以上述例子做一些說明 AlarmManager-87 [000] 1044.600929: 87:120:R + [000] 69:118:SActivityManager =>PID87,執行優先級120,Task狀態為Running,運作在處理器0的AlarmManager,會喚醒PID69,執行優先級118,Task狀態為Sleep運作在處理器0的ActivityManager AlarmManager-87 [000] 1044.601509: 87:120:R ==> [000] 69:118:RActivityManager =>PID87,執行優先級120,Task狀態為Running,運作在處理器0的AlarmManager,會把執行權切換(Context-Switch)到PID69,執行優先級118,Task狀態為Running運作在處理器0的ActivityManager ActivityManager-69 [000] 1044.602102: 69:118:R + [000] 72:120:SProcessStats =>PID69,執行優先級118,Task狀態為Running,運作在處理器0的ActivityManager,會喚醒PID72,執行優先級120,Task狀態為Sleep運作在處理器0的ProcessStats ActivityManager-69 [000] 1044.604484: 69:118:R + [000] 67:118:Ser.ServerThread =>PID69,執行優先級118,Task狀態為Running,運作在處理器0的ActivityManager,會喚醒PID67,執行優先級118,Task狀態為Sleep運作在處理器0的er.ServerThread ActivityManager-69 [000] 1044.604661: 69:118:R ==> [000] 67:118:Rer.ServerThread =>PID69,執行優先級118,Task狀態為Running,運作在處理器0的ActivityManager,會把執行權切換(Context-Switch)到PID67,執行優先級118,Task狀態為Running運作在處理器0的er.ServerThread
有關TaskPriority參考如下表 (技術部分也可以參考筆者這篇文章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 |
設定路徑為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 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:0wl_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: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 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主要用來跟踪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) 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
主要會列出目前最深的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只是提供系統問題一部分的資訊,其它可用的工具與分析問題的知識背景,會是有志於在這產業的開發者,需要持續努力的.