Kernel | Log中的速率限制

4,985 阅读6分钟

本文分析基于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进程ratelimit流程.png

我们首先来看看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.cbinder_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未设置时才有效,这一点在实际使用时需要注意。