Profile and Tracing - MarekBykowski/readme GitHub Wiki
Perf
root@fvp-base:~# perf stat wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
Connecting to downloads.yoctoproject.org (37.27.135.249:80)
saving to 'linux-2.6.19.2.tar.bz2'
linux-2.6.19.2.tar.b 100% |***************************************************************************************| 40.7M 0:00:00 ETA
'linux-2.6.19.2.tar.bz2' saved
Performance counter stats for 'wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2':
1400.08 msec task-clock # 0.202 CPUs utilized
221 context-switches # 157.848 /sec
0 cpu-migrations # 0.000 /sec
80 page-faults # 57.140 /sec
138323644 cycles # 0.099 GHz
138323644 instructions # 1.00 insn per cycle
13721653 branches # 9.801 M/sec
0 branch-misses
6.934882790 seconds time elapsed
0.035931000 seconds user
1.373390000 seconds sys
Ftrace
ftrace essentially refers to everything included in the /sys/kernel/debug/tracing directory of the mounted debugfs filesystem
# mount -t debugfs nodev /sys/kernel/debug
# cd /sys/kernel/debug/tracing
# echo <pid-of-berserk-task> > set_ftrace_pid
# echo function > current_tracer
# cat trace
trace-cmd
trace-cmd is an extensive command-line “wrapper” interface that hides the details of all the individual files in /sys/kernel/debug/tracing.
List available tracers
$ trace-cmd list -t
blk function_graph function nop
Enable one from the list, eg. function tracer
trace-cmd start -p function
Show only 50 lines of the trace output, then stop and clear
trace-cmd show | head -n 50
trace-cmd stop
trace-cmd clear
Pick another tracer function_graph`
trace-cmd start -p function_graph
trace-cmd show | head -n 50
trace-cmd stop
trace-cmd clear
If you want to see more depth
trace-cmd start -p function_graph --max-graph-depth 5
trace-cmd show | head -n 50
trace-cmd stop
trace-cmd clear
Trace specific function
Show all available functions to trace
trace-cmd list -f
Show starting ext4_
trace-cmd list -f | grep ^ext4_
Trace all ext4_ and play back
trace-cmd record -l ext4_* -p function_graph
trace-cmd report | head -20
Stack trace
Use /sys/kernel/debug/tracing
The stack tracer is built form the function tracer infrastructure. It does not uses the Ftrace ring buffer, but it does use the function tracer to hook into every function call.
echo 1 > /proc/sys/kernel/stack_tracer_enabled
See the stack back trace of the largest stack that was encountered when the stack tracer is activated
cat /sys/kernel/debug/tracing/stack_trace
See the max size used through the run
# cat /sys/kernel/debug/tracing/stack_max_size
3848
Use trace-cmd
Enabling the stack tracer checks the stack used at each function call within the kernel. When a new maximum usage stack is discovered, it is recorded.
- Enable the stack tracer and play a bit in the system
root@fvp-base:~# trace-cmd stack --start
root@fvp-base:~# trace-cmd stack
(stack tracer running)
Depth Size Location (9 entries)
----- ---- --------
0) 3816 24 stack_trace_consume_entry+0x8/0x68
1) 3792 184 arch_stack_walk+0x150/0x3e0
2) 3608 688 stack_trace_save+0x58/0x90
3) 2920 1312 __kfence_alloc+0xc4/0x740
4) 1608 192 mempool_alloc_slab+0x24/0x38
5) 1416 48 handle_mm_fault+0x17c/0x280
6) 1368 368 el1_abort+0x40/0x68
7) 1000 576 __arch_clear_user+0x10/0xa0
8) 424 424 load_elf_binary+0x5b4/0x14a8
Then download a file and check if the greater stack back trace was recorded. Ss seen yes it was.
root@fvp-base:~# wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2
Connecting to downloads.yoctoproject.org (37.27.135.249:80)
saving to 'linux-2.6.19.2.tar.bz2'
linux-2.6.19.2.tar.b 100% |***************************************************************************************| 40.7M 0:00:00 ETA
'linux-2.6.19.2.tar.bz2' saved
root@fvp-base:~# trace-cmd stack
(stack tracer running)
Depth Size Location (16 entries)
----- ---- --------
0) 3976 312 idle_cpu+0x8/0x60
1) 3664 120 irq_exit_rcu+0x5c/0xd8
2) 3544 304 virtqueue_notify+0x2c/0x68
3) 3240 336 start_xmit+0x3c4/0x4d8
4) 2904 192 __dev_queue_xmit+0x3c8/0xdd0
5) 2712 112 ip_finish_output+0x50/0x130
6) 2600 320 __ip_queue_xmit+0x170/0x460
7) 2280 128 ip_queue_xmit+0x1c/0x30
8) 2152 48 __tcp_push_pending_frames+0x44/0xd8
9) 2104 368 tcp_v4_do_rcv+0x1f4/0x380
10) 1736 192 tcp_v4_rcv+0xd94/0xe48
11) 1544 256 ip_sublist_rcv_finish+0x50/0x78
12) 1288 144 ip_list_rcv+0x104/0x1b0
13) 1144 320 netif_receive_skb_list_internal+0x200/0x340
14) 824 288 napi_complete_done+0x70/0x1c0
15) 536 536 net_rx_action+0x2e4/0x340