使用ftrace定位“谁动了我的内核日志”

Posted 2021-03-21 tsecer

一、问题

进程被OOMkill之后退出，在/var/log/messages文件中并没有发现对应的系统日志，那么日志去哪里了呢？

二、内核日志如何获得

内核相关日志相关功能主要集中在kernelprintkprintk.c，虽然功能比较简单，但是在内核代码组织结构中还是享有一个单独的文件夹，可见该功能的重要性。
从实现上看，内核运行时printk打印的日志会被放在一个内核缓冲区结构中，还会被打印到内核启动参数指定的终端上。对于终端的配置，可以通过
tsecer@harry: cat /proc/cmdline
……console=ttyS0 console=tty0 ……
tsecer@harry:
这里的ttyS0对应我们机器上的串口，通常在嵌入式开发中这个输入必不可少并且非常有用。另一个tty0我们可以认为就是PC机器上的“键盘+显示器”组成的输入/输入系统。
而对于内核中环形缓冲区中存储的日志，用户态可以有两种方式来获取：

1、通过虚拟的设备文件

设备文件的主设备号为1，次设备号为11
#define MEM_MAJOR 1
#ifdef CONFIG_PRINTK
[11] = { "kmsg", 0644, &kmsg_fops, NULL },
#endif
tsecer@harry: ll -lrt /dev/kmsg
crw-r--r-- 1 root root 1, 11 Jul 5 14:27 /dev/kmsg
tsecer@harry:

2、通过syslog系统调用

由于该系统调用名称可C库中syslog重复了，C库对应的用户态函数名称为klogctl。通常来说，系统日志守护进程(默认为rsyslogd)会定时从中读取内核日志并转移到/var/log/messages文件中，但是也有可能是其它进程读取：
tsecer@harry: fuser /dev/kmsg
/dev/kmsg: 1 145
tsecer@harry: cat /proc/145/cmdline
/usr/lib/systemd/systemd-journald
tsecer@harry:

 

三、当系统没有/dev/kmsg文件时

当系统没有这个文件时，通过dmesg看到没有内核日志输出，说明有进程“偷偷的”把内核日志读取之后并清空了。而清空是通过syslog系统调用实现，所以现在的问题就是如何找到是系统中那个进程执行了这个操作？
此时就需要使用到内核API调用接口的监控，这个时候ftrace就闪亮登场了。

四、如何使用ftrace找到API调用进程

这个从网上搜索下就可以找到很多，对于这个问题，操作方法如下：
echo SyS_syslog > /sys/kernel/debug/tracing/set_ftrace_filter
echo function >/sys/kernel/debug/tracing/current_tracer
tail -f /sys/kernel/debug/tracing/trace
从/sys/kernel/debug/tracing/trace可以看到是哪个进程调用了该接口，有进程PID和进程字符串名称。

五、ftrace的实现说明

1、documentation中说明

ftrace原始的意义应该是function trace的缩写，它最主要的功能是提供了函数级别的跟踪，这个是一个非常大的进步。这些函数不仅包括了系统API接口，还包含了内核中主要的内部接口，所以对系统监控和分析非常有意义。
Although ftrace is typically considered the function tracer, it
is really a frame work of several assorted tracing utilities.
There‘s latency tracing to examine what occurs between interrupts
disabled and enabled, as well as for preemption and from a time
a task is woken to the task is actually scheduled in.

2、实现需要考虑的问题

2、1 效率

这个感觉是最主要的问题，如果要跟踪函数运行，那么必须要在函数运行前打桩(插入stub)，而如果真的所有函数打桩，则将会极大拖慢系统运行效率，所以自然而然需要使用热补丁。
使用热补丁可能需要编译器支持，否则在函数开始的指令在CISC(机器指令不定长)机型下无法插入一个完整的跳转指令。

2、2 符号表查询

由于用户提供的是一个字符串名称，所以需要能够实现字符串和地址之间的转换，这个感觉相对比较简单，可以通过链接器支持。

3、内核的实现方法

3、1 编译器支持

从linux-3.12.6Documentation raceftrace-design.txt文件说明来看，这里打桩使用了gcc的-pg功能，添加该功能会为每个函数执行前添加一个mcount调用
tsecer@harry: cat main.c
int main()
{
return 0;
}
tsecer@harry: gcc -S -pg main.c
tsecer@harry: cat main.s
.file "main.c"
.text
.globl main
.type main, @function
main:
.LFB0:
.cfi_startproc
pushq %rbp
.cfi_def_cfa_offset 16
.cfi_offset 6, -16
movq %rsp, %rbp
.cfi_def_cfa_register 6
call mcount
movl $0, %eax
popq %rbp
.cfi_def_cfa 7, 8
ret
.cfi_endproc
.LFE0:
.size main, .-main
.ident "GCC: (GNU) 4.8.5 20150623 (Red Hat 4.8.5-4)"
.section .note.GNU-stack,"",@progbits
tsecer@harry:
以linux-3.12.6archx86kernelMakefile.txt文件为例，可以看到在开启CONFIG_FUNCTION_TRACER的时候添加了-pg编译选项
ifdef CONFIG_FUNCTION_TRACER
# Do not profile debug and lowlevel utilities
CFLAGS_REMOVE_tsc.o = -pg
CFLAGS_REMOVE_paravirt-spinlocks.o = -pg
CFLAGS_REMOVE_pvclock.o = -pg
CFLAGS_REMOVE_kvmclock.o = -pg
CFLAGS_REMOVE_ftrace.o = -pg
CFLAGS_REMOVE_early_printk.o = -pg
endif

