[PATCH 2/4] printk/lib: simulate slow consoles

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

*** FOR TESTING ***

Add a hack to delay console_drivers and simulate slow console(s). Doing
something like

preempt_disable();
while (...) {
printk();
delay();
}
preempt_enable();

is not correct. First, not every printk() ends up in console_unlock(),
second - delay should happen in console_unlock() if we want to test
printk() offloading, not outside of printk().

A simple test_printk.sh script to run the tests:

8<-----------------------------------------------------------------------------

TEST_CASE=1
_MAX_NUM_MESSAGES=1024
_CONSOLE_DRIVERS_DELAY=3500

sysctl kernel.watchdog_thresh=5

if [ "z$MAX_NUM_MESSAGES" != "z" ]; then
_MAX_NUM_MESSAGES=$MAX_NUM_MESSAGES
fi

if [ "z$CONSOLE_DRIVERS_DELAY" != "z" ]; then
_CONSOLE_DRIVERS_DELAY=$CONSOLE_DRIVERS_DELAY
fi

while [ $TEST_CASE -le 256 ]; do
echo 1 > /sys/kernel/debug/tracing/events/printk/offloading/enable
echo 1 > /sys/kernel/debug/tracing/trace

echo "Executing test $TEST_CASE"

modprobe test_printk max_num_messages=$_MAX_NUM_MESSAGES \
console_drivers_delay=$_CONSOLE_DRIVERS_DELAY \
tests_mask=$TEST_CASE

TEST_DONE=`cat /sys/test_printk/test_done`
while [ $TEST_DONE -ne 1 ]; do
sleep 1s;
let TEST_DONE=`cat /sys/test_printk/test_done`
done

rmmod test_printk

echo 0 > /sys/kernel/debug/tracing/events/printk/offloading/enable
cat /sys/kernel/debug/tracing/trace > /tmp/trace-test_case-$TEST_CASE

echo "Done... cat /tmp/trace-test_case-$TEST_CASE"
cat /tmp/trace-test_case-$TEST_CASE

echo "================================================================"

let TEST_CASE=$TEST_CASE*2
done

sysctl kernel.watchdog_thresh=10

8<-----------------------------------------------------------------------------

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
kernel/printk/printk.c | 15 +++++++++++++++
lib/test_printk.c | 10 +++++++++-
2 files changed, 24 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index d4e1abb36d3f..01626f2f42bd 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -75,6 +75,9 @@ int console_printk[4] = {
int oops_in_progress;
EXPORT_SYMBOL(oops_in_progress);

+int __CONSOLE_DRIVERS_DELAY__ = 0;
+EXPORT_SYMBOL(__CONSOLE_DRIVERS_DELAY__);
+
/*
* console_sem protects the console_drivers list, and also
* provides serialisation for access to the entire console
@@ -2584,6 +2587,18 @@ void console_unlock(void)

stop_critical_timings(); /* don't trace print latency */
call_console_drivers(ext_text, ext_len, text, len);
+
+ /* pretend we have a slow console */
+ {
+ volatile int num_chars, num_iter;
+
+ for (num_chars = 0; num_chars < len; num_chars++) {
+ num_iter = 0;
+ while (num_iter++ < __CONSOLE_DRIVERS_DELAY__)
+ cpu_relax();
+ }
+ }
+
start_critical_timings();

/* Must be called under printk_safe */
diff --git a/lib/test_printk.c b/lib/test_printk.c
index 9b01a03ef385..a030f1e61745 100644
--- a/lib/test_printk.c
+++ b/lib/test_printk.c
@@ -22,9 +22,10 @@
#define MAX_MESSAGES 4242
#define ALL_TESTS (~0UL)

+static int console_drivers_delay;
+
static unsigned long max_num_messages;
static unsigned long tests_mask;
-
static DEFINE_MUTEX(hog_mutex);

static struct hrtimer printk_timer;
@@ -148,6 +149,8 @@ static void test_noirq_printk_storm(void)
local_irq_restore(flags);
}

+extern int __CONSOLE_DRIVERS_DELAY__;
+
/*
* hogger printk() tests are based on Tejun Heo's code
*/
@@ -381,6 +384,8 @@ static int __init test_init(void)
if (!max_num_messages)
max_num_messages = MAX_MESSAGES;

+ __CONSOLE_DRIVERS_DELAY__ = console_drivers_delay;
+
if (!tests_mask)
tests_mask = ALL_TESTS;

@@ -409,6 +414,9 @@ 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_param(console_drivers_delay, int, 0);
+MODULE_PARM_DESC(console_drivers_delay, "Delay console drivers");
+
module_init(test_init);
module_exit(test_exit);

--
2.15.1