阅读 1380

Kernel | Log中的速率限制

本文分析基于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未设置时才有效,这一点在实际使用时需要注意。

文章分类
Android
文章标签