====== 11. Profiling în nucleul Linux ====== ===== Subiecte abordate ===== * Resurse urmărite pentru profiling și benchmarking * Utilitare pentru profiling: perf, tracepoints, kprobes, ftrace, măsurători de timp * Scenarii pentru profiling la nivelul nucleului ===== Resurse utile ===== * http://btorpey.github.io/blog/2014/02/18/clock-sources-in-linux/ * http://people.redhat.com/williams/latency-howto/rt-latency-howto.txt * http://stackoverflow.com/questions/4655711/measuring-execution-time-of-a-function-inside-linux-kernel * https://rt.wiki.kernel.org/index.php/Cyclictest * https://sourceware.org/systemtap/ * http://lttng.org/ * http://elinux.org/Ftrace * https://www.kernel.org/doc/Documentation/kprobes.txt * https://www.kernel.org/doc/Documentation/trace/ * https://lwn.net/Articles/608497/ ===== Exerciții ===== Arhiva de suport pentru exerciții se găsește [[http://koala.cs.pub.ro/training/res/linux-kernel-dev/arc/cap-11-tasks.zip|aici]]. Descărcați arhiva și apoi decomprimați-o folosind comanda unzip cap-11-tasks.zip ==== Folosire perf ==== Unul din utilitarele principale de profiling în Linux este perf. perf folosește suportul sistemului de operare pentru a oferi informații diverse despre comportamentul unui proces sau al sistemului. Perf are noțiunea de evenimente care pot fi monitorizate/contorizate. În directorul ''perf/'' există două fișier care realizează operații cu memoria în diverse situații. Compilați fișierele și apoi rulați-le sub ''perf'' în mașina virtuală VirtualBox folosind comanda sudo perf stat ./row sudo perf stat ./coumn În comanda de mai sus observăm timpul total de rulare și alte informația. Observăm cum accesarea memoriei afectează performanța. În cazul în care avem acces la un sistem fizic cu suport hardware pentru contorizarea cache miss-urilor putem rula comenzi precum cele de mai jos: sudo perf stat -e cache-misses,L1-dcache-load-misses ./row Performance counter stats for './row': 63,244 cache-misses 336,519 L1-dcache-load-misses 0.094361996 seconds time elapsed sudo perf stat -e cache-misses,L1-dcache-load-misses ./column Performance counter stats for './column': 16,419,606 cache-misses 17,372,077 L1-dcache-load-misses 0.340619826 seconds time elapsed ==== perf + tracepoints ==== ''perf'' poate fi folosit în conjuncție funcționalitatea de ''tracepoints'' a kernel-ului pentru a afișa informații statistice despre apeluri de funcții de la nivelul nucleului. De exemplu, dacă ne interesează câte apeluri ''kmalloc()'' se întâmplă pe parcursul a ''10'' secunde de rulare a sistemului vom folosi, pe mașina virtuală VirtualBox comanda sudo perf stat -a -e kmem:kmalloc sleep 10 Dacă ne interesează câte apeluri ''kmalloc()'' face o aplicație dată, vom folosi comanda sudo perf stat -e kmem:kmalloc ls Pentru a afișa toate tracepoint-urile folosibile cu ajutorul comenzii ''perf'' folosim comanda sudo perf list tracepoint Folosiți comanda ''perf'' de tracepoint pentru a investiga funcții din kernel folosite de o aplicație oarecare. ==== Măsurare timp în user space ==== În anumite situații avem nevoie să măsurăm doar anumite funcționalități din cadrul unui program: accese la memorie, apeluri de funcții, secvență de cod. Putem folosi un profiler care să ne spună acest lucru sau, dacă avem acces la codul sursă, putem calcula intern durata. În directorul ''user-measure-time/'' se găsește implementarea unui program care măsoară granularitatea la nivel de milisecundă a unui apel ''nanosleep()''. Urmăriți programul și rulați-l pe mașina virtuală VirtualBox. Dacă doriți puteți să-l rulați și pe mașina virtuală QEMU. Programul are rolul de a ne arăta dacă sistemul ne permite operații de tip sleep cu granularitate la nivel de milisecundă. Putem valida funcționarea corectă urmărind numărul de schimbări de context voluntare: /usr/bin/time -v ./measure_time Sleep time (ns): 1114314228 Command being timed: "./measure_time" User time (seconds): 0.00 System time (seconds): 0.03 Percent of CPU this job got: 2% Elapsed (wall clock) time (h:mm:ss or m:ss): 0:01.11 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 1344 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 0 Minor (reclaiming a frame) page faults: 76 Voluntary context switches: 1001 Involuntary context switches: 1 Swaps: 0 File system inputs: 0 File system outputs: 0 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0 Întrucât sunt ''1000'' de schimbări voluntare înseamnă că sistemul are suport pentru acest nivel de granularitate de sleep. Acest lucru se poate detecta urmărind intrările cu șirul ''resolution'' în fișierul ''/proc/timers'': $ cat /proc/timer_list | grep resolution .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs .resolution: 1 nsecs Granularitatea (rezoluția) este de 1 nanosecundă, deci putem avea granularitate la nivel de milisecundă pentru sleep. ==== Măsurare timp în user space și kernel space ==== Testați overhead-ul aproximativ al unui apel de sistem implementând un driver care folosește o funcție ''ioctl()'' care, pentru început, nu face nimic. Apelați funcția dintr-un proces din userspace (de mai multe ori) și afișați durata aproximativă a apelului ''ioctl()''. Apoi apelați în cadrul apelului ''ioctl()'' funcția kmalloc(1024, GFP_KERNEL); și afișați care este overhead-ul cauzat de funcția ''kmalloc()''. Realizați o sumă a diferențelor între valorile variabilei ''jiffies'' după apelul ''kmalloc()'' și înainte de apelul ''kmalloc()'' pentru a avea o estimare la nivelul nucleului legată de durata apelului ''kmalloc()''. ==== kprobes și SystemTap ==== În anumite situații un dezvoltator dorește să afișeze informații din anumite puncte de la nivelul nucleului sau să altereze în mod dinamic comportamentul unei funcții (mai rar). Pentru aceasta are nevoie de un mod prin care să poată "injecta" funcționalitate în momentul în care o funcție este apelată. Acest lucru este realizabil cu ajutorul funcționalității de ''kprobes'', //probe// care pot fi injectate dinamic în cadrul funcțiilor de la nivelul nucleului. În directorul ''samples/kprobes/'' din codul sursă al nucleului aveți exemple de trei module care folosesc cele trei tipuri de probe: ''kprobes'', ''kretprobes'' și ''jprobes''. Compilați și testați cele trei module (aveți nevoie să le copiați undeva și să creați pentru ele fișierele Makefile și Kbuild). Întrucât este mai dificil de creat module care să folosească facilitatea de ''kprobes'' (nu toată lumea face module de kernel la nivelul fiecărei zile), se poate folosi utilitarul SystemTap. SystemTap oferă un limbaj propriu (similar C/shell scripting) cu ajutorul căruia se creează scripturi. Aceste scripturi sunt apoi folosite pentru a genera în dinamic un modul de kernel și pentru a-l injecta apoi la nivelul nucleului și a produce funcționalitatea dorită. ==== Folosire ftrace ==== De la versiunea ''2.6.27'' există o nouă funcționalitate a nucleului Linux care poate fi folosită pentru investigații (tracing) și analiză de performanță: ''ftrace''. ''ftrace'' realizează de principiu //function tracing// la nivelul nucleului, cu overhead minim, dar poate fi folosit și pentru alte funcționalităti. ''ftrace'' este extrem de flexibil, inclusiv docmentația sa fiind destul de vastă. ''ftrace'' funcționează cu ajutorul sistemului de fișiere ''debugfs'', montat, în general, în ''/sys/kernel/debug/''. Interfața pentru ''ftrace'' se găsește în ''/sys/kernel/debug/tracing/''. Urmăriți fișierele din acel director pentru o investigație inițială. Pentru o investigație mai facilă, se poate folosi utilitarul ''trace-cmd'' (așa cum este indicat [[http://elinux.org/Ftrace|aici]]). Ca să investigăm, de exemplu, funcțiile folosite de procesul curent vom folosi, ca **root**, pe mașina virtuală VirtualBox, comenzile root@box:~# cd /sys/kernel/debug/tracing/ root@box:/sys/kernel/debug/tracing# echo $$ > set_ftrace_pid root@box:/sys/kernel/debug/tracing# echo function > current_tracer root@box:/sys/kernel/debug/tracing# echo 1 > tracing_on root@box:/sys/kernel/debug/tracing# ls available_events dyn_ftrace_total_info kprobe_profile saved_cmdlines set_graph_function trace tracing_max_latency available_filter_functions enabled_functions max_graph_depth saved_cmdlines_size set_graph_notrace trace_clock tracing_on available_tracers events options set_event snapshot trace_marker tracing_thresh buffer_size_kb free_buffer per_cpu set_ftrace_filter stack_max_size trace_options uprobe_events buffer_total_size_kb instances printk_formats set_ftrace_notrace stack_trace trace_pipe uprobe_profile current_tracer kprobe_events README set_ftrace_pid stack_trace_filter tracing_cpumask root@box:/sys/kernel/debug/tracing# echo 0 > tracing_on root@box:/sys/kernel/debug/tracing# less trace Observați cantitatea mare de output din fișierul ''trace''. Dacă vrem să investigăm doar apelul funcției ''schedule_timeout()'' vom folosi, ca **root**, pe mașina virtuală VirtualBox, comenzile root@box:/sys/kernel/debug/tracing# echo $$ > set_ftrace_pid root@box:/sys/kernel/debug/tracing# echo "schedule_timeout" > set_ftrace_filter root@box:/sys/kernel/debug/tracing# echo function > current_tracer root@box:/sys/kernel/debug/tracing# echo 1 > tracing_on root@box:/sys/kernel/debug/tracing# ls available_events dyn_ftrace_total_info kprobe_profile saved_cmdlines set_graph_function trace tracing_max_latency available_filter_functions enabled_functions max_graph_depth saved_cmdlines_size set_graph_notrace trace_clock tracing_on available_tracers events options set_event snapshot trace_marker tracing_thresh buffer_size_kb free_buffer per_cpu set_ftrace_filter stack_max_size trace_options uprobe_events buffer_total_size_kb instances printk_formats set_ftrace_notrace stack_trace trace_pipe uprobe_profile current_tracer kprobe_events README set_ftrace_pid stack_trace_filter tracing_cpumask root@box:/sys/kernel/debug/tracing# echo 0 > tracing_on root@box:/sys/kernel/debug/tracing# less trace Dacă ne interesează, de exemplu, să obținem graficul de apeluri de funcții împreună cu durata lor pentru apelurile de sistem open (''SyS_open'') com folosi comenzile root@box:/sys/kernel/debug/tracing# echo $$ > set_ftrace_pid root@box:/sys/kernel/debug/tracing# echo > set_ftrace_filter root@box:/sys/kernel/debug/tracing# echo "SyS_open" > set_graph_function root@box:/sys/kernel/debug/tracing# echo function_graph > current_tracer root@box:/sys/kernel/debug/tracing# echo 0 > tracing_on root@box:/sys/kernel/debug/tracing# ls available_events dyn_ftrace_total_info kprobe_profile saved_cmdlines set_graph_function trace tracing_max_latency available_filter_functions enabled_functions max_graph_depth saved_cmdlines_size set_graph_notrace trace_clock tracing_on available_tracers events options set_event snapshot trace_marker tracing_thresh buffer_size_kb free_buffer per_cpu set_ftrace_filter stack_max_size trace_options uprobe_events buffer_total_size_kb instances printk_formats set_ftrace_notrace stack_trace trace_pipe uprobe_profile current_tracer kprobe_events README set_ftrace_pid stack_trace_filter tracing_cpumask root@box:/sys/kernel/debug/tracing# echo 1 > tracing_on root@box:/sys/kernel/debug/tracing# less trace ''ftrace'' conține un set impresionant de funcționalități. Le puteți urmări în [[https://www.kernel.org/doc/Documentation/trace/ftrace.txt|documentația din kernel]] și le puteți testa.