本文分析基于Linux kernel 5.4
最近帮其他组的同事看了个有趣的问题，原因恰好和kernel log（又被称为kmsg/dmsg）中的速率限制有关。虽然知识点并不复杂，但鉴于自己寻找资料时的痛苦经历，还是决定将细节记录于此，以便后人查阅。
问题描述：子进程挂了以后，init进程并没有打印出它的死亡信息。按理来说，子进程一旦挂掉，init进程将会收到SIGCHLD信号（除非子进程中有线程呈现D状态）。在SIGCHLD的信号处理函数里，有如下代码，意味着无论如何都会打印log。然而在我们的案例中，这两句话都没有出现。
if (siginfo.si_code == CLD_EXITED) {
LOG(INFO) << name << " exited with status " << siginfo.si_status << wait_string;
} else {
LOG(INFO) << name << " received signal " << siginfo.si_status << wait_string;
}
我最初怀疑子进程并没有向init发送SIGCHLD信号。但查阅之后的ps信息，发现该子进程消失的无影无踪。这也就意味着子进程被父进程调用waitpid完美地回收了，否则它将呈现Zombie状态一直存活下去。这样看来，SIGCHLD已经发送，上述代码也被执行过了，可是log为什么凭空消失了呢？
根本的原因是kmsg对init输出的log进行了速率限制，每5秒钟最多可以输出10行log，多出的部分将被丢弃。在我们的问题中，子进程挂掉之前init进程的输出恰好达到了速率限制的上限，因此之后的输出都被丢弃了。以下是具体分析。
我们首先来看看init进程中的log到底去向何处。
在进程起始阶段，通过InitKernelLogging设置log的输出方式。
void InitKernelLogging(char** argv) {
SetFatalRebootTarget();
android::base::InitLogging(argv, &android::base::KernelLogger, InitAborter);
}
当有log输出时，最终会调用KernelLogLine进行打印。
static void KernelLogLine(const char* msg, int length, android::base::LogSeverity severity,
const char* tag) {
// clang-format off
static constexpr int kLogSeverityToKernelLogLevel[] = {
[android::base::VERBOSE] = 7, // KERN_DEBUG (there is no verbose kernel log
// level)
[android::base::DEBUG] = 7, // KERN_DEBUG
[android::base::INFO] = 6, // KERN_INFO
[android::base::WARNING] = 4, // KERN_WARNING
[android::base::ERROR] = 3, // KERN_ERROR
[android::base::FATAL_WITHOUT_ABORT] = 2, // KERN_CRIT
[android::base::FATAL] = 2, // KERN_CRIT
};
// clang-format on
static_assert(arraysize(kLogSeverityToKernelLogLevel) == android::base::FATAL + 1,
"Mismatch in size of kLogSeverityToKernelLogLevel and values in LogSeverity");
static int klog_fd = OpenKmsg(); //static代码，只运行一次
if (klog_fd == -1) return;
int level = kLogSeverityToKernelLogLevel[severity];
// The kernel's printk buffer is only 1024 bytes.
// TODO: should we automatically break up long lines into multiple lines?
// Or we could log but with something like "..." at the end?
char buf[1024] __attribute__((__uninitialized__));
size_t size = snprintf(buf, sizeof(buf), "<%d>%s: %.*s\n", level, tag, length, msg);
if (size > sizeof(buf)) {
size = snprintf(buf, sizeof(buf), "<%d>%s: %zu-byte message too long for printk\n",
level, tag, size);
}
iovec iov[1];
iov[0].iov_base = buf;
iov[0].iov_len = size;
TEMP_FAILURE_RETRY(writev(klog_fd, iov, 1));
}
其中有两个关键的部分，一个是OpenKmsg获取驱动文件的fd，另一个是writev往文件中写入log。OpenKmsg实质上就是打开/dev/kmsg驱动文件。
#if defined(__linux__)
static int OpenKmsg() {
#if defined(__ANDROID__)
// pick up 'file w /dev/kmsg' environment from daemon's init rc file
const auto val = getenv("ANDROID_FILE__dev_kmsg");
if (val != nullptr) {
int fd;
if (android::base::ParseInt(val, &fd, 0)) {
auto flags = fcntl(fd, F_GETFL);
if ((flags != -1) && ((flags & O_ACCMODE) == O_WRONLY)) return fd;
}
}
#endif
return TEMP_FAILURE_RETRY(open("/dev/kmsg", O_WRONLY | O_CLOEXEC));
}
#endif
接着去了解kmsg驱动中的具体操作。当上层通过open打开驱动时，实际上调用的是devkmsg_open。当上层通过writev往驱动中写入数据时，实际上调用的是devkmsg_write。
const struct file_operations kmsg_fops = {
.open = devkmsg_open,
.read = devkmsg_read,
.write_iter = devkmsg_write,
.llseek = devkmsg_llseek,
.poll = devkmsg_poll,
.release = devkmsg_release,
};
在devkmsg_open中，变量user需要重点关注。通过将其存入file->private_data，从而保证了两件事情。一是每个打开/dev/kmsg的进程都会有一个独立的devkmsg_user对象，二是这个对象在驱动文件的生命周期内一直存在。
static int devkmsg_open(struct inode *inode, struct file *file)
{
struct devkmsg_user *user;
...
user = kmalloc(sizeof(struct devkmsg_user), GFP_KERNEL);
if (!user)
return -ENOMEM;
ratelimit_default_init(&user->rs);
...
file->private_data = user;
return 0;
}
user中有一个rs对象，记录的正是速率限制的具体配置，它的初始化由ratelimit_default_init完成。
struct devkmsg_user {
u64 seq;
u32 idx;
struct ratelimit_state rs;
struct mutex lock;
char buf[CONSOLE_EXT_LOG_MAX];
};
ratelimit_default_init会将rs的interval字段设置为默认的5HZ，将burst字段设置为默认的10，刚好对应了我们上文中提到的每5秒钟最多可以输出10行log。
#define DEFAULT_RATELIMIT_INTERVAL (5 * HZ)
#define DEFAULT_RATELIMIT_BURST 10
static inline void ratelimit_default_init(struct ratelimit_state *rs)
{
return ratelimit_state_init(rs, DEFAULT_RATELIMIT_INTERVAL,
DEFAULT_RATELIMIT_BURST);
}
static inline void ratelimit_state_init(struct ratelimit_state *rs,
int interval, int burst)
{
memset(rs, 0, sizeof(*rs));
raw_spin_lock_init(&rs->lock);
rs->interval = interval;
rs->burst = burst;
}
到这里为止，我们介绍的还只是配置部分。那么速率限制的配置为何会生效呢？这就要接着去看writev的写log动作了。
/* Keep both the 'on' and 'off' bits clear, i.e. ratelimit by default: */
#define DEVKMSG_LOG_MASK_DEFAULT 0
static unsigned int __read_mostly devkmsg_log = DEVKMSG_LOG_MASK_DEFAULT;
static ssize_t devkmsg_write(struct kiocb *iocb, struct iov_iter *from)
{
...
/* Ratelimit when not explicitly enabled. */
if (!(devkmsg_log & DEVKMSG_LOG_MASK_ON)) {
if (!___ratelimit(&user->rs, current->comm))
return ret;
}
...
具体输出的代码
}
devkmsg_log默认为0，因此会进行__ratelimit的判断。__ratelimit中的代码只判断一件事：5秒内该函数是否被调用了超过10次。不过请注意，这个调用是和user中的rs对象绑定在一起的。也就是说，不同进程的统计分开计算，因为他们操作的rs对象是独立的。因此，init进程的速率限定只对本进程有效。
虽然devkmsg_log默认为0，但是kernel开放了动态修改它的权限，以便在某些时刻关掉用户空间往/dev/kmsg写入log时的速率限制。这种动态修改的方式将在文末提及。
/*
* __ratelimit - rate limiting
* @rs: ratelimit_state data
* @func: name of calling function
*
* This enforces a rate limit: not more than @rs->burst callbacks
* in every @rs->interval
*
* RETURNS:
* 0 means callbacks will be suppressed.
* 1 means go ahead and do it.
*/
int ___ratelimit(struct ratelimit_state *rs, const char *func)
{
unsigned long flags;
int ret;
if (!rs->interval)
return 1;
/*
* If we contend on this state's lock then almost
* by definition we are too busy to print a message,
* in addition to the one that will be printed by
* the entity that is holding the lock already:
*/
if (!raw_spin_trylock_irqsave(&rs->lock, flags))
return 0;
if (!rs->begin)
rs->begin = jiffies;
if (time_is_before_jiffies(rs->begin + rs->interval)) {
if (rs->missed) {
if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
printk_deferred(KERN_WARNING
"%s: %d callbacks suppressed\n",
func, rs->missed);
rs->missed = 0;
}
}
rs->begin = jiffies;
rs->printed = 0;
}
if (rs->burst && rs->burst > rs->printed) {
rs->printed++;
ret = 1;
} else {
rs->missed++;
ret = 0;
}
raw_spin_unlock_irqrestore(&rs->lock, flags);
return ret;
}
其实内核中很多其他模块也都采用了这种速率限定的打印模式，譬如binder。
Binder中有两个重要的文件，一个是binder.c，另一个是binder_alloc.c。它们分别在自己的文件头部进行了如下定义。pr_info_ratelimited最终也是对printk做速率限制，而且其采用的配置同样是5秒10行。不过它里面的ratelimit_state是局部静态变量，因此意味着速率限制的对象是每一句单独的打印。这一点和init针对进程整体进行限制是完全不同的。
假设有多个进程同时调用binder.c的binder_transaction代码，而且函数内有两处调用pr_info_ratelimited。那么在5秒内，每一处的pr_info_ratelimited都受到10行的限制，这些调用可能来自不同的进程。而两处不同的pr_info_ratelimited调用则互不干扰。
[printk_ratelimited]
/*
* ratelimited messages with local ratelimit_state,
* no local ratelimit_state used in the !PRINTK case
*/
#ifdef CONFIG_PRINTK
#define printk_ratelimited(fmt, ...) \
({ \
static DEFINE_RATELIMIT_STATE(_rs, \
DEFAULT_RATELIMIT_INTERVAL, \
DEFAULT_RATELIMIT_BURST); \
\
if (__ratelimit(&_rs)) \
printk(fmt, ##__VA_ARGS__); \
})
[binder.c]
#define binder_debug(mask, x...) \
do { \
if (binder_debug_mask & mask) \
pr_info_ratelimited(x); \
} while (0)
#define binder_user_error(x...) \
do { \
if (binder_debug_mask & BINDER_DEBUG_USER_ERROR) \
pr_info_ratelimited(x); \
if (binder_stop_on_user_error) \
binder_stop_on_user_error = 2; \
} while (0)
[binder_alloc.c]
#define binder_alloc_debug(mask, x...) \
do { \
if (binder_alloc_debug_mask & mask) \
pr_info_ratelimited(x); \
} while (0)
此外还有一个误解需要澄清。
网上的很多资料提到了两个sysctl节点：/proc/sys/kernel/printk_ratelimit_burst和/proc/sys/kernel/printk_ratelimit。
$ cat /proc/sys/kernel/printk_ratelimit_burst
10
$ cat /proc/sys/kernel/printk_ratelimit
5
看到这两个节点后，我们会本能地以为速率限制可以动态调节，直接往节点中echo一个新值不就可以了么。但真的会有效果么？答案是否定的。
{
.procname = "printk_ratelimit",
.data = &printk_ratelimit_state.interval,
.maxlen = sizeof(int),
.mode = 0644,
.proc_handler = proc_dointvec_jiffies,
},
{
.procname = "printk_ratelimit_burst",
.data = &printk_ratelimit_state.burst,
.maxlen = sizeof(int),
.mode = 0644,
.proc_handler = proc_dointvec,
},
原因是节点的值最终会反映到全局变量printk_ratelimit_state中，而不论是init进程，还是pr_info_ratelimited，它们都会创建自己的ratelimit_state对象，而不会使用这个全局的变量。因此printk_ratelimit_state的修改并不会影响到init进程和pr_info_ratelimited的速率限制。
#define DEFINE_RATELIMIT_STATE(name, interval_init, burst_init) \
\
struct ratelimit_state name = \
RATELIMIT_STATE_INIT(name, interval_init, burst_init) \
DEFINE_RATELIMIT_STATE(printk_ratelimit_state, 5 * HZ, 10);
如果想要修改init进程和pr_info_ratelimited文件的速率限制，最直接的方式是改掉代码中以下两个变量的值，当DEFAULT_RATELIMIT_INTERVAL修改为0时，意味着关闭速率限制。但这种方式需要重新编译，因此使用起来并不方便。
#define DEFAULT_RATELIMIT_INTERVAL (5 * HZ)
#define DEFAULT_RATELIMIT_BURST 10
如果仅仅想修改init进程（用户空间）的速率限制，那么还可以使用Kernel开放的动态修改的权限。
这里有两种方式可以关闭速率限制，一种是修改kernel command line，另一种是修改sysctl的节点值。具体的原理较为简单，相信阅读完链接的代码大家都能弄懂。
1.修改kernel command line, 这种方式需要重启手机。以下是这个参数的相关介绍。
Add a "printk.devkmsg" kernel command line parameter which controls how
userspace writes into /dev/kmsg. It has three options:
* ratelimit - ratelimit logging from userspace.
* on - unlimited logging from userspace
* off - logging from userspace gets ignored
让手机进入fastboot模式可以在重启间隙修改这个值，如下操作。
fastboot --cmdline "其他参数 printk.devkmsg=on" boot boot.img
2.adb shell进入手机，然后执行"echo on > /proc/sys/kernel/printk_devkmsg"。这种方式可以在运行时动态设置，最为方便。
Furthermore, we can control the logging from a lower priority sysctl
interface - kernel.printk_devkmsg.
That interface will succeed only if printk.devkmsg *hasn't* been
supplied on the command line. If it has, then printk.devkmsg is a
one-time setting which remains for the duration of the system lifetime.
This "locking" of the setting is to prevent userspace from changing the
logging on us through sysctl(2).
通过sysctl设置的方式只在printk.devkmsg的kernel command未设置时才有效，这一点在实际使用时需要注意。
