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

Sergey Senozhatsky
2017-12-04T13:55:25Z

*** 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