3、2运行效率问题

每个函数加一个mcount调用，即使mcount为空，那也遭不住啊。所以内核的方法是在构建生成的最终可执行文件中添加所有有mcount调用位置的地址信息，在内核启动前，动态把这些位置的mcount调用转换为nop指令，这样避免跳转。
linux-3.12.6kernel raceftrace.c
static int ftrace_update_code(struct module *mod)
{
……
/*
* Do the initial record conversion from mcount jump
* to the NOP instructions.
*/
if (!ftrace_code_disable(mod, p))
break;
……
}

3、3运行时修改调用函数

linux-3.12.6kernel raceftrace.c
void ftrace_modify_all_code(int command)
{
int update = command & FTRACE_UPDATE_TRACE_FUNC;

/*
* If the ftrace_caller calls a ftrace_ops func directly,
* we need to make sure that it only traces functions it
* expects to trace. When doing the switch of functions,
* we need to update to the ftrace_ops_list_func first
* before the transition between old and new calls are set,
* as the ftrace_ops_list_func will check the ops hashes
* to make sure the ops are having the right functions
* traced.
*/
if (update)
ftrace_update_ftrace_func(ftrace_ops_list_func);
……
}
static inline void
__ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip,
struct ftrace_ops *ignored, struct pt_regs *regs)
{

……
do_for_each_ftrace_op(op, ftrace_ops_list) {
if (ftrace_ops_test(op, ip, regs))
op->func(ip, parent_ip, op, regs);
} while_for_each_ftrace_op(op);
……
}

3、4符号表的支持

这个其实相对比较简单，由链接器生成即可，运行时处理符号表代码在该文件中linux-3.12.6kernelkallsyms.c

六、输出格式的控制

1、输出格式控制

static enum print_line_t print_trace_fmt(struct trace_iterator *iter)
{
struct trace_seq *s = &iter->seq;
unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
struct trace_entry *entry;
struct trace_event *event;

entry = iter->ent;

test_cpu_buff_start(iter);

event = ftrace_find_event(entry->type);

if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
if (iter->iter_flags & TRACE_FILE_LAT_FMT) {
if (!trace_print_lat_context(iter))
goto partial;
} else {
if (!trace_print_context(iter))
goto partial;
}
}

if (event)
return event->funcs->trace(iter, sym_flags, event);

if (!trace_seq_printf(s, "Unknown type %d ", entry->type))
goto partial;

return TRACE_TYPE_HANDLED;
partial:
return TRACE_TYPE_PARTIAL_LINE;
}

这里意味着输出的进程字符串名称最长16字节
int trace_print_context(struct trace_iterator *iter)
{
struct trace_seq *s = &iter->seq;
struct trace_entry *entry = iter->ent;
unsigned long long t;
unsigned long secs, usec_rem;
char comm[TASK_COMM_LEN];
int ret;

trace_find_cmdline(entry->pid, comm);

ret = trace_seq_printf(s, "%16s-%-5d [%03d] ",
comm, entry->pid, iter->cpu);
……
}

2、系统配置

tsecer@harry: for f in /sys/kernel/debug/tracing/options/*; do echo $f; cat $f; done
/sys/kernel/debug/tracing/options/annotate
1
/sys/kernel/debug/tracing/options/bin
0
/sys/kernel/debug/tracing/options/block
0
/sys/kernel/debug/tracing/options/branch
0
/sys/kernel/debug/tracing/options/context-info
1
/sys/kernel/debug/tracing/options/disable_on_free
0
/sys/kernel/debug/tracing/options/ftrace_preempt
0
/sys/kernel/debug/tracing/options/function-trace
1
/sys/kernel/debug/tracing/options/graph-time
1
/sys/kernel/debug/tracing/options/hex
0
/sys/kernel/debug/tracing/options/irq-info
1
/sys/kernel/debug/tracing/options/latency-format
0
/sys/kernel/debug/tracing/options/markers
1
/sys/kernel/debug/tracing/options/overwrite
1
/sys/kernel/debug/tracing/options/print-parent
1
/sys/kernel/debug/tracing/options/printk-msg-only
0
/sys/kernel/debug/tracing/options/raw
0
/sys/kernel/debug/tracing/options/record-cmd
1
/sys/kernel/debug/tracing/options/sleep-time
1
/sys/kernel/debug/tracing/options/stacktrace
0
/sys/kernel/debug/tracing/options/sym-addr
0
/sys/kernel/debug/tracing/options/sym-offset
0
/sys/kernel/debug/tracing/options/sym-userobj
0
/sys/kernel/debug/tracing/options/test_nop_accept
0
/sys/kernel/debug/tracing/options/test_nop_refuse
0
/sys/kernel/debug/tracing/options/trace_printk
1
/sys/kernel/debug/tracing/options/userstacktrace
0
/sys/kernel/debug/tracing/options/verbose
0
tsecer@harry: