Android筆記-Linux Kernel Ftrace (Function Trace)解析

Posted by Lawpig on 6月 01, 2017 | No comments

Android筆記-Linux Kernel Ftrace (Function Trace)解析

Android筆記-Linux Kernel Ftrace (Function Trace)解析
hlchou@mail2000.com.tw
by loda
在軟體開發時,通常都會面臨到系統效能調教的需求,我們希望知道哪些區塊的程式碼或函式被執行的次數頻繁,或是佔據較高的處理器時間,以便藉此優化程式碼撰寫的行為,或是改善耗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”,就會把 likelyunlikely巨集定義如下所示
/*
* 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的動作,likelyunlikely就只會透過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的執行區塊,放到前面連續的程式碼中,至於執行時期會執行到ifelse的區塊,就根據X條件是否為0來決定.參考GCC文件,我們也可以搭配條件判斷的寫法
可以參考Linux Kernelinclude/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編譯為機械碼時程式碼排列的順序,減少處理器PipelineFlush的機率,這對執行效能也是有很大的幫助.
GCC support for the GNU profiler gprof
有關GNU gprof的介紹可以參考網頁http://www.cs.utah.edu/dept/old/texinfo/as/gprof.html .基於GCCProfiling的支援,開發端可以透過 -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
mainlea 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
FuncApush %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
FuncBpush %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.
% timecumulative (seconds)self (seconds)callsSelf (ms/call)Total (ms/call)name
100.540.470.47100000.050.05FuncA
00.47010472.49FuncB
=>簡要說明每次呼叫FuncA需要0.05ms,總共呼叫了10000,耗時0.47秒 (ㄟ 也許應該說每次呼叫FuncA需要0.047ms會比較精確一點),FnucB被呼叫1,耗時472.49ms (funcB中會執行9999FuncA).
Call graph
granularity: each sample hit covers 2 byte(s) for 2.12% of 0.47 seconds
index% timeselfchildrencalledname
001/10000main [2]
0.4709999/10000FuncB [3]
[1]1000.47010000FuncA [1]
=>簡要說明FuncA為主體來對比,FuncA執行了10000次共0.47秒的時間,FuncB呼叫了FuncA 9999 (佔總數9999/10000), main呼叫了FuncA 1次 (佔總數1/10000)
index% timeselfchildrencalledname
[2]10000.47main [2]
00.471FuncB [3]
001/10000FuncA [1]
=>簡要說明main為主體來對比,main呼叫的函式(children)花了 0.47,分別呼叫了FuncB 佔了9999/10000(約等於1)的時間,與呼叫了FuncA佔了1/10000的時間.
index% timeselfchildrencalledname
00.471main [2]
[3]10000.471FuncB [3]
0.4709999/10000FuncA [1]
=>簡要說明funcB為主體來對比,main呼叫的函式FuncA funcB(children)花了0.47,FuncB呼叫的函式FuncA花了0.47秒 (因為最小單位為0.01,太接近的兩個數字如果差距是在0.01秒以內,數字就有機會變成一樣),FuncB被呼叫1,FuncAFuncB呼叫9999
Index by function name
[1] FuncA [3] FuncB
Infrastructure for profiling code inserted by ‘gcc -pg’.
Linux KernelEnable 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_filterset_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編譯器,對編譯結果的影響.
沒有打開Ftracerdo_fork函式打開Ftracerdo_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開頭為 accountrun的函式呼叫行為,如下指令所示
#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_notraceset_ftrace_filter相反,在動態Ftrace(Dynamic Ftrace)的組態下,那設定到這檔案中的函式名稱,都會被取消呼叫mcount的動作,不納入Function Trace的機制中如果同一個函式同時被設定到 set_ftrace_filter 與 set_ftrace_notrace,則該函式將會以 set_ftrace_notrace為主,將不納入Trace.
設定不要Trace有包含cpualign字元的函式名稱,如下指令所示
# 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 =>找一個要TraceProcess 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中就只會顯示該 PIDtracing結果
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平台則可以支援.
使用範例如下的寫法,選擇只追蹤函式名稱包含有 spinprocess字串的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
..
就只會看到有包含 spinprocess字串的函式呼叫,
接下來,如果要把有包含 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
..
可以看到最後的結果,就是會包含有 spinprocess字串的函式呼叫,並且把其中有包括 rawtimes字串的函式呼叫過濾掉.
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 Tracing1, 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_disabledLevel
6,lock-depth:
接下來屬於 time的欄位,單位為 us,代表的是從呼叫的函式到被呼叫的函式所經過的時間,這段時間如果超過 preempt_mark_thresh (default 100)的值,時間後面就會標示 ‘!’,如果超過1us,就會標示 ‘+’,如果小於或等於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,運作在處理器0AlarmManager, 會喚醒 PID 69,執行優先級118,Task狀態為Sleep運作在處理器0ActivityManager
AlarmManager-87 [000] 1044.601509: 87:120:R ==> [000] 69:118:R ActivityManager
=>PID 87,執行優先級120,Task狀態為 Running,運作在處理器0AlarmManager, 會把執行權切換(Context-Switch)到 PID 69,執行優先級118,Task狀態為Running運作在處理器0ActivityManager
ActivityManager-69 [000] 1044.602102: 69:118:R + [000] 72:120:S ProcessStats
=>PID 69,執行優先級118,Task狀態為 Running,運作在處理器0ActivityManager, 會喚醒 PID 72,執行優先級120,Task狀態為Sleep運作在處理器0ProcessStats
ActivityManager-69 [000] 1044.604484: 69:118:R + [000] 67:118:S er.ServerThread
=>PID 69,執行優先級118,Task狀態為 Running,運作在處理器0ActivityManager, 會喚醒 PID 67,執行優先級118,Task狀態為Sleep運作在處理器0er.ServerThread
ActivityManager-69 [000] 1044.604661: 69:118:R ==> [000] 67:118:R er.ServerThread
=>PID 69,執行優先級118,Task狀態為 Running,運作在處理器0ActivityManager , 會把執行權切換(Context-Switch)到 PID 67,執行優先級118,Task狀態為Running運作在處理器0er.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/”)
Kernel task priority說明
0 to 99Real-Time priority 99 to 0
100 to 139對應到Task Nice Value -20 to 19
140idle task priority
有關Task 狀態 參考如下表
狀態符號說明
R (Running)Wants to run, may not
S (Sleep)ctually be runningProcess is waiting to be woken up (handles signals)
D (Disk sleep)(uninterruptible sleep) Process must be woken up (ignores signals)
T (Stopped)Process suspended
t (Traced)Process is being traced (with something like gdb)
Z (Zombie)Process waiting to be cleaned up
X (Unknown)
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 tracer1, Trace likely/unlikely profiler
設定路徑為Kernel hacking —>Tracers —>Branch Profiling —>Trace likely/unlikely profiler
用以顯示Kernel基於likely/unlikelyRun-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的位址,減少處理器PipelineFlush的機會,從而也可以讓系統的運作效率更佳.
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的分配情況。包括kfreekmem_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
Profiling1,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 tracingEvent幾乎是整個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_eventheader_page這三個控制檔案外,其他每個目錄都包含一種類別的Event參數,以目前筆者所使用的環境,Event包含了以下的類別
名稱
說明
bklBKLLinux Kernel 2.2,為了提供一個暫時簡易的支援SMP機制,除了讓多核心的架構可以支援多個Tasks同時運作外,還需要支援一個Global Spin-Lock機制,確保同一時間只有一個Task在一個需要保護的子系統中運作,因此,就有了BKL機制的誕生,然而,BKL機制本身仍有諸多缺陷 (詳情,後續會再抽空用其他文章描述多核心的Kernel運作),也因此,新版的Linux Kernel會逐步的移除BKL機制,讓核心可以採用更適當的多核心設計機制.
參考Kernel Lock實作/lib/kernel_lock.c,BKL全名為 Big Kernel Lock,主要是提供各別子系統,確保同一時間只有一個Task可以在該子系統中運作(例如,Kernel 2.6.31reiserfs檔案系統實作中,針對SMP(Symmetric Multi-Processors)處理器組態,就用到BKL確保同一時間只有一個Task可以對reiserfs進行操作),目前BKL並不建議在新設計的程式碼中使用,在最新的Linux Kernel 2.6.39,BKL機制也已經移除.
檢視 events/bkl目錄下,共支援以下的Events
lock_kernel unlock_kernel
#echo 1 > /debug/tracing/events/bkl/enable
檢視 /debug/tracing/trace下的結果,
block會把blk-core (in block/blk-core.c)中相關處理的動作,記錄下來,供開發者觀察相關行程對Block裝置的行為,
檢視 events/block目錄下,共支援以下的Events
block_bio_backmerge block_bio_remap block_rq_insert block_split block_bio_bounce block_getrq block_rq_issue block_unplug_io block_bio_complete block_plug block_rq_remap block_unplug_timer block_bio_frontmerge block_rq_abort block_rq_requeue block_bio_queue block_rq_complete block_sleeprq
#echo 1 > /debug/tracing/events/block/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
kjournald-48 [000] 5699.102000: block_bio_queue: 253,0 WS 217891064 + 8 [kjournald]
kjournald-48 [000] 5699.102000: block_bio_remap: 8,2 WS 217891448 + 8 <- (253,0) 217891064
kjournald-48 [000] 5699.102000: block_bio_remap: 8,0 WS 218100293 + 8 <- (8,2) 217891448
kjournald-48 [000] 5699.102000: block_bio_queue: 8,0 WS 218100293 + 8 [kjournald]
kjournald-48 [000] 5699.102000: block_getrq: 8,0 WS 218100293 + 8 [kjournald]
kjournald-48 [000] 5699.102000: block_plug: [kjournald]
kjournald-48 [000] 5699.102000: block_rq_insert: 8,0 WS 0 () 218100293 + 8 [kjournald]
kjournald-48 [000] 5699.102000: block_rq_issue: 8,0 WS 0 () 218100293 + 8 [kjournald]
<…>-13394 [000] 5699.114000: block_rq_complete: 8,0 WS () 218100293 + 8 [0]
<…>-13394 [000] 5699.114000: block_bio_complete: 253,0 WS 217891064 + 8 [0]
kjournald-48 [000] 5699.126000: block_bio_queue: 253,0 WS 61864 + 8 [kjournald]
kjournald-48 [000] 5699.126000: block_bio_remap: 8,2 WS 62248 + 8 <- (253,0) 61864
kjournald-48 [000] 5699.126000: block_bio_remap: 8,0 WS 271093 + 8 <- (8,2) 62248
kjournald-48 [000] 5699.126000: block_bio_queue: 8,0 WS 271093 + 8 [kjournald]
kjournald-48 [000] 5699.126000: block_getrq: 8,0 WS 271093 + 8 [kjournald]
kjournald-48 [000] 5699.126000: block_plug: [kjournald]
kjournald-48 [000] 5699.126000: block_rq_insert: 8,0 WS 0 () 271093 + 8 [kjournald]
kjournald-48 [000] 5699.126000: block_rq_issue: 8,0 WS 0 () 271093 + 8 [kjournald]
kjournald-48 [000] 5699.127000: block_rq_complete: 8,0 WS () 271093 + 8 [0]
kjournald-48 [000] 5699.127000: block_bio_complete: 253,0 WS 61864 + 8 [0]
kjournald-48 [000] 5699.128000: block_bio_queue: 253,0 WS 61872 + 8 [kjournald]
kjournald-48 [000] 5699.128000: block_bio_remap: 8,2 WS 62256 + 8 <- (253,0) 61872
kjournald-48 [000] 5699.128000: block_bio_remap: 8,0 WS 271101 + 8 <- (8,2) 62256
kjournald-48 [000] 5699.128000: block_bio_queue: 8,0 WS 271101 + 8 [kjournald]
kjournald-48 [000] 5699.128000: block_getrq: 8,0 WS 271101 + 8 [kjournald]
kjournald-48 [000] 5699.128000: block_plug: [kjournald]
kjournald-48 [000] 5699.128000: block_rq_insert: 8,0 WS 0 () 271101 + 8 [kjournald]
kjournald-48 [000] 5699.128000: block_rq_issue: 8,0 WS 0 () 271101 + 8 [kjournald]
kjournald-48 [000] 5699.129000: block_rq_complete: 8,0 WS () 271101 + 8 [0]
kjournald-48 [000] 5699.129000: block_bio_complete: 253,0 WS 61872 + 8 [0]
kjournald-48 [000] 5699.129000: block_bio_queue: 253,0 WS 61880 + 8 [kjournald]
irq檢視 events/irq目錄下,共支援以下的Events
irq_handler_entry softirq_entry softirq_raise irq_handler_exit softirq_exit
#echo 1 > /debug/tracing/events/irq/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<idle>-0 [000] 5601.436000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.436000: softirq_raise: vec=9 [action=RCU]
<idle>-0 [000] 5601.436000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.436000: softirq_exit: vec=1 [action=TIMER]
<idle>-0 [000] 5601.436000: softirq_entry: vec=9 [action=RCU]
<idle>-0 [000] 5601.436000: softirq_exit: vec=9 [action=RCU]
<idle>-0 [000] 5601.437000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.437000: softirq_raise: vec=9 [action=RCU]
<idle>-0 [000] 5601.437000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.437000: softirq_exit: vec=1 [action=TIMER]
<idle>-0 [000] 5601.437000: softirq_entry: vec=9 [action=RCU]
<idle>-0 [000] 5601.437000: softirq_exit: vec=9 [action=RCU]
<idle>-0 [000] 5601.438000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.438000: softirq_raise: vec=9 [action=RCU]
<idle>-0 [000] 5601.438000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.438000: softirq_exit: vec=1 [action=TIMER]
<idle>-0 [000] 5601.438000: softirq_entry: vec=9 [action=RCU]
<idle>-0 [000] 5601.438000: softirq_exit: vec=9 [action=RCU]
<idle>-0 [000] 5601.439000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.439000: softirq_raise: vec=9 [action=RCU]
<idle>-0 [000] 5601.439000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.439000: softirq_exit: vec=1 [action=TIMER]
<idle>-0 [000] 5601.439000: softirq_entry: vec=9 [action=RCU]
<idle>-0 [000] 5601.439000: softirq_exit: vec=9 [action=RCU]
<idle>-0 [000] 5601.440000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.440000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.440000: softirq_exit: vec=1 [action=TIMER]
<idle>-0 [000] 5601.441000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.441000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.441000: softirq_exit: vec=1 [action=TIMER]
<idle>-0 [000] 5601.442000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.442000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.442000: softirq_exit: vec=1 [action=TIMER]
<idle>-0 [000] 5601.443000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.443000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.443000: softirq_exit: vec=1 [action=TIMER]
<idle>-0 [000] 5601.444000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.444000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.444000: softirq_exit: vec=1 [action=TIMER]
<idle>-0 [000] 5601.445000: softirq_raise: vec=1 [action=TIMER]
<idle>-0 [000] 5601.445000: softirq_entry: vec=1 [action=TIMER]
<idle>-0 [000] 5601.445000: softirq_exit: vec=1 [action=TIMER]
kmem檢視 events/kmem目錄下,共支援以下的Events
kmalloc_node mm_page_alloc mm_page_pcpu_drain kmem_cache_alloc mm_page_alloc_extfrag mm_pagevec_free kfree kmem_cache_alloc_node mm_page_alloc_zone_locked kmalloc kmem_cache_free mm_page_free_direct
#echo 1 > /debug/tracing/events/kmem/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
cc1-12884 [000] 5513.761000: kmem_cache_alloc: call_site=c0527d6e ptr=f4ed5300 bytes_req=192 bytes_alloc=192 gfp_flags=GFP_KERNEL|GFP_ZERO
cc1-12884 [000] 5513.762000: kmem_cache_free: call_site=c047fb8b ptr=f59e7740
cc1-12884 [000] 5513.762000: kmem_cache_free: call_site=c0527d1b ptr=f4eb3680
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c050c13a ptr=f4f2217c bytes_req=88 bytes_alloc=88 gfp_flags=GFP_KERNEL|GFP_ZERO
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c050c13a ptr=f4f2222c bytes_req=88 bytes_alloc=88 gfp_flags=GFP_KERNEL|GFP_ZERO
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c050be6e ptr=f4f53b1c bytes_req=88 bytes_alloc=88 gfp_flags=GFP_KERNEL|GFP_ZERO
cc1-12884 [000] 5513.762000: mm_page_alloc: page=f7490cc0 pfn=316902 order=0 migratetype=0 gfp_flags=GFP_KERNEL|GFP_REPEAT|GFP_ZERO|0x2
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c0511475 ptr=f4f407d0 bytes_req=24 bytes_alloc=24 gfp_flags=GFP_KERNEL
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c05114c5 ptr=f4f58ac8 bytes_req=16 bytes_alloc=16 gfp_flags=GFP_KERNEL
cc1-12884 [000] 5513.762000: mm_page_alloc: page=f7214760 pfn=235451 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE
cc1-12884 [000] 5513.762000: kmalloc: call_site=c057c8e7 ptr=f4cc7800 bytes_req=192 bytes_alloc=192 gfp_flags=GFP_KERNEL
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c050c13a ptr=f4f79124 bytes_req=88 bytes_alloc=88 gfp_flags=GFP_KERNEL|GFP_ZERO
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c050af83 ptr=f4f221d4 bytes_req=88 bytes_alloc=88 gfp_flags=GFP_KERNEL
cc1-12884 [000] 5513.762000: kmem_cache_free: call_site=c050a063 ptr=f4f221d4
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c050c13a ptr=f4f221d4 bytes_req=88 bytes_alloc=88 gfp_flags=GFP_KERNEL|GFP_ZERO
cc1-12884 [000] 5513.762000: mm_page_alloc: page=f7490c80 pfn=316900 order=0 migratetype=0 gfp_flags=GFP_KERNEL|GFP_REPEAT|GFP_ZERO|0x2
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c0511475 ptr=f4edb368 bytes_req=24 bytes_alloc=24 gfp_flags=GFP_KERNEL
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c05114c5 ptr=f4f58438 bytes_req=16 bytes_alloc=16 gfp_flags=GFP_KERNEL
cc1-12884 [000] 5513.762000: mm_page_alloc: page=f7284d80 pfn=249836 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE
cc1-12884 [000] 5513.762000: kfree: call_site=c057cac7 ptr=f4cc7800
cc1-12884 [000] 5513.762000: kfree: call_site=c057be25 ptr=f4f517e0
cc1-12884 [000] 5513.762000: kfree: call_site=c057be2d ptr=f5af3280
cc1-12884 [000] 5513.762000: kmem_cache_alloc: call_site=c050baa3 ptr=f4f79f94 bytes_req=88 bytes_alloc=88 gfp_flags=GFP_KERNEL|GFP_ZERO
cc1-12884 [000] 5513.762000: mm_page_alloc: page=f727d7a0 pfn=248893 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE|GFP_ZERO
cc1-12884 [000] 5513.762000: kfree: call_site=c057b030 ptr=f4ee5f40
cc1-12884 [000] 5513.762000: kfree: call_site=c052ce9b ptr=f5af3480
cc1-12884 [000] 5513.762000: kmem_cache_free: call_site=c0536936 ptr=f4cdf000
cc1-12884 [000] 5513.762000: mm_page_alloc: page=f72571c0 pfn=243982 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE
cc1-12884 [000] 5513.763000: mm_page_alloc: page=f7490be0 pfn=316895 order=0 migratetype=0 gfp_flags=GFP_KERNEL|GFP_REPEAT|GFP_ZERO|0x2
cc1-12884 [000] 5513.763000: mm_page_alloc: page=f7274860 pfn=247747 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE
mce檢視 events/mce目錄下,共支援以下的Events
mce_record
module檢視 events/module目錄下,共支援以下的Events
module_free module_load module_request module_get module_put
#echo 1 > /debug/tracing/events/module/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
insmod-12522 [000] 5384.763000: module_load: cramfs
insmod-12522 [000] 5384.766000: module_put: cramfs call_site=sys_init_module refcnt=2
rmmod-12526 [000] 5396.917000: module_free: cramfs
napi檢視 events/napi目錄下,共支援以下的Events
napi_poll
#echo 1 > /debug/tracing/events/napi/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<…>-12085 [000] 5144.521000: napi_poll: napi poll on napi struct f5981460 for device eth0
<…>-12090 [000] 5144.695000: napi_poll: napi poll on napi struct f5981460 for device eth0
<…>-12090 [000] 5144.695000: napi_poll: napi poll on napi struct f5981460 for device eth0
make-12099 [000] 5144.895000: napi_poll: napi poll on napi struct f5981460 for device eth0
make-12099 [000] 5144.895000: napi_poll: napi poll on napi struct f5981460 for device eth0
cc1-12102 [000] 5144.969000: napi_poll: napi poll on napi struct f5981460 for device eth0
cc1-12102 [000] 5144.972000: napi_poll: napi poll on napi struct f5981460 for device eth0
as-12103 [000] 5145.005000: napi_poll: napi poll on napi struct f5981460 for device eth0
make-12111 [000] 5145.175000: napi_poll: napi poll on napi struct f5981460 for device eth0
date-12120 [000] 5145.363000: napi_poll: napi poll on napi struct f5981460 for device eth0
in.telnetd-1955 [000] 5145.366000: napi_poll: napi poll on napi struct f5981460 for device eth0
grep-12132 [000] 5145.566000: napi_poll: napi poll on napi struct f5981460 for device eth0
sh-12136 [000] 5145.631000: napi_poll: napi poll on napi struct f5981460 for device eth0
bash-1957 [000] 5145.634000: napi_poll: napi poll on napi struct f5981460 for device eth0
sh-12143 [000] 5145.834000: napi_poll: napi poll on napi struct f5981460 for device eth0
top-9088 [000] 5145.855000: napi_poll: napi poll on napi struct f5981460 for device eth0
sh-12143 [000] 5145.857000: napi_poll: napi poll on napi struct f5981460 for device eth0
make-12147 [000] 5145.915000: napi_poll: napi poll on napi struct f5981460 for device eth0
make-12147 [000] 5145.920000: napi_poll: napi poll on napi struct f5981460 for device eth0
cc1-12152 [000] 5146.053000: napi_poll: napi poll on napi struct f5981460 for device eth0
cc1-12152 [000] 5146.053000: napi_poll: napi poll on napi struct f5981460 for device eth0
as-12153 [000] 5146.113000: napi_poll: napi poll on napi struct f5981460 for device eth0
make-12161 [000] 5146.253000: napi_poll: napi poll on napi struct f5981460 for device eth0
sh-12162 [000] 5146.540000: napi_poll: napi poll on napi struct f5981460 for device eth0
rm-12168 [000] 5146.543000: napi_poll: napi poll on napi struct f5981460 for device eth0
make-12173 [000] 5146.720000: napi_poll: napi poll on napi struct f5981460 for device eth0
bash-1957 [000] 5146.724000: napi_poll: napi poll on napi struct f5981460 for device eth0
ld-12179 [000] 5146.901000: napi_poll: napi poll on napi struct f5981460 for device eth0
ld-12179 [000] 5146.903000: napi_poll: napi poll on napi struct f5981460 for device eth0
make-12185 [000] 5147.004000: napi_poll: napi poll on napi struct f5981460 for device eth0
net檢視 events/net目錄下,共支援以下的Events
net_dev_queue net_dev_xmit netif_receive_skb netif_rx
#echo 1 > /debug/tracing/events/net/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
in.telnetd-1955 [000] 4446.238000: net_dev_queue: dev=eth0 skbaddr=f5aa2470 len=56
in.telnetd-1955 [000] 4446.238000: net_dev_xmit: dev=eth0 skbaddr=f5aa2470 len=56 rc=0
<idle>-0 [000] 4446.436000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
<idle>-0 [000] 4446.436000: net_dev_queue: dev=eth0 skbaddr=f5aa2bf0 len=80
<idle>-0 [000] 4446.436000: net_dev_xmit: dev=eth0 skbaddr=f5aa2bf0 len=80 rc=0
<idle>-0 [000] 4446.593000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
in.telnetd-1955 [000] 4446.596000: net_dev_queue: dev=eth0 skbaddr=f5aa2bf0 len=66
in.telnetd-1955 [000] 4446.596000: net_dev_xmit: dev=eth0 skbaddr=f5aa2bf0 len=66 rc=0
in.telnetd-9058 [000] 4446.689000: net_dev_queue: dev=eth0 skbaddr=f5aa2470 len=136
in.telnetd-9058 [000] 4446.689000: net_dev_xmit: dev=eth0 skbaddr=f5aa2470 len=136 rc=0
<idle>-0 [000] 4446.782000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
in.telnetd-1955 [000] 4446.785000: net_dev_queue: dev=eth0 skbaddr=f5aa2bf0 len=95
in.telnetd-1955 [000] 4446.785000: net_dev_xmit: dev=eth0 skbaddr=f5aa2bf0 len=95 rc=0
<idle>-0 [000] 4446.888000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
<idle>-0 [000] 4446.888000: net_dev_queue: dev=eth0 skbaddr=f5aa2d70 len=953
<idle>-0 [000] 4446.888000: net_dev_xmit: dev=eth0 skbaddr=f5aa2d70 len=953 rc=0
<idle>-0 [000] 4446.983000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
<idle>-0 [000] 4447.087000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
<idle>-0 [000] 4447.550000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
in.telnetd-1955 [000] 4447.552000: net_dev_queue: dev=eth0 skbaddr=f5aa2d70 len=82
in.telnetd-1955 [000] 4447.552000: net_dev_xmit: dev=eth0 skbaddr=f5aa2d70 len=82 rc=0
<idle>-0 [000] 4447.752000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
<idle>-0 [000] 4447.974000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
in.telnetd-1955 [000] 4447.976000: net_dev_queue: dev=eth0 skbaddr=f5aa2d70 len=56
in.telnetd-1955 [000] 4447.976000: net_dev_xmit: dev=eth0 skbaddr=f5aa2d70 len=56 rc=0
<idle>-0 [000] 4448.175000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
<idle>-0 [000] 4448.175000: net_dev_queue: dev=eth0 skbaddr=f5aa2bf0 len=1138
<idle>-0 [000] 4448.175000: net_dev_xmit: dev=eth0 skbaddr=f5aa2bf0 len=1138 rc=0
<idle>-0 [000] 4448.373000: netif_receive_skb: dev=eth0 skbaddr=f4f6ad40 len=46
in.telnetd-9058 [000] 4448.701000: net_dev_queue: dev=eth0 skbaddr=f5aa2bf0 len=1004
in.telnetd-9058 [000] 4448.701000: net_dev_xmit: dev=eth0 skbaddr=f5aa2bf0 len=1004 rc=0
power檢視 events/power目錄下,共支援以下的Events
clock_disable cpu_frequency power_end clock_enable cpu_idle machine_suspend power_frequency clock_set_rate power_domain_target power_start
#echo 1 > /debug/tracing/events/power/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<idle>-0 [000] 4370.240000: power_start: type=1 state=1 cpu_id=0
<idle>-0 [000] 4370.240000: cpu_idle: state=1 cpu_id=0
<idle>-0 [000] 4370.241000: power_end: cpu_id=0
<idle>-0 [000] 4370.241000: cpu_idle: state=4294967295 cpu_id=0
<idle>-0 [000] 4370.241000: power_start: type=1 state=1 cpu_id=0
<idle>-0 [000] 4370.241000: cpu_idle: state=1 cpu_id=0
<idle>-0 [000] 4370.242000: power_end: cpu_id=0
<idle>-0 [000] 4370.242000: cpu_idle: state=4294967295 cpu_id=0
<idle>-0 [000] 4370.242000: power_start: type=1 state=1 cpu_id=0
<idle>-0 [000] 4370.242000: cpu_idle: state=1 cpu_id=0
<idle>-0 [000] 4370.243000: power_end: cpu_id=0
<idle>-0 [000] 4370.243000: cpu_idle: state=4294967295 cpu_id=0
<idle>-0 [000] 4370.243000: power_start: type=1 state=1 cpu_id=0
<idle>-0 [000] 4370.243000: cpu_idle: state=1 cpu_id=0
<idle>-0 [000] 4370.244000: power_end: cpu_id=0
<idle>-0 [000] 4370.244000: cpu_idle: state=4294967295 cpu_id=0
<idle>-0 [000] 4370.244000: power_start: type=1 state=1 cpu_id=0
<idle>-0 [000] 4370.244000: cpu_idle: state=1 cpu_id=0
<idle>-0 [000] 4370.245000: power_end: cpu_id=0
<idle>-0 [000] 4370.245000: cpu_idle: state=4294967295 cpu_id=0
<idle>-0 [000] 4370.245000: power_start: type=1 state=1 cpu_id=0
<idle>-0 [000] 4370.245000: cpu_idle: state=1 cpu_id=0
<idle>-0 [000] 4370.246000: power_end: cpu_id=0
<idle>-0 [000] 4370.246000: cpu_idle: state=4294967295 cpu_id=0
<idle>-0 [000] 4370.246000: power_start: type=1 state=1 cpu_id=0
<idle>-0 [000] 4370.246000: cpu_idle: state=1 cpu_id=0
<idle>-0 [000] 4370.247000: power_end: cpu_id=0
<idle>-0 [000] 4370.247000: cpu_idle: state=4294967295 cpu_id=0
<idle>-0 [000] 4370.247000: power_start: type=1 state=1 cpu_id=0
<idle>-0 [000] 4370.247000: cpu_idle: state=1 cpu_id=0
raw_syscalls檢視 events/raw_syscalls目錄下,共支援以下的Events
sys_enter sys_exit
#echo 1 > /debug/tracing/events/raw_syscalls/enable
檢視 /debug/tracing/trace下的結果,
bash-3798 [000] 9209.897945: sys_enter: NR 63 (a, 1, a, 0, a, bff53448)
bash-3798 [000] 9209.897966: sys_exit: NR 63 = 1
bash-3798 [000] 9209.897970: sys_enter: NR 221 (a, 1, 0, 0, b77cfff4, bff53328)
bash-3798 [000] 9209.897972: sys_exit: NR 221 = 1
bash-3798 [000] 9209.897975: sys_enter: NR 6 (a, 1, 0, 0, 0, bff53448)
bash-3798 [000] 9209.897976: sys_exit: NR 6 = 0
bash-3798 [000] 9209.897988: sys_enter: NR 175 (0, 0, 80fe4dc, 8,b77cfff4, bff535bc)
bash-3798 [000] 9209.897991: sys_exit: NR 175 = 0
bash-3798 [000] 9209.897994: sys_enter: NR 174 (2, bff53400, bff53374, 8, b77cfff4, bff53498)
bash-3798 [000] 9209.897996: sys_exit: NR 174 = 0
sched檢視 events/sched目錄下,共支援以下的Events
sched_process_exit sched_stat_sleep sched_process_fork sched_stat_wait sched_kthread_stop sched_process_free sched_switch sched_kthread_stop_ret sched_process_wait sched_wait_task sched_migrate_task sched_stat_iowait sched_wakeup sched_pi_setprio sched_stat_runtime sched_wakeup_new
#echo 1 > /debug/tracing/events/sched/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
bash-1957 [000] 4232.264000: sched_stat_wait: comm=kworker/0:0 pid=4 delay=0 [ns]
bash-1957 [000] 4232.264000: sched_switch: prev_comm=bash prev_pid=1957 prev_prio=120 prev_state=R ==> next_comm=kworker/0:0 next_pid=4 next_prio=120
kworker/0:0-4 [000] 4232.265000: sched_stat_runtime: comm=kworker/0:0 pid=4 runtime=956546 [ns] vruntime=1353114806115 [ns]
kworker/0:0-4 [000] 4232.265000: sched_stat_sleep: comm=in.telnetd pid=1955 delay=3893232 [ns]
kworker/0:0-4 [000] 4232.265000: sched_wakeup: comm=in.telnetd pid=1955 prio=120 success=1 target_cpu=000
kworker/0:0-4 [000] 4232.265000: sched_stat_wait: comm=in.telnetd pid=1955 delay=0 [ns]
kworker/0:0-4 [000] 4232.265000: sched_switch: prev_comm=kworker/0:0 prev_pid=4 prev_prio=120 prev_state=S ==> next_comm=in.telnetd next_pid=1955 next_prio=120
in.telnetd-1955 [000] 4232.265000: sched_stat_wait: comm=bash pid=1957 delay=956546 [ns]
in.telnetd-1955 [000] 4232.265000: sched_switch: prev_comm=in.telnetd prev_pid=1955 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1957 next_prio=120
bash-1957 [000] 4232.266000: sched_stat_runtime: comm=bash pid=1957 runtime=1329219 [ns] vruntime=1353118178788 [ns]
bash-1957 [000] 4232.267000: sched_stat_runtime: comm=bash pid=1957 runtime=672432 [ns] vruntime=1353118851220 [ns]
bash-1957 [000] 4232.267000: sched_wakeup: comm=bash pid=1957 prio=120 success=0 target_cpu=000
bash-1957 [000] 4232.267000: sched_switch: prev_comm=bash prev_pid=1957 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120
<idle>-0 [000] 4232.268000: sched_stat_sleep: comm=kworker/0:0 pid=4 delay=3016584 [ns]
<idle>-0 [000] 4232.268000: sched_wakeup: comm=kworker/0:0 pid=4 prio=120 success=1 target_cpu=000
<idle>-0 [000] 4232.268000: sched_stat_wait: comm=kworker/0:0 pid=4 delay=0 [ns]
<idle>-0 [000] 4232.268000: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:0 next_pid=4 next_prio=120
kworker/0:0-4 [000] 4232.268000: sched_stat_sleep: comm=in.telnetd pid=1955 delay=3016584 [ns]
kworker/0:0-4 [000] 4232.268000: sched_wakeup: comm=in.telnetd pid=1955 prio=120 success=1 target_cpu=000
kworker/0:0-4 [000] 4232.268000: sched_stat_wait: comm=in.telnetd pid=1955 delay=0 [ns]
kworker/0:0-4 [000] 4232.268000: sched_switch: prev_comm=kworker/0:0 prev_pid=4 prev_prio=120 prev_state=S ==> next_comm=in.telnetd next_pid=1955 next_prio=120
in.telnetd-1955 [000] 4232.268000: sched_switch: prev_comm=in.telnetd prev_pid=1955 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120
<idle>-0 [000] 4232.533000: sched_stat_sleep: comm=top pid=9088 delay=2003729805 [ns]
<idle>-0 [000] 4232.533000: sched_wakeup: comm=top pid=9088 prio=120 success=1 target_cpu=000
<idle>-0 [000] 4232.533000: sched_stat_wait: comm=top pid=9088 delay=292215 [ns]
<idle>-0 [000] 4232.533000: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=top next_pid=9088 next_prio=120
<…>-9088 [000] 4232.533000: sched_stat_sleep: comm=in.telnetd pid=9058 delay=2005198147 [ns]
<…>-9088 [000] 4232.533000: sched_wakeup: comm=in.telnetd pid=9058 prio=120 success=1 target_cpu=000
<…>-9088 [000] 4232.534000: sched_stat_runtime: comm=top pid=9088 runtime=889219 [ns] vruntime=1353116740439 [ns]
<…>-9088 [000] 4232.535000: sched_stat_runtime: comm=top pid=9088 runtime=872178 [ns] vruntime=1353117612617 [ns]
<…>-9088 [000] 4232.536000: sched_stat_runtime: comm=top pid=9088 runtime=1030578 [ns] vruntime=1353118643195 [ns]
scsi檢視 events/scsi目錄下,共支援以下的Events
scsi_dispatch_cmd_done scsi_dispatch_cmd_start scsi_eh_wakeup scsi_dispatch_cmd_error scsi_dispatch_cmd_timeout
#echo 1 > /debug/tracing/events/scsi/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
kjournald-48 [000] 4120.730000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=218489949 txlen=8 protect=0 raw=2a 00 0d 05 e4 5d 00 00 08 00)
<…>-10718 [000] 4120.730000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=218489949 txlen=8 protect=0 raw=2a 00 0d 05 e4 5d 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.734000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267293 txlen=8 protect=0 raw=2a 00 00 04 14 1d 00 00 08 00)
kjournald-48 [000] 4120.734000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267293 txlen=8 protect=0 raw=2a 00 00 04 14 1d 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.734000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267301 txlen=8 protect=0 raw=2a 00 00 04 14 25 00 00 08 00)
kjournald-48 [000] 4120.734000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267301 txlen=8 protect=0 raw=2a 00 00 04 14 25 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.735000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267309 txlen=8 protect=0 raw=2a 00 00 04 14 2d 00 00 08 00)
kjournald-48 [000] 4120.735000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267309 txlen=8 protect=0 raw=2a 00 00 04 14 2d 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.736000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267317 txlen=8 protect=0 raw=2a 00 00 04 14 35 00 00 08 00)
kjournald-48 [000] 4120.736000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267317 txlen=8 protect=0 raw=2a 00 00 04 14 35 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.736000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267325 txlen=8 protect=0 raw=2a 00 00 04 14 3d 00 00 08 00)
kjournald-48 [000] 4120.736000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267325 txlen=8 protect=0 raw=2a 00 00 04 14 3d 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.738000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267333 txlen=8 protect=0 raw=2a 00 00 04 14 45 00 00 08 00)
kjournald-48 [000] 4120.738000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267333 txlen=8 protect=0 raw=2a 00 00 04 14 45 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.738000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267341 txlen=8 protect=0 raw=2a 00 00 04 14 4d 00 00 08 00)
kjournald-48 [000] 4120.738000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267341 txlen=8 protect=0 raw=2a 00 00 04 14 4d 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.738000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267349 txlen=8 protect=0 raw=2a 00 00 04 14 55 00 00 08 00)
kjournald-48 [000] 4120.738000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267349 txlen=8 protect=0 raw=2a 00 00 04 14 55 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.742000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267357 txlen=8 protect=0 raw=2a 00 00 04 14 5d 00 00 08 00)
kjournald-48 [000] 4120.742000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267357 txlen=8 protect=0 raw=2a 00 00 04 14 5d 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.742000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267365 txlen=8 protect=0 raw=2a 00 00 04 14 65 00 00 08 00)
kjournald-48 [000] 4120.742000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267365 txlen=8 protect=0 raw=2a 00 00 04 14 65 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.743000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267373 txlen=8 protect=0 raw=2a 00 00 04 14 6d 00 00 08 00)
kjournald-48 [000] 4120.743000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267373 txlen=8 protect=0 raw=2a 00 00 04 14 6d 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.744000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267381 txlen=8 protect=0 raw=2a 00 00 04 14 75 00 00 08 00)
kjournald-48 [000] 4120.744000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267381 txlen=8 protect=0 raw=2a 00 00 04 14 75 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.744000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267389 txlen=8 protect=0 raw=2a 00 00 04 14 7d 00 00 08 00)
kjournald-48 [000] 4120.744000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267389 txlen=8 protect=0 raw=2a 00 00 04 14 7d 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.745000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267397 txlen=8 protect=0 raw=2a 00 00 04 14 85 00 00 08 00)
kjournald-48 [000] 4120.745000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267397 txlen=8 protect=0 raw=2a 00 00 04 14 85 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
kjournald-48 [000] 4120.745000: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267405 txlen=8 protect=0 raw=2a 00 00 04 14 8d 00 00 08 00)
kjournald-48 [000] 4120.745000: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 cmnd=(WRITE_10 lba=267405 txlen=8 protect=0 raw=2a 00 00 04 14 8d 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
signal檢視 events/signal目錄下,共支援以下的Events
signal_deliver signal_lose_info signal_generate signal_overflow_fail
#echo 1 > /debug/tracing/events/signal/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<…>-9862 [000] 3893.720000: signal_generate: sig=17 errno=0 code=262145 comm=bash pid=1957
<…>-9863 [000] 3893.732000: signal_generate: sig=17 errno=0 code=262145 comm=bash pid=1957
bash-1957 [000] 3893.733000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=807aa60 sa_flags=0
<…>-9864 [000] 3894.941000: signal_generate: sig=17 errno=0 code=262145 comm=bash pid=1957
<…>-9865 [000] 3894.949000: signal_generate: sig=17 errno=0 code=262145 comm=bash pid=1957
bash-1957 [000] 3894.949000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=807aa60 sa_flags=0
<…>-9868 [000] 3899.215000: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=9867
<…>-9869 [000] 3899.225000: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=9867
<…>-9867 [000] 3899.226000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=807aa60 sa_flags=0
<…>-9867 [000] 3899.228000: signal_generate: sig=17 errno=0 code=262145 comm=make pid=9866
make-9866 [000] 3899.228000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=8053850 sa_flags=10000000
<…>-9870 [000] 3899.245000: signal_generate: sig=17 errno=0 code=262145 comm=make pid=9866
make-9866 [000] 3899.246000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=8053850 sa_flags=10000000
<…>-9873 [000] 3899.336000: signal_generate: sig=17 errno=0 code=262145 comm=arm-none-eabi-g pid=9872
<…>-9874 [000] 3899.412000: signal_generate: sig=17 errno=0 code=262145 comm=arm-none-eabi-g pid=9872
<…>-9872 [000] 3899.414000: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=9871
<…>-9871 [000] 3899.414000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=807aa60 sa_flags=0
<…>-9875 [000] 3899.428000: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=9871
<…>-9871 [000] 3899.428000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=807aa60 sa_flags=0
<…>-9871 [000] 3899.431000: signal_generate: sig=17 errno=0 code=262145 comm=make pid=9866
make-9866 [000] 3899.431000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=8053850 sa_flags=10000000
<…>-9878 [000] 3899.514000: signal_generate: sig=17 errno=0 code=262145 comm=arm-none-eabi-g pid=9877
<…>-9879 [000] 3899.578000: signal_generate: sig=17 errno=0 code=262145 comm=arm-none-eabi-g pid=9877
<…>-9877 [000] 3899.580000: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=9876
<…>-9876 [000] 3899.580000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=807aa60 sa_flags=0
<…>-9880 [000] 3899.593000: signal_generate: sig=17 errno=0 code=262145 comm=sh pid=9876
<…>-9876 [000] 3899.594000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=807aa60 sa_flags=0
<…>-9876 [000] 3899.595000: signal_generate: sig=17 errno=0 code=262145 comm=make pid=9866
make-9866 [000] 3899.595000: signal_deliver: sig=17 errno=0 code=262145 sa_handler=8053850 sa_flags=10000000
<…>-9883 [000] 3899.682000: signal_generate: sig=17 errno=0 code=262145 comm=arm-none-eabi-g pid=9882
skb檢視 events/skb目錄下,共支援以下的Events
consume_skb kfree_skb skb_copy_datagram_iovec
#echo 1 > /debug/tracing/events/skb/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
bash-1957 [000] 3800.664000: consume_skb: skbaddr=f5aa2ef0
<idle>-0 [000] 3800.864000: consume_skb: skbaddr=f5aa2a70
top-9088 [000] 3801.184000: consume_skb: skbaddr=f5aa2a70
in.telnetd-1955 [000] 3801.281000: skb_copy_datagram_iovec: skbaddr=f4f6a500 len=3
<idle>-0 [000] 3801.285000: consume_skb: skbaddr=f5aa2ef0
in.telnetd-1955 [000] 3801.437000: skb_copy_datagram_iovec: skbaddr=f4f6a500 len=3
bash-1957 [000] 3801.440000: consume_skb: skbaddr=f5aa2ef0
in.telnetd-1955 [000] 3802.094000: skb_copy_datagram_iovec: skbaddr=f4f6a500 len=3
bash-1957 [000] 3802.098000: consume_skb: skbaddr=f5aa2ef0
in.telnetd-1955 [000] 3802.605000: skb_copy_datagram_iovec: skbaddr=f4f6a500 len=1
bash-1957 [000] 3802.607000: kfree_skb: skbaddr=f4f6a500 protocol=0 location=c0814f61
bash-1957 [000] 3802.609000: consume_skb: skbaddr=f5aa2ef0
<idle>-0 [000] 3802.804000: consume_skb: skbaddr=f5aa2a70
top-9088 [000] 3803.193000: consume_skb: skbaddr=f5aa2a70
<idle>-0 [000] 3803.392000: consume_skb: skbaddr=f5aa2ef0
top-9088 [000] 3805.206000: consume_skb: skbaddr=f5aa2ef0
top-9088 [000] 3805.211000: consume_skb: skbaddr=f5aa2a70
top-9088 [000] 3805.212000: consume_skb: skbaddr=f5aa22f0
in.telnetd-1955 [000] 3805.970000: skb_copy_datagram_iovec: skbaddr=f4f6a500 len=3
in.telnetd-1955 [000] 3805.974000: consume_skb: skbaddr=f5aa22f0
in.telnetd-1955 [000] 3806.251000: skb_copy_datagram_iovec: skbaddr=f4f6a500 len=1
bash-1957 [000] 3806.252000: kfree_skb: skbaddr=f4f6a500 protocol=0 location=c0814f61
bash-1957 [000] 3806.255000: consume_skb: skbaddr=f5aa22f0
<idle>-0 [000] 3806.457000: consume_skb: skbaddr=f5aa2a70
top-9088 [000] 3807.222000: consume_skb: skbaddr=f5aa2a70
top-9088 [000] 3807.222000: consume_skb: skbaddr=f5aa22f0
top-9088 [000] 3807.223000: consume_skb: skbaddr=f5aa22f0
in.telnetd-1955 [000] 3807.300000: skb_copy_datagram_iovec: skbaddr=f4f6a500 len=1
more-9857 [000] 3807.303000: consume_skb: skbaddr=f5aa2ef0
<idle>-0 [000] 3807.431000: consume_skb: skbaddr=f5aa2a70
<idle>-0 [000] 3807.471000: consume_skb: skbaddr=f5aa2770
in.telnetd-1955 [000] 3807.471000: skb_copy_datagram_iovec: skbaddr=f4f6a500 len=3
syscalls檢視 events/syscalls目錄下,共支援以下的Events
sys_enter_accept
sys_enter_accept4
sys_enter_access
sys_enter_acct
sys_enter_add_key
sys_enter_adjtimex
sys_enter_alarm
sys_enter_bdflush
sys_enter_bind
sys_enter_brk
.
sys_exit_vmsplice
sys_exit_wait4
sys_exit_waitid
sys_exit_waitpid
sys_exit_write
sys_exit_writev
#echo 1 > /debug/tracing/events/syscalls/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
bash-1957 [000] 3716.573000: sys_open -> 0x3
bash-1957 [000] 3716.573000: sys_fcntl64(fd: 1, cmd: 1, arg: 0)
bash-1957 [000] 3716.573000: sys_fcntl64 -> 0x0
bash-1957 [000] 3716.573000: sys_fcntl64(fd: 1, cmd: 0, arg: a)
bash-1957 [000] 3716.573000: sys_fcntl64 -> 0xa
bash-1957 [000] 3716.573000: sys_fcntl64(fd: 1, cmd: 1, arg: 0)
bash-1957 [000] 3716.573000: sys_fcntl64 -> 0x0
bash-1957 [000] 3716.573000: sys_fcntl64(fd: a, cmd: 2, arg: 1)
bash-1957 [000] 3716.573000: sys_fcntl64 -> 0x0
bash-1957 [000] 3716.573000: sys_dup2(oldfd: 3, newfd: 1)
bash-1957 [000] 3716.573000: sys_dup2 -> 0x1
bash-1957 [000] 3716.573000: sys_close(fd: 3)
bash-1957 [000] 3716.573000: sys_close -> 0x0
bash-1957 [000] 3716.574000: sys_write(fd: 1, buf: b781c000, count: 1)
bash-1957 [000] 3716.574000: sys_write -> 0x1
bash-1957 [000] 3716.574000: sys_dup2(oldfd: a, newfd: 1)
bash-1957 [000] 3716.574000: sys_dup2 -> 0x1
bash-1957 [000] 3716.574000: sys_fcntl64(fd: a, cmd: 1, arg: 0)
bash-1957 [000] 3716.574000: sys_fcntl64 -> 0x1
bash-1957 [000] 3716.574000: sys_close(fd: a)
bash-1957 [000] 3716.574000: sys_close -> 0x0
bash-1957 [000] 3716.574000: sys_rt_sigprocmask(how: 0, set: 0, oset: 80fe4dc, sigsetsize: 8)
bash-1957 [000] 3716.574000: sys_rt_sigprocmask -> 0x0
bash-1957 [000] 3716.574000: sys_rt_sigaction(sig: 2, act: bfd40dc0, oact: bfd40d34, sigsetsize: 8)
bash-1957 [000] 3716.574000: sys_rt_sigaction -> 0x0
bash-1957 [000] 3716.574000: sys_time(tloc: 0)
bash-1957 [000] 3716.574000: sys_time -> 0x4dd7d442
bash-1957 [000] 3716.574000: sys_rt_sigprocmask(how: 0, set: bfd4054c, oset: bfd404cc, sigsetsize: 8)
bash-1957 [000] 3716.574000: sys_rt_sigprocmask -> 0x0
bash-1957 [000] 3716.574000: sys_ioctl(fd: ff, cmd: 5410, arg: bfd404c4)
bash-1957 [000] 3716.574000: sys_ioctl -> 0x0
timer檢視 events/timer目錄下,共支援以下的Events
hrtimer_expire_exit itimer_state timer_init hrtimer_init timer_cancel timer_start hrtimer_cancel hrtimer_start timer_expire_entry hrtimer_expire_entry itimer_expire timer_expire_exit
#echo 1 > /debug/tracing/events/timer/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
bash-1925 [000] 3590.212000: timer_cancel: timer=f58a10cc
bash-1925 [000] 3590.213000: timer_expire_entry: timer=f58a10cc function=delayed_work_timer_fn now=3290213
bash-1925 [000] 3590.213000: timer_expire_exit: timer=f58a10cc
in.telnetd-1923 [000] 3590.213000: timer_start: timer=f5446b4c function=tcp_write_timer expires=3290566 [timeout=353]
bash-1925 [000] 3590.215000: timer_start: timer=f58a10cc function=delayed_work_timer_fn expires=3290216 [timeout=1]
<idle>-0 [000] 3590.216000: timer_cancel: timer=f58a10cc
<idle>-0 [000] 3590.216000: timer_expire_entry: timer=f58a10cc function=delayed_work_timer_fn now=3290216
<idle>-0 [000] 3590.216000: timer_expire_exit: timer=f58a10cc
<idle>-0 [000] 3590.275000: timer_cancel: timer=f5446b68
<idle>-0 [000] 3590.275000: timer_expire_entry: timer=f5446b68 function=tcp_delack_timer now=3290275
<idle>-0 [000] 3590.275000: timer_expire_exit: timer=f5446b68
<idle>-0 [000] 3590.409000: timer_cancel: timer=f5446b4c
<idle>-0 [000] 3590.409000: timer_start: timer=f5446b4c function=tcp_write_timer expires=3290767 [timeout=358]
<idle>-0 [000] 3590.458000: hrtimer_cancel: hrtimer=f4d21b80
<idle>-0 [000] 3590.458000: hrtimer_expire_entry: hrtimer=f4d21b80 function=hrtimer_wakeup now=3612200721124
<idle>-0 [000] 3590.458000: hrtimer_expire_exit: hrtimer=f4d21b80
gam_server-1890 [000] 3590.459000: hrtimer_init: hrtimer=f4d21b80 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_ABS
gam_server-1890 [000] 3590.459000: hrtimer_start: hrtimer=f4d21b80 function=hrtimer_wakeup expires=3613207309303 softexpires=3613202309315
<idle>-0 [000] 3590.767000: timer_cancel: timer=f5446b4c
<idle>-0 [000] 3590.767000: timer_expire_entry: timer=f5446b4c function=tcp_write_timer now=3290767
<idle>-0 [000] 3590.767000: timer_expire_exit: timer=f5446b4c
<idle>-0 [000] 3591.002000: timer_cancel: timer=f64036b0
<idle>-0 [000] 3591.002000: timer_expire_entry: timer=f64036b0 function=delayed_work_timer_fn now=3291002
<idle>-0 [000] 3591.002000: timer_expire_exit: timer=f64036b0
kworker/0:0-4 [000] 3591.002000: timer_start: timer=f64036b0 function=delayed_work_timer_fn expires=3292002 [timeout=1000]
<idle>-0 [000] 3591.004000: timer_cancel: timer=f598135c
<idle>-0 [000] 3591.004000: timer_expire_entry: timer=f598135c function=e1000_watchdog now=3291004
<idle>-0 [000] 3591.004000: timer_start: timer=f598135c function=e1000_watchdog expires=3293004 [timeout=2000]
vmscan檢視 events/vmscan目錄下,共支援以下的Events
mm_vmscan_memcg_isolate mm_vmscan_memcg_reclaim_begin mm_vmscan_direct_reclaim_begin mm_vmscan_memcg_reclaim_end mm_vmscan_direct_reclaim_end mm_vmscan_memcg_softlimit_reclaim_begin mm_vmscan_kswapd_sleep mm_vmscan_memcg_softlimit_reclaim_end mm_vmscan_kswapd_wake mm_vmscan_wakeup_kswapd mm_vmscan_lru_isolate mm_vmscan_writepage mm_vmscan_lru_shrink_inactive
#echo 1 > /debug/tracing/events/vmscan/enable
檢視 /debug/tracing/trace下的結果,
workqueue檢視 events/workqueue目錄下,共支援以下的Events
workqueue_activate_work workqueue_execute_start workqueue_execute_end workqueue_queue_work
#echo 1 > /debug/tracing/events/workqueue/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
bash-1957 [000] 3205.721000: workqueue_queue_work: work struct=f58a24bc function=flush_to_ldisc workqueue=f600dac0 req_cpu=0 cpu=0
bash-1957 [000] 3205.721000: workqueue_activate_work: work struct f58a24bc
kworker/0:0-4 [000] 3205.721000: workqueue_execute_start: work struct f58a24bc: function flush_to_ldisc
kworker/0:0-4 [000] 3205.721000: workqueue_execute_end: work struct f58a24bc
<idle>-0 [000] 3205.723000: workqueue_queue_work: work struct=f58a24bc function=flush_to_ldisc workqueue=f600dac0 req_cpu=0 cpu=0
<idle>-0 [000] 3205.723000: workqueue_activate_work: work struct f58a24bc
kworker/0:0-4 [000] 3205.723000: workqueue_execute_start: work struct f58a24bc: function flush_to_ldisc
kworker/0:0-4 [000] 3205.723000: workqueue_execute_end: work struct f58a24bc
<idle>-0 [000] 3206.002000: workqueue_queue_work: work struct=f64036a0 function=vmstat_update workqueue=f600dac0 req_cpu=0 cpu=0
<idle>-0 [000] 3206.002000: workqueue_activate_work: work struct f64036a0
kworker/0:0-4 [000] 3206.002000: workqueue_execute_start: work struct f64036a0: function vmstat_update
kworker/0:0-4 [000] 3206.002000: workqueue_execute_end: work struct f64036a0
<idle>-0 [000] 3206.347000: workqueue_queue_work: work struct=f58bf8bc function=flush_to_ldisc workqueue=f600dac0 req_cpu=0 cpu=0
<idle>-0 [000] 3206.347000: workqueue_activate_work: work struct f58bf8bc
kworker/0:0-4 [000] 3206.347000: workqueue_execute_start: work struct f58bf8bc: function flush_to_ldisc
kworker/0:0-4 [000] 3206.347000: workqueue_execute_end: work struct f58bf8bc
<idle>-0 [000] 3206.349000: workqueue_queue_work: work struct=f58a24bc function=flush_to_ldisc workqueue=f600dac0 req_cpu=0 cpu=0
<idle>-0 [000] 3206.349000: workqueue_activate_work: work struct f58a24bc
kworker/0:0-4 [000] 3206.349000: workqueue_execute_start: work struct f58a24bc: function flush_to_ldisc
kworker/0:0-4 [000] 3206.349000: workqueue_execute_end: work struct f58a24bc
<idle>-0 [000] 3206.654000: workqueue_queue_work: work struct=f58bf8bc function=flush_to_ldisc workqueue=f600dac0 req_cpu=0 cpu=0
<idle>-0 [000] 3206.654000: workqueue_activate_work: work struct f58bf8bc
kworker/0:0-4 [000] 3206.654000: workqueue_execute_start: work struct f58bf8bc: function flush_to_ldisc
kworker/0:0-4 [000] 3206.654000: workqueue_execute_end: work struct f58bf8bc
writeback檢視 events/writeback目錄下,共支援以下的Events
writeback_exec writeback_nothread wbc_balance_dirty_start writeback_nowork wbc_balance_dirty_wait writeback_pages_written wbc_balance_dirty_written writeback_queue wbc_writeback_start writeback_thread_start wbc_writeback_wait writeback_thread_stop wbc_writeback_written writeback_wait_iff_congested wbc_writepage writeback_wake_background writeback_bdi_register writeback_wake_forker_thread writeback_bdi_unregister writeback_wake_thread writeback_congestion_wait
#echo 1 > /debug/tracing/events/writeback/enable
檢視 /debug/tracing/trace下的結果,
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<…>-2719 [000] 2262.160000: writeback_wake_thread: bdi 253:0
<…>-1921 [000] 2262.160000: wbc_writeback_start: bdi 253:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0x1d7b80 start=0x0 end=0x0
<…>-1921 [000] 2262.160000: wbc_writeback_written: bdi 253:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0x1d7b80 start=0x0 end=0x0
<…>-1921 [000] 2262.160000: writeback_pages_written: 0
<…>-1921 [000] 2267.160000: wbc_writeback_start: bdi 253:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0x1d8f08 start=0x0 end=0x0
<…>-1921 [000] 2267.160000: wbc_writeback_written: bdi 253:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0x1d8f08 start=0x0 end=0x0
<…>-1921 [000] 2267.160000: writeback_pages_written: 0
<…>-1921 [000] 2272.160000: wbc_writeback_start: bdi 253:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0x1da290 start=0x0 end=0x0
<…>-1921 [000] 2272.160000: writeback_pages_written: 0
<…>-1921 [000] 2277.160000: wbc_writeback_start: bdi 253:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0x1db618 start=0x0 end=0x0
<…>-1921 [000] 2277.160000: wbc_writeback_written: bdi 253:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0x1db618 start=0x0 end=0x0
<…>-1921 [000] 2277.160000: writeback_pages_written: 0
<…>-1921 [000] 2282.160000: wbc_writeback_start: bdi 253:0: towrt=1024 skip=0 mode=0 kupd=1 bgrd=0 reclm=0 cyclic=1 more=0 older=0x1dc9a0 start=0x0 end=0x0
結尾,
在平台移植與開發上,效能調教對於產品化的影響很深,本文主要介紹Ftrace的概念與操作範例,對筆者而言,這套工具可以幫助在複雜行為下,去分析系統效能的瓶頸,例如,是否有中斷關閉過長的行為,或是修改過的核心函式,不適當的行為佔據過多的處理器時間目前,Linux平台上,能使用的工具不少(或是也可以使用商業的ICE產品),對這些工具內部運作原理掌握的程度越高,我們就會有足夠的知識背景幫助團隊在問題發生時,借重適當的工具去分析問題的原因,Ftrace只是提供系統問題一部分的資訊,其它可用的工具與分析問題的知識背景,會是有志於在這產業的開發者,需要持續努力的.
























0 意見:

張貼留言