Vanilla Kernel or Vanilla Software
阅读一个2008年的帖子的时候, 遇到一个词 vanilla kernel, 很是迷惑, 这到底是啥 Linux. 先去查了一下这个词: vanilla: 香草. 香草内核? 不管你想的是什么, 我第一个想到的就是香草冰激凌. 那么 vanilla Linux 到底是什么呢?
ftrace
本文简单介绍 Ftrace 相关的内容, 然后给出几个实用的例子.
关键概念
- Ftrace 官方是首字母大写 Ftrace;
- Ftrace 的 Kernel 文档: https://www.kernel.org/doc/html/latest/trace/ftrace.html
- Ftrace 不是一个简单的工具/命令, 而是一个观测内核的框架. 它可以用来 debug/分析延迟/profiling 内核;
- 它的延迟分析能够分析在 interrupt 关闭/打开, 抢占关闭/打开的情况下的延迟;
- 内核提供了上百个事件(event)的观测, 通过配置 tracefs, 可以通过 Ftrace 看到这些 event 的情况;
kernel 支持的 tracer 以及配置 tracer
pi@raspberrypi:~/tmp $ sudo cat /sys/kernel/tracing/available_tracers blk function_graph wakeup_dl wakeup_rt wakeup irqsoff function nop sudo echo function_graph > /sys/kernel/tracing/current_tracer
tracefs
Ftrace 使用 tracefs 配置和产生输出, tracefs 是一个虚拟的文件系统, 用来与 kernel 提供的tracing 框架交互. 它能够动态的打开/关闭某个tracing feature. tracefs 提供一个层级路径结构, 不同的子目录对应不同的 tracing 事件. 它的主路径在 /sys/kernel/tracing.
通过 tracefs 我们可以:
- 控制 tracing events: 打开或关闭一个/一组events. 如: function call, context switch, memory allocation
- 控制某些选项: 如 trace buffer size, trace data 格式, event handler 的行为
- 配置数据搜集文件: 如你可以配置trace data 从专门文件读,
trace,trace_pipe,trace_marker. - 过滤: 如 过滤特定的线程, 进程, event type.
几个例子
确保 tracefs 被挂载
$ ls /sys/kernel/tracing
# 若没挂载, 使用下面命令挂载 tracefs.
$ sudo mount -t tracefs nodev /sys/kernel/tracingtrace function uptime_proc_show 的例子
# 查看所有可用的 functions
$ cat available_filter_functions
# 写入要 trace 的函数
$ echo uptime_proc_show > /sys/kernel/tracing/set_ftrace_filter
# trace function
$ echo function > /sys/kernel/tracing/current_tracer
# 打开 trace
$ echo 1 > /sys/kernel/tracing/tracing_on
# 做一些有写入操作的动作
$ uptime
# 关闭 tracing
$ echo 0 > /sys/kernel/tracing/tracing_on
# 查看 tracing 数据
$ cat /sys/kernel/tracing/trace
# tracer: function
#
# entries-in-buffer/entries-written: 1/1 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
uptime-39274 [005] ..... 46635.054971: uptime_proc_show <-seq_read_iter
# trace 改成 nop
$ echo nop > /sys/kernel/tracing/current_tracertrace function uptime_proc_show 并显示 stack trace 的例子
根上面的例子一样, 只是在
$ echo uptime_proc_show > /sys/kernel/tracing/set_ftrace_filter
$ echo function > /sys/kernel/tracing/current_tracer
$ echo 1 > /sys/kernel/tracing/options/func_stack_trace
$ echo 1 > /sys/kernel/tracing/tracing_on
$ uptime
$ uptime
$ echo 0 > /sys/kernel/tracing/tracing_on
$ cat /sys/kernel/tracing/trace
# tracer: function
#
# entries-in-buffer/entries-written: 4/4 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
uptime-39283 [005] ..... 47476.243887: uptime_proc_show <-seq_read_iter
uptime-39283 [005] ..... 47476.243892: <stack trace>
=> uptime_proc_show
=> seq_read_iter
=> proc_reg_read_iter
=> new_sync_read
=> vfs_read
=> ksys_read
=> __x64_sys_read
=> do_syscall_64
=> entry_SYSCALL_64_after_hwframe
uptime-39284 [005] ..... 47480.208731: uptime_proc_show <-seq_read_iter
uptime-39284 [005] ..... 47480.208736: <stack trace>
=> uptime_proc_show
=> seq_read_iter
=> proc_reg_read_iter
=> new_sync_read
=> vfs_read
=> ksys_read
=> __x64_sys_read
=> do_syscall_64
=> entry_SYSCALL_64_after_hwframe
# 清理
$ echo 0 > /sys/kernel/tracing/options/func_stack_trace
$ echo 0 > /sys/kernel/tracing/tracing_on
$ echo nop > /sys/kernel/tracing/current_tracer
$ echo "" > /sys/kernel/tracing/tracefunction_graph tracer 的例子
$ echo uptime_proc_show > set_graph_function
$ echo function_graph > current_tracer
$ echo 1 > tracing_on
$ uptime
$ echo 0 > tracing_on
$ cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) | uptime_proc_show() {
0) | get_idle_time() {
0) | get_cpu_idle_time_us() {
0) 0.230 us | ktime_get();
0) 0.788 us | }
0) 1.231 us | }
0) | get_idle_time() {
0) | get_cpu_idle_time_us() {
0) 0.125 us | ktime_get();
0) 0.177 us | nr_iowait_cpu();
0) 0.742 us | }
0) 0.964 us | }
... 省略 一些 重复 ...
0) 0.197 us | ktime_get_with_offset();
0) 0.107 us | ns_to_timespec64();
0) 0.118 us | set_normalized_timespec64();
0) 1.007 us | seq_printf();
0) + 30.206 us | }
# 清理
$ echo nop > current_tracer
$ echo "" > set_graph_functionfunction_graph tracer 并过滤一些 function 的例子
$ echo uptime_proc_show > set_graph_function
$ echo get_idle_time > set_graph_notrace
$ echo function_graph > current_tracer
$ echo 1 > tracing_on
$ uptime
$ echo 0 > tracing_on
$ cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) | uptime_proc_show() {
0) 0.371 us | ktime_get_with_offset();
0) 0.152 us | ns_to_timespec64();
0) 0.138 us | set_normalized_timespec64();
0) 1.027 us | seq_printf();
0) 8.900 us | }
# 清理
$ echo nop > current_tracer
$ echo "" > set_graph_function
$ echo "" > set_graph_notracetrace event 的例子
显示可用的 trace events:
$ cat /sys/kernel/tracing/available_events
$ ls /sys/kernel/tracing/events/以 events/syscalls/sys_enter_write 为例展示 trace event
$ ls /sys/kernel/tracing/events/syscalls/sys_enter_write
enable filter format hist id inject trigger
# 查看输出格式
$ cat /sys/kernel/tracing/events/syscalls/sys_enter_write/format
# enable event tracing for that event
$ echo 1 > /sys/kernel/tracing/events/syscalls/sys_enter_write/enable
$ echo 1 > /sys/kernel/tracing/tracing_on
# 查看输出
$ cat /sys/kernel/tracing/trace
cat-39448 [005] ..... 49432.357354: sys_write(fd: 1, buf: 7f8e06c19000, count: 62)
cat-39448 [005] ..... 49432.357304: sys_write(fd: 1, buf: 7f8e06c19000, count: 62)
# 清理
$ echo 0 > /sys/kernel/tracing/tracing_on
$ echo 0 > /sys/kernel/tracing/events/syscalls/sys_enter_write/enable设置 event 过滤条件
过滤 fd 不是 1 的(标准输出 stdout):
$ cat /sys/kernel/tracing/events/syscalls/sys_enter_write/filter
none
$ echo "fd!=1" > /sys/kernel/tracing/events/syscalls/sys_enter_write/filter
$ echo 1 > /sys/kernel/tracing/events/syscalls/sys_enter_write/enable
$ echo 1 > /sys/kernel/tracing/tracing_on
$ cat /sys/kernel/tracing/trace
sudo-3129 [003] ..... 51059.260638: sys_write(fd: 8, buf: 560f1fb345e0, count: fff)
# 清理
$ echo 0 > /sys/kernel/tracing/tracing_on
$ echo 0 > /sys/kernel/tracing/events/syscalls/sys_enter_write/enable
$ echo "" > /sys/kernel/tracing/traceevent 的 histogram
histogram 通过 trigger 实现
# 查看 trigger
cat /sys/kernel/tracing/events/events/syscalls/sys_enter_write/trigger
# Available triggers:
# traceon traceoff snapshot stacktrace enable_event disable_event enable_hist disable_hist hist
$ echo "hist:key=common_pid.execname:val=count:sort=count.descending" > /sys/kernel/tracing/events/syscalls/sys_enter_write/trigger
$ echo "fd!=1" > /sys/kernel/tracing/events/syscalls/sys_enter_write/filter
$ echo 1 > /sys/kernel/tracing/events/syscalls/sys_enter_write/enable
$ echo 1 > /sys/kernel/tracing/tracing_on
$ cat /sys/kernel/tracing/trace
$ cat /sys/kernel/tracing/events/syscalls/sys_enter_write/hist
# event histogram
#
# trigger info: hist:keys=common_pid.execname:vals=hitcount,count:sort=count.descending:size=2048 [active]
#
{ common_pid: sshd [ 1036] } hitcount: 169 count: 13000
{ common_pid: sudo [ 3129] } hitcount: 169 count: 9678
{ common_pid: cat [ 39478] } hitcount: 2 count: 7893
{ common_pid: bash [ 3132] } hitcount: 108 count: 1371
{ common_pid: multipathd [ 497] } hitcount: 122 count: 976
{ common_pid: cat [ 39479] } hitcount: 4 count: 37
{ common_pid: upowerd [ 2616] } hitcount: 1 count: 8
Totals:
Hits: 575
Entries: 7
Dropped: 0
# 清理
$ echo 0 > /sys/kernel/tracing/tracing_on
$ echo 0 > /sys/kernel/tracing/events/syscalls/sys_enter_write/enable
$ echo "" > /sys/kernel/tracing/traceFtrace filter
多个 filter
$ echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter $ cat set_ftrace_filter hrtimer_interrupt sys_nanosleep模糊匹配 模式 使用*. 前面,后面,中间等
$ echo 'hrtimer_*' > set_ftrace_filter $ cat set_ftrace_filter添加更多 filter
$ echo sys_nanosleep >> set_ftrace_filter使用文件
available_filter_functions里面的索引值$ head -1 available_filter_functions $ echo 1 > set_ftrace_filter $ cat set_ftrace_filter写文件到文件系统, 并抓取
ksys_write的 function call:写一个shell 文件 test.sh
echo $$ sleep 5 echo "" > /sys/kernel/tracing/trace echo ksys_write > /sys/kernel/tracing/set_graph_function echo $$ > /sys/kernel/tracing/set_ftrace_pid echo function_graph > /sys/kernel/tracing/current_tracer echo 1 > /sys/kernel/tracing/tracing_on echo $$ > /tmp/test.txt echo 0 > /sys/kernel/tracing/tracing_on cat /sys/kernel/tracing/trace > /tmp/result.txt echo nop > /sys/kernel/tracing/current_tracer echo "" > /sys/kernel/tracing/trace echo "done" cat /tmp/result.txt
其它
以下都是材料, 还没整理:
- 这应该是比较早的关于 ftrace 的邮件: https://lwn.net/Articles/264029/
- 关于 ftrace 的一个配置的说明: https://cateee.net/lkddb/web-lkddb/FTRACE.html
Enable the kernel to trace every kernel function. This is done by
using a compiler feature to insert a small, 5-byte No-Operation
instruction to the beginning of every kernel function, which NOP
sequence is then dynamically patched into a tracer call when tracing
is enabled by the administrator. If it's runtime disabled (the bootup
default), then the overhead of the instructions is very small and not
measurable even in micro-benchmarks.
3.https://alex.dzyoba.com/blog/ftrace/#:~:text=Ftrace%20is%20a%20framework%20for,Tracepoints%20support
关于 ftrace 的一些关键字:
框架, NOP, -pg, gcc, gprof, trace-cmd, kernelShark, tracefs, 文件接口, mcount, 所有 kernel 函数, function, function_graph.
how it works
Ftrace -> mcount -> gpro -> (-pg flags)
https://github.com/freelancer-leon/notes/blob/master/kernel/trace/ftrace-design.md
https://ftp.gnu.org/old-gnu/Manuals/gprof-2.9.1/html_node/gprof_25.html
参考: https://www.kernel.org/doc/html/latest/trace/ftrace.html
站点的流量少了
今天有空去看了下最近的这个站点的流量, 发现少了一些. 再看一周的流量, 也比以前少了. 之前至少每天有30~70的PV. 可是最近少了一半.
打开更长的周期和来源分析一下, 从5月开始,发现从百度来的明显减少了, 不知道是为什么? 最近几天几乎为0. 
大概5月13号左右换过一次 IP. 但是看上去并不相关.
去看了下最近百度的抓取状态, 发现最近半个月没有任何抓取数据. 不知道是不是因为最近没有更新文章导致的.
Linux kernel 的编译选项(flags)
最近在一个树莓派上实验 BPF 工具, 首先安装了 BCC 和 bpftrace. 不过安装之后有些不能用. 根据官方安装文档, 要使用这些工具, Linux kernel 在编译的时候, 需要打开某些 flags. 根据文档, 这些 flags 在这些地方:
Kernel compile flags can usually be checked by looking at
/proc/config.gz or /boot/config-.
但是我的树莓派却没有这些文件:
pi@raspberrypi:~ $ uname -a
Linux raspberrypi 5.15.32-v7+ #1538 SMP Thu Mar 31 19:38:48 BST 2022 armv7l GNU/Linux
pi@raspberrypi:~ $ cat /etc/issue
Raspbian GNU/Linux 11 \n \l
pi@raspberrypi:~ $ ls -lah /proc/config.gz
ls: cannot access '/proc/config.gz': No such file or directory
pi@raspberrypi:~ $ ls -lah /boot/* | grep config
-rwxr-xr-x 1 root root 1.7K Oct 4 2018 /boot/config.txt
pi@raspberrypi:~ $ cat /boot/config.txt | grep BPF可以看到, 我最新版本的 Raspbian 里面没有 /proc/config.gz 文件. 虽然能在 /boot/ 目录看到一个 config.txt, 却没有找到 BPF 相关的配置.
于是去查看 proc 伪文件系统的 man 文档, 可以看到说 /proc/config.gz 其实是由 /lib/modules/$(uname -r)/build/.config 复制过来的. 于是去查看这个原始文件:
pi@raspberrypi:~ $ cat /lib/modules/$(uname -r)/build/.config | grep BPF
CONFIG_BPF=y
CONFIG_HAVE_EBPF_JIT=y
# BPF subsystem
CONFIG_BPF_SYSCALL=y
# CONFIG_BPF_JIT is not set
# CONFIG_BPF_UNPRIV_DEFAULT_OFF is not set
# CONFIG_BPF_PRELOAD is not set
# end of BPF subsystem
CONFIG_CGROUP_BPF=y
CONFIG_NETFILTER_XT_MATCH_BPF=m
# CONFIG_BPFILTER is not set
# CONFIG_NET_CLS_BPF is not set
# CONFIG_NET_ACT_BPF is not set
# CONFIG_BPF_STREAM_PARSER is not set
CONFIG_LWTUNNEL_BPF=y
CONFIG_BPF_LIRC_MODE2=y
# CONFIG_NBPFAXI_DMA is not set
CONFIG_BPF_EVENTS=y
# CONFIG_TEST_BPF is not set所以, 其实这些 kernel 的编译配置都是在存在这个文件的.
gprof
gprof 是什么?
gprof 是一个用来分析应用程序把时间花费在哪的性能分析工具.
gprof 怎么用?
- 编译和链接程序使用
-pg选项; - 执行程序, 产生 gmon.out 数据文件;
- 使用 gprof 读取 gmon.out 数据文件产生报告;
//使用 **-pg** 参数编译你的程序
pi@raspberrypi:~ $ echo 'int main(){}' | gcc -o hello -xc -pg -O3 -
pi@raspberrypi:~ $ ls
hello
pi@raspberrypi:~ $ ./hello
pi@raspberrypi:~ $ ls -lah
gmon.out hello
pi@raspberrypi:~ $ which gprof
/usr/bin/gprof
pi@raspberrypi:~ $ gprof hello gmon.outgprof - how it works?
要想使用 gprof 做性能分析, 必须在编译程序的时候注入一些代码, 这些代码在运行时搜集代码的执行情况, 把搜集的数据放到当前路径下的 gmon.out 文件. 然后 gprof 读这个文件, 生成 report.
实现细节: https://sourceware.org/binutils/docs/gprof/Implementation.html
使用 -pg 选项编译的时候, 每个函数的开头都条用 mcount (monitor count). mcount 在不同的平台实现不同, 不过代码都在 profiling 的 lib 里面, 它负责记录并维护这些 call graph 的数据: 包括当前函数以及谁 call 的当前函数. 一般当前函数以及父函数都是通过遍历栈帧的方式获得的.
The mcount routine, included in the profiling library, is responsible for recording in an in-memory call graph table both its parent routine (the child) and its parent's parent. This is typically done by examining the stack frame to find both the address of the child, and the return address in the original parent. Since this is a very machine-dependant operation, mcount itself is typically a short assembly-language stub routine that extracts the required information, and then calls __mcount_internal (a normal C function) with two arguments - frompc and selfpc. __mcount_internal is responsible for maintaining the in-memory call graph, which records frompc, selfpc, and the number of times each of these call arcs was transversed.库函数的调用记录是通过特殊的库版本实现的, 通常这些库都是使用-pg选项生成的.
为什么是 pg ?
在 gprof 之前, 有个性能分析程序是 prof, 要使用 prof 这个工具, gcc 给的参数是 -p, 那么轮到 gprof 的时候, 就使用参数 -pg
pg 之外的其它编译参数
-g line-by-line profiling -a if 的每个分支, loop 的每次循环
refer:
https://hpc.llnl.gov/software/development-environment-software/gprof
https://en.wikipedia.org/wiki/Gprof