*** 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 <[email protected]> --- 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 <[email protected]> + * + * 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
