[PATCH 1/4] printk/lib: add offloading trace events and test_printk module

[Sergey Senozhatsky <sergey.senozhatsky@gmail.com>]

*** FOR TESTING ***

Add console_unlock() offloading trace events and a new test_printk
testing module. test_printk does a number of offloading/handoff
tests - console_unlock() with preemption disabled, under rcu read
lock, with IRQs disabled, and so on.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/trace/events/printk.h |  26 +++
 kernel/printk/printk.c        |  17 ++
 lib/Kconfig.debug             |   3 +
 lib/Makefile                  |   1 +
 lib/test_printk.c             | 415 ++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 462 insertions(+)
 create mode 100644 lib/test_printk.c

diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
index 13d405b2fd8b..d883f5015cd2 100644
--- a/include/trace/events/printk.h
+++ b/include/trace/events/printk.h
@@ -31,6 +31,32 @@ TRACE_EVENT(console,
 
 	TP_printk("%s", __get_str(msg))
 );
+
+TRACE_EVENT(offloading,
+	TP_PROTO(char *ev,
+		char *key1,
+		unsigned long value1),
+
+	TP_ARGS(ev, key1, value1),
+
+	TP_STRUCT__entry(
+		__string(event, ev)
+
+		__string(__key1, key1)
+		__field(u64, __value1)
+	),
+
+	TP_fast_assign(
+		__assign_str(event, ev ? ev : " ? ");
+		__assign_str(__key1, key1 ? key1 : " -- ");
+		__entry->__value1 = value1;
+	),
+
+	TP_printk("%s %s:%llu",
+		__get_str(event),
+		__get_str(__key1),
+		__entry->__value1)
+);
 #endif /* _TRACE_PRINTK_H */
 
 /* This part must be outside protection */
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2395f18fec53..d4e1abb36d3f 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -662,6 +662,12 @@ should_handoff_printing(u64 printing_start_ts)
 
 	/* A new task - reset the counters. */
 	if (printing_task != current) {
+		trace_offloading_rcuidle("reset counters, prev_task data",
+				printing_task ?
+					printing_task->comm :
+					"NO_PREVIOUS_TASK",
+				this_cpu_read(printing_elapsed));
+
 		touch_printk_offloading_watchdog();
 		printing_task = current;
 		return DONT_HANDOFF;
@@ -694,6 +700,9 @@ should_handoff_printing(u64 printing_start_ts)
 		 * console_unlock(), it will have another full
 		 * `offloading_threshold()' time slice.
 		 */
+		trace_offloading_rcuidle("[!] forced up()",
+				"elapsed", this_cpu_read(printing_elapsed));
+
 		for_each_possible_cpu(cpu)
 			touch_printk_offloading_watchdog_on_cpu(cpu);
 		return PRINTK_KTHREAD_HANDOFF;
@@ -707,6 +716,10 @@ should_handoff_printing(u64 printing_start_ts)
 	cpumask_copy(printk_offload_cpus, cpu_online_mask);
 	cpumask_clear_cpu(smp_processor_id(), printk_offload_cpus);
 
+	trace_offloading_rcuidle("wake up kthread",
+			"elapsed",
+			this_cpu_read(printing_elapsed));
+
 	/*
 	 * If this_cpu is the one and only online CPU, then try to wake up
 	 * `printk_kthread' on it.
@@ -3173,6 +3186,10 @@ static int printk_kthread_func(void *data)
 
 		console_unlock();
 
+		trace_offloading_rcuidle("kthread released console_sem",
+				"PRINTK_PENDING_OUTPUT",
+				test_bit(PRINTK_PENDING_OUTPUT, &printk_pending));
+
 		/* We might have been blocked on console_sem */
 		if (kthread_should_park())
 			kthread_parkme();
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index c076234802d9..9e37988b0cfa 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -1948,6 +1948,9 @@ config TEST_DEBUG_VIRTUAL
 
 	  If unsure, say N.
 
+config TEST_PRINTK
+	tristate "Test printk() and console_unlock()"
+
 endmenu # runtime tests
 
 config MEMTEST
diff --git a/lib/Makefile b/lib/Makefile
index f495fd46fdc7..65667a03443d 100644
--- a/lib/Makefile
+++ b/lib/Makefile
@@ -66,6 +66,7 @@ obj-$(CONFIG_TEST_UUID) += test_uuid.o
 obj-$(CONFIG_TEST_PARMAN) += test_parman.o
 obj-$(CONFIG_TEST_KMOD) += test_kmod.o
 obj-$(CONFIG_TEST_DEBUG_VIRTUAL) += test_debug_virtual.o
+obj-$(CONFIG_TEST_PRINTK) += test_printk.o
 
 ifeq ($(CONFIG_DEBUG_KOBJECT),y)
 CFLAGS_kobject.o += -DDEBUG
diff --git a/lib/test_printk.c b/lib/test_printk.c
new file mode 100644
index 000000000000..9b01a03ef385
--- /dev/null
+++ b/lib/test_printk.c
@@ -0,0 +1,415 @@
+/*
+ * Test cases for printk() offloading [console_unlock()] functionality.
+ *
+ * Copyright (c) 2017 Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
+ *
+ * This file is released under the GPLv2.
+ */
+
+#include <linux/kernel.h>
+#include <linux/module.h>
+#include <linux/delay.h>
+#include <linux/sched.h>
+#include <linux/printk.h>
+#include <linux/console.h>
+#include <linux/mutex.h>
+#include <linux/workqueue.h>
+#include <linux/hrtimer.h>
+#include <linux/sysfs.h>
+#include <linux/device.h>
+#include <linux/rcupdate.h>
+
+#define MAX_MESSAGES	4242
+#define ALL_TESTS	(~0UL)
+
+static unsigned long max_num_messages;
+static unsigned long tests_mask;
+
+static DEFINE_MUTEX(hog_mutex);
+
+static struct hrtimer printk_timer;
+static ktime_t timer_interval;
+
+static int test_done;
+
+#define TEST_PREEMPT_CONSOLE_UNLOCK	(1 << 0)
+#define TEST_NONPREEMPT_CONSOLE_UNLOCK	(1 << 1)
+#define TEST_NOIRQ_CONSOLE_UNLOCK	(1 << 2)
+#define TEST_NONPREEMPT_PRINTK_STORM	(1 << 3)
+#define TEST_NOIRQ_PRINTK_STORM	(1 << 4)
+#define TEST_NONPREEMPT_PRINTK_HOGGER	(1 << 5)
+#define TEST_NOIRQ_PRINTK_HOGGER	(1 << 6)
+#define TEST_PREEMPT_PRINTK_EMERG_SYNC	(1 << 7)
+#define TEST_RCU_LOCK_CONSOLE_UNLOCK	(1 << 8)
+
+static void test_preemptible_console_unlock(void)
+{
+	unsigned long num_messages = 0;
+
+	pr_err("=== TEST %s\n", __func__);
+
+	console_lock();
+	while (num_messages++ < max_num_messages)
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+	console_unlock();
+}
+
+static void test_nonpreemptible_console_unlock(void)
+{
+	unsigned long num_messages = 0;
+
+	pr_err("=== TEST %s\n", __func__);
+
+	num_messages = 0;
+	console_lock();
+	while (num_messages++ < max_num_messages)
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+
+	preempt_disable();
+	console_unlock();
+	preempt_enable();
+}
+
+static void test_rculock_console_unlock(void)
+{
+	unsigned long num_messages = 0;
+
+	pr_err("=== TEST %s\n", __func__);
+
+	num_messages = 0;
+	console_lock();
+	while (num_messages++ < max_num_messages)
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+
+	rcu_read_lock();
+	console_unlock();
+	rcu_read_unlock();
+}
+
+static void test_noirq_console_unlock(void)
+{
+	unsigned long flags;
+	unsigned long num_messages = 0;
+
+	pr_err("=== TEST %s\n", __func__);
+
+	num_messages = 0;
+	console_lock();
+	while (num_messages++ < max_num_messages)
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+
+	local_irq_save(flags);
+	console_unlock();
+	local_irq_restore(flags);
+}
+
+static void test_nonpreemptible_printk_storm(void)
+{
+	unsigned long num_messages = 0;
+
+	pr_err("=== TEST %s\n", __func__);
+
+	num_messages = 0;
+	preempt_disable();
+	while (num_messages++ < max_num_messages)
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+	preempt_enable();
+}
+
+static void test_noirq_printk_storm(void)
+{
+	unsigned long flags;
+	unsigned long num_messages = 0;
+
+	pr_err("=== TEST %s\n", __func__);
+
+	num_messages = 0;
+	local_irq_save(flags);
+	while (num_messages++ < max_num_messages)
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+	local_irq_restore(flags);
+}
+
+/*
+ * hogger printk() tests are based on Tejun Heo's code
+ */
+static void nonpreemptible_printk_workfn(struct work_struct *work)
+{
+	unsigned long num_messages = 0;
+
+	while (num_messages++ < max_num_messages) {
+		mutex_lock(&hog_mutex);
+		mutex_unlock(&hog_mutex);
+		preempt_disable();
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+		preempt_enable();
+		cond_resched();
+	}
+}
+static DECLARE_WORK(nonpreemptible_printk_work, nonpreemptible_printk_workfn);
+
+static void hog_printk_workfn(struct work_struct *work)
+{
+	unsigned long num_messages = 0;
+
+	while (num_messages++ < max_num_messages) {
+		mutex_lock(&hog_mutex);
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+		mutex_unlock(&hog_mutex);
+		cond_resched();
+	}
+}
+static DECLARE_WORK(hog_printk_work, hog_printk_workfn);
+
+static void test_nonpreemptoble_printk_hogger(void)
+{
+	pr_err("=== TEST %s\n", __func__);
+
+	queue_work_on(0, system_wq, &nonpreemptible_printk_work);
+	msleep(42);
+	queue_work_on(1, system_wq, &hog_printk_work);
+
+	msleep(420);
+
+	flush_work(&nonpreemptible_printk_work);
+	flush_work(&hog_printk_work);
+
+	console_lock();
+	console_unlock();
+}
+
+static enum hrtimer_restart printk_timerfn(struct hrtimer *timer)
+{
+	static long iter = 1024;
+	unsigned long num_messages = 0;
+
+	if (!console_trylock()) {
+		while (num_messages++ < max_num_messages / 10) {
+			pr_info("=== %s [F] Append message %lu out of %lu\n",
+					__func__,
+					num_messages,
+					max_num_messages / 10);
+		}
+	} else {
+		while (num_messages++ < max_num_messages) {
+			pr_info("=== %s [S] Append message %lu out of %lu\n",
+					__func__,
+					num_messages,
+					max_num_messages);
+		}
+
+		console_unlock();
+	}
+
+	hrtimer_forward_now(&printk_timer, timer_interval);
+	if (--iter < 1)
+		return HRTIMER_NORESTART;
+	return HRTIMER_RESTART;
+}
+
+static void preempt_printk_workfn(struct work_struct *work)
+{
+	unsigned long num_messages = 0;
+
+	hrtimer_init(&printk_timer, CLOCK_MONOTONIC, HRTIMER_MODE_REL);
+	printk_timer.function = printk_timerfn;
+	timer_interval = ktime_set(0, 2 * NSEC_PER_MSEC);
+	hrtimer_start(&printk_timer, timer_interval, HRTIMER_MODE_REL);
+
+	while (num_messages++ < max_num_messages) {
+		preempt_disable();
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+		preempt_enable();
+	}
+}
+static DECLARE_WORK(preempt_printk_work, preempt_printk_workfn);
+
+static void test_noirq_printk_hogger(void)
+{
+	pr_err("=== TEST %s\n", __func__);
+
+	queue_work_on(0, system_wq, &preempt_printk_work);
+
+	msleep(420);
+
+	flush_work(&preempt_printk_work);
+	hrtimer_cancel(&printk_timer);
+
+	console_lock();
+	console_unlock();
+}
+
+static void test_preemptible_printk_emergency_sync(void)
+{
+	unsigned long num_messages = 0;
+
+	pr_err("=== TEST %s\n", __func__);
+
+	console_lock();
+	while (num_messages++ < max_num_messages)
+		pr_info("=== %s Append message %lu out of %lu\n",
+				__func__,
+				num_messages,
+				max_num_messages);
+	console_unlock();
+	msleep(840);
+
+	printk_emergency_begin_sync();
+	console_lock();
+	console_unlock();
+	printk_emergency_end_sync();
+}
+
+static void wait_for_test(const char *test_name)
+{
+	int done = 0;
+
+	do {
+		pr_err("... waiting for %s\n", test_name);
+		msleep(1000);
+
+		if (console_trylock()) {
+			console_unlock();
+			done = 1;
+		}
+	} while (done == 0);
+}
+
+static void run_tests(void)
+{
+	if (tests_mask & TEST_PREEMPT_CONSOLE_UNLOCK) {
+		test_preemptible_console_unlock();
+		wait_for_test("preemptible_console_unlock()");
+	}
+
+	if (tests_mask & TEST_NONPREEMPT_CONSOLE_UNLOCK) {
+		test_nonpreemptible_console_unlock();
+		wait_for_test("nonpreemptible_console_unlock()");
+	}
+
+	if (tests_mask & TEST_NOIRQ_CONSOLE_UNLOCK) {
+		test_noirq_console_unlock();
+		wait_for_test("noirq_console_unlock()");
+	}
+
+	if (tests_mask & TEST_NONPREEMPT_PRINTK_STORM) {
+		test_nonpreemptible_printk_storm();
+		wait_for_test("nonpreemptible_printk_storm()");
+	}
+
+	if (tests_mask & TEST_NOIRQ_PRINTK_STORM) {
+		test_noirq_printk_storm();
+		wait_for_test("noirq_printk_storm()");
+	}
+
+	if (tests_mask & TEST_NONPREEMPT_PRINTK_HOGGER) {
+		test_nonpreemptoble_printk_hogger();
+		wait_for_test("nonpreemptoble_printk_hogger()");
+	}
+
+	if (tests_mask & TEST_NOIRQ_PRINTK_HOGGER) {
+		test_noirq_printk_hogger();
+		wait_for_test("noirq_printk_hogger()");
+	}
+
+	if (tests_mask & TEST_PREEMPT_PRINTK_EMERG_SYNC) {
+		test_preemptible_printk_emergency_sync();
+		wait_for_test("preemptible_printk_emergency_sync()");
+	}
+
+	if (tests_mask & TEST_RCU_LOCK_CONSOLE_UNLOCK) {
+		test_rculock_console_unlock();
+		wait_for_test("rculock_console_unlock()");
+	}
+
+	test_done = 1;
+}
+
+static ssize_t test_done_show(struct device *dev,
+			      struct device_attribute *attr,
+			      char *buf)
+{
+	char *s = buf;
+
+	s += sprintf(s, "%d\n", test_done);
+	return (s - buf);
+}
+static DEVICE_ATTR_RO(test_done);
+
+static struct kobject *test_kobj;
+
+static struct attribute *test_attrs[] = {
+	&dev_attr_test_done.attr,
+	NULL,
+};
+
+static const struct attribute_group attr_group = {
+	.attrs = test_attrs,
+};
+
+static int __init test_init(void)
+{
+	int ret;
+
+	if (!max_num_messages)
+		max_num_messages = MAX_MESSAGES;
+
+	if (!tests_mask)
+		tests_mask = ALL_TESTS;
+
+	test_kobj = kobject_create_and_add("test_printk", NULL);
+	if (!test_kobj)
+		return -ENOMEM;
+	ret = sysfs_create_group(test_kobj, &attr_group);
+	if (ret) {
+		kobject_put(test_kobj);
+		return ret;
+	}
+
+	run_tests();
+	return 0;
+}
+
+static void __exit test_exit(void)
+{
+	sysfs_remove_group(test_kobj, &attr_group);
+	kobject_put(test_kobj);
+}
+
+module_param(max_num_messages, ulong, 0);
+MODULE_PARM_DESC(num_devices, "Number of messages to printk() in each test");
+
+module_param(tests_mask, ulong, 0);
+MODULE_PARM_DESC(tests_mask, "Which tests to run");
+
+module_init(test_init);
+module_exit(test_exit);
+
+MODULE_LICENSE("GPL");
-- 
2.15.1