内核日志系统与调试输出¶

本节目标

了解课程参考内核中新增的轻量级日志接口。
学会使用 LOG_DEBUG、LOG_INFO、LOG_WARN、LOG_ERROR 为关键路径添加调试输出。
理解 LOG_LEVEL 的编译期开关，以及为什么它几乎不会引入额外运行时开销。
知道哪些位置适合打日志，哪些位置需要谨慎。

前置条件

建议先完成实验0：内核编译运行与 GDB 调试，并对 trap / syscall 的基本执行路径有初步认识。

1 为什么要给内核加日志¶

在用户态程序中，调试手段往往比较直接：可以打印变量，也可以用 gdb 跟踪单个进程。但在操作系统实验里，很多问题发生在更底层的位置，例如：

刚进入 trap 入口，用户态还没有机会打印任何内容；
某个系统调用参数错误，流程在内核里直接返回 -1；
页分配、页表映射或调度路径中，错误只在极少数分支上出现；
内核尚未完全跑稳时，单纯依赖断点调试成本较高。

因此，一个轻量级、可按级别过滤、能自动带上下文信息的日志系统会非常有用。它不能替代 gdb，但很适合回答下面这类问题：

“流程到底有没有走到这里？”
“当前是哪个 hart、哪个进程在执行这段代码？”
“异常分支是被谁触发的？”

建议把日志当作定位工具，而不是最终功能

写日志的目标是缩小排查范围，而不是长期依赖大量输出维持系统可观测性。问题定位完成后，应及时删除、下调级别，或将日志收敛到更少的关键点。

2 当前参考代码已经提供了什么¶

NexOS 中已经加入了一套最小可用的日志接口。按功能看，核心文件如下：

路径	作用
`kernel/include/log.h`	定义日志级别常量、核心宏 `_LOG_IMPL` 和四个对外接口宏。
`Makefile`	通过 `LOG_LEVEL ?= 0` 和 `-DLOG_LEVEL=$(LOG_LEVEL)` 把日志级别传给编译器。
`kernel/core/kalloc.c`	在 `kalloc()` 中给出 `LOG_INFO` / `LOG_ERROR` 示例。
`kernel/core/trap.c`	在 `trap_init()` 中给出 `LOG_INFO` 示例，并保留了可选的 `LOG_DEBUG` 埋点。
`kernel/core/syscall.c`	在未知系统调用分支中给出 `LOG_WARN` 示例。
`user/logtest.c`	提供一个用户态触发程序，用于观察日志输出。

从接口形式上看，使用方式非常简单：

#include "log.h"

void demo(void) {
    LOG_DEBUG("entered demo()");
    LOG_INFO("mapping va=%p", va);
    LOG_WARN("unexpected state=%d", state);
    LOG_ERROR("allocation failed");
}

3 这套日志宏会输出什么¶

日志宏最终会把以下上下文拼进输出前缀中：

日志级别：DEBUG / INFO / WARN / ERROR
当前 hart 编号：通过 cpuid() 获取
当前进程 pid：通过 myproc() 获取
文件名与行号：通过 __FILE__ 和 __LINE__ 获取

格式示意如下：

[WARN] [CPU 0] [PID 4] (kernel/core/syscall.c:651) unknown syscall 999

其中每一部分的含义分别是：

[WARN]：当前日志级别；
[CPU 0]：当前运行在第 0 个 hart；
[PID 4]：当前进程号为 4；
(kernel/core/syscall.c:651)：日志调用点位于该文件的该行；
unknown syscall 999：你在日志宏中写入的正文。

为什么有时会看到 PID -

在内核早期启动阶段，或者某些还没有绑定到当前进程上下文的位置，myproc() 可能返回空指针。此时日志系统会打印 PID -，这表示“当前没有稳定的进程上下文”，并不一定代表出现了错误。

4 最基本的使用方法¶

4.1 在代码中引入头文件¶

如果某个 .c 文件想使用日志宏，需要先包含：

#include "log.h"

通常建议把它和 defs.h、proc.h、riscv.h 等内核头文件一起放在文件头部。

4.2 选择合适的日志级别¶

一个常见的经验是：

LOG_DEBUG：临时排查时使用，输出最细；
LOG_INFO：描述正常但关键的流程节点；
LOG_WARN：流程还能继续，但已经出现可疑现象；
LOG_ERROR：出现明显错误，通常需要立即检查。

例如，在系统调用入口中记录异常编号：

if (num > 0 && num < (int)(sizeof(syscalls) / sizeof(syscalls[0])) && syscalls[num]) {
    p->trapframe->a0 = syscalls[num]();
} else {
    LOG_WARN("unknown syscall %d", num);
    p->trapframe->a0 = (uint64)-1;
}

4.3 注意 `printf()` 只支持一个精简子集¶

日志宏底层仍然调用内核自己的 printf()，而不是 Linux 用户态常见的 glibc printf()。因此你应当把它视为一个教学版、轻量级格式化输出函数。

当前实现中，常用的格式包括：

%d / %i
%u
%x / %X
%o
%p
%s
%c
%%
l / ll 长度修饰

但它不保证支持完整的宽度、精度、对齐控制，也不支持浮点格式。因此写日志时应尽量保持简单，优先打印：整数、地址、短字符串和错误码。

不要照搬用户态 printf 习惯

如果你在日志里使用过于复杂的格式字符串，或者假设它具备完整 glibc 语义，输出结果可能并不符合预期。写内核日志时，最稳妥的做法是：少格式化、少花样、只打印最关键的信息。

5 `LOG_LEVEL`：编译期控制日志开关¶

参考代码把日志级别设计成了编译期选项。也就是说，是否保留某一类日志，不是在运行时 if (...) 判断，而是在预处理阶段直接决定宏展开结果。

在 log.h 中，不同级别的宏大致是这样工作的：

如果当前 LOG_LEVEL 允许该级别输出，宏会展开成真正的 printf(...)；
如果不允许，宏会直接展开成 ((void)0)。

这样做的好处是：被关闭的日志在编译后几乎没有运行时成本。

5.1 日志级别含义¶

`LOG_LEVEL` 值	含义	会输出哪些日志
`0`	`DEBUG`	全部输出
`1`	`INFO`	`INFO`、`WARN`、`ERROR`
`2`	`WARN`	`WARN`、`ERROR`
`3`	`ERROR`	仅 `ERROR`
`4`	`NONE`	关闭全部日志

5.2 如何在编译时指定级别¶

最直接的方式是在 make 命令行上传参：

make clean
make qemu LOG_LEVEL=2

如果你只想重新编译内核，也可以先执行：

make LOG_LEVEL=1

如果你修改了用户态测试程序（例如 user/logtest.c），还需要重新打包文件系统镜像：

make fsimg

课程实验里推荐从 LOG_LEVEL=2 开始

WARN 级别通常足够观察异常路径，同时又不会像 DEBUG / INFO 那样产生过多输出。只有当你明确需要跟踪更细的执行链路时，再临时切到 0 或 1。

6 如何验证这套日志系统确实生效¶

参考仓库已经提供了一个专门的用户态程序 logtest。它会触发以下几类路径：

fork()：触发进程复制与内存分配相关流程；
sbrk()：触发用户地址空间增长；
手工把寄存器 a7 置为 999 后执行 ecall：触发“未知系统调用”路径。

推荐按下面步骤做一次最小验证：

make clean
make qemu LOG_LEVEL=2

进入系统 shell 后运行：

logtest

在 LOG_LEVEL=2 下，你至少应当能观察到类似下面的 WARN 级别输出：

$ logtest
--- Log Trigger Test Starting ---
[WARN] [CPU 0] [PID 4] (kernel/core/syscall.c:651) unknown syscall 999
--- Log Trigger Test Finished ---

如果你把级别改成 LOG_LEVEL=1，通常还会看到更多 INFO 级别日志，例如 trap_init() 或页分配路径中的输出。

7 为什么说它“轻量”但仍然很有用¶

这套实现并没有引入复杂的数据结构，也没有专门的日志缓冲区。它的核心思想其实非常朴素：

用宏统一日志接口；
在宏里自动补齐上下文；
在编译期裁剪不需要的日志；
最终仍通过内核串口输出到 QEMU 控制台。

这使它特别适合课程实验中的几个场景：

快速确认控制流有没有走到某个关键分支；
观察 trap / syscall / 内存管理等路径上的局部行为；
为实验报告保留最小可复现的调试证据；
在 gdb 之前，先用低成本方法缩小问题范围。

日志和 gdb 的分工不同

日志更擅长回答“有没有到这里”“当前大概处于什么状态”；gdb 更擅长回答“具体哪一条指令、哪个寄存器、哪个内存地址出了问题”。两者通常是配合使用，而不是二选一。

8 哪些地方适合打日志，哪些地方要谨慎¶

8.1 比较适合打日志的位置¶

异常分支、错误返回分支；
系统调用分发入口与关键失败点；
页表建立、地址空间扩张、资源分配失败等关键事件；
你刚刚修改过、最怀疑出错的控制路径。

8.2 需要特别谨慎的位置¶

页分配器、调度器、trap / 中断入口等高频或敏感路径；
持有自旋锁的临界区；
中断关闭期间；
早期启动阶段，此时很多子系统尚未完全稳定。

高频路径里不要长期保留大量 INFO / DEBUG 日志

例如页分配器 kalloc() 这种函数，调用频率非常高。如果长期保留细粒度日志，不仅会让输出极其嘈杂，也可能放大串口输出和锁竞争带来的副作用。参考代码中这类埋点更适合作为教学示例或临时调试手段，而不是默认常驻配置。

8.3 一个实用的工作流¶

建议按下面顺序使用日志：

先只在最怀疑的 1~2 个位置加日志；
先用 LOG_WARN / LOG_ERROR 看异常路径；
如果信息不够，再临时加 LOG_INFO / LOG_DEBUG；
定位完成后，及时删掉或下调日志级别；
对关键结论，再用 gdb 或最小测试程序做一次交叉验证。

9 练习题¶

练习 1：打开系统调用调试日志

kernel/core/syscall.c 中已经保留了一条被注释掉的 LOG_DEBUG("syscall %d executing", num);。请尝试取消注释，并分别用 LOG_LEVEL=0 与 LOG_LEVEL=2 启动系统，对比执行 hello、pid、logtest 时的输出差异。

练习 2：为异常 trap 增加一条日志

在 kernel/core/trap.c 中，为非 SCAUSE_ECALL_U 的异常路径增加一条 LOG_ERROR，打印 scause、sepc 和 stval。思考：为什么这类日志更适合使用 ERROR 而不是 DEBUG？

练习 3：比较日志与 gdb 的作用

任选一个你在实验中遇到过的问题，分别尝试用“加日志”和“打断点”两种方式定位，并总结：哪种方式更快？哪种方式更精确？它们各自适合什么场景？