printk_defered打印详细解析

在linux源码中有一种特殊的打印函数，用户sched_flow过程中，此函数就是printk_defered，pirntk_defered源码如下所示：

int printk_deferred(const char *fmt, ...)
{
	va_list args;
	int r;
	va_start(args, fmt);
	r = vprintk_deferred(fmt, args);
	va_end(args);
	return r;
}

可以看到printk_defered函数主要调用了vprintk_deferred这个API来打印

int vprintk_deferred(const char *fmt, va_list args)
{
	int r;

	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
	defer_console_output();

	return r;
}

可以看到vprintk_deferred主要调用两个函数：vprintk_emit和defer_console_output。下面主要分析这两个API的作用

asmlinkage int vprintk_emit(int facility, int level,
			    const char *dict, size_t dictlen,
			    const char *fmt, va_list args)
{
	int printed_len;
	bool in_sched = false;
	unsigned long flags;
#ifdef CONFIG_PRINTK_MT_PREFIX
	/* save the status of irqs_disabled() */
	isIrqsDisabled = irqs_disabled();
#endif
	if (level == LOGLEVEL_SCHED) {
		level = LOGLEVEL_DEFAULT;
		in_sched = true;
	}

	boot_delay_msec(level);
	printk_delay();

	/* This stops the holder of console_sem just where we want him */
	logbuf_lock_irqsave(flags);
	printed_len = vprintk_store(facility, level, dict, dictlen, fmt, args);
	logbuf_unlock_irqrestore(flags);

	/* If called from the scheduler, we can not call up(). */
	if (!in_sched && cpu_online(raw_smp_processor_id())) {
		/*
		 * Try to acquire and then immediately release the console
		 * semaphore.  The release will print out buffers and wake up
		 * /dev/kmsg and syslog() users.
		 */
		if (console_trylock_spinning())
			console_unlock();
	}

	return printed_len;
}

可以看到在vprintk_deferred中在调用vprintk_emit时vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args)，有传递参数

LOGLEVEL_SCHED，在vprintk_emit函数中有对level值的判断，if (level == LOGLEVEL_SCHED)，如果level值为LOGLEVEL_SCHED，那么将设置flag:in_sched为true，接下来，将本次log内容通过vprintk_store函数存入printk_buffer。再继续向下看，因为in_sched值为true，那么！in_sched值为false，因此不会执行console_unlock函数进行log打印。

再继续向下分析defer_console_output函数

void defer_console_output(void)
{
	preempt_disable();
	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
	preempt_enable();
}

在函数defer_console_output函数中主要执行以下功能：

1.关闭抢占

2.将printk_pending进行赋值   printk_pending|=PRINTK_PENDING_OUTPUT

3.将当前运行CPU的irq work:wake_up_klogd_work加入woke_queue

4.开启抢占

接下来看下printk_pending变量的赋值过程

首先printk_pendng是一个per_cpu变量

static DEFINE_PER_CPU(int, printk_pending);

数据类型为int类型

#define __this_cpu_or(pcp, val)						\
({									\
	__this_cpu_preempt_check("or");					\
	raw_cpu_or(pcp, val);						\
})

__this_cpu_preemt_check("or")主要是检测or操作抢占情况，判断当前是否有其他进程抢占

这里主要分析raw_cpu_or赋值操作

#define raw_cpu_or(pcp, val)		__pcpu_size_call(raw_cpu_or_, pcp, val)

#define __pcpu_size_call(stem, variable, ...)				\
do {									\
	__verify_pcpu_ptr(&(variable));					\
	switch(sizeof(variable)) {					\
		case 1: stem##1(variable, __VA_ARGS__);break;		\
		case 2: stem##2(variable, __VA_ARGS__);break;		\
		case 4: stem##4(variable, __VA_ARGS__);break;		\
		case 8: stem##8(variable, __VA_ARGS__);break;		\
		default: 						\
			__bad_size_call_parameter();break;		\
	}								\
} while (0)

__pcpu_size_call(raw_cpu_or_, pcp, val)传入变量为raw_cpu_or_,printk_pending,PRINTK_PENDING_OUTPUT

将此define展开，因为printk_pending 为int类型，因此sizeof(printk_pending)=4

也就是ras_cpu_or_4(printk_pending,PRINTK_PENDING_OUTPUT)

#define raw_cpu_or_4(pcp, val)		raw_cpu_generic_to_op(pcp, val, |=)

#define raw_cpu_generic_to_op(pcp, val, op)				\
do {									\
	*raw_cpu_ptr(&(pcp)) op val;					\
} while (0)

这里raw_cpu_ptr(&(pcp))主要是获取当前cpu的per_cpu中printk_pending变量的线性地址，相当于

* this_cpu_printk_pending |= PRINTK_PENDING_OUTPUT

接下来再来看下irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));

static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
	.func = wake_up_klogd_work_func,
	.flags = IRQ_WORK_LAZY,
};

可以看到此处定义了一个per_cpu变量，其数据类型是struct irq_work，变量名为wake_up_klogd_work，它的回调函数.func指向wake_up_klogd_work_func，它的flag标志位.flags为IRQ_WORK_LAZY

/* Enqueue the irq work @work on the current CPU */
bool irq_work_queue(struct irq_work *work)
{
	/* Only queue if not already pending */
	if (!irq_work_claim(work))
		return false;

	/* Queue the entry and raise the IPI if needed. */
	preempt_disable();

	/* If the work is "lazy", handle it from next tick if any */
	if (work->flags & IRQ_WORK_LAZY) {
		if (llist_add(&work->llnode, this_cpu_ptr(&lazy_list)) &&
		    tick_nohz_tick_stopped())
			arch_irq_work_raise();
	} else {
		if (llist_add(&work->llnode, this_cpu_ptr(&raised_list)))
			arch_irq_work_raise();
	}

	preempt_enable();

	return true;
}
EXPORT_SYMBOL_GPL(irq_work_queue);

从这段代码可以看出，首先声明了此irq_work，将其加入irq_work_quene,接着判断work_flags的值，如果为IRQ_WORK_LAZY，那么等待tick下一次到来再处理，否则立刻处理

#ifdef CONFIG_IRQ_WORK
void arch_irq_work_raise(void)
{
	if (arch_irq_work_has_interrupt())
		send_IPI_single(smp_processor_id(), MSG_TAG_IRQ_WORK);
}
#endif

处理内容为如果当前irq_work中断已经到来，便发送ipi信号进行work处理

此irq_work：wake_up_klogd_work的处理内容为

static void wake_up_klogd_work_func(struct irq_work *irq_work)
{
	int pending = __this_cpu_xchg(printk_pending, 0);

	if (pending & PRINTK_PENDING_OUTPUT) {
		/* If trylock fails, someone else is doing the printing */
		if (console_trylock())
			console_unlock();
	}

	if (pending & PRINTK_PENDING_WAKEUP)
		wake_up_interruptible(&log_wait);
}

控制printk console进行log打印