Message-ID: <ZsdoD6PomBRsB-ow@debarbos-thinkpadt14sgen2i.remote.csb>
Date: Thu, 22 Aug 2024 12:32:15 -0400
From: Derek Barbosa <debarbos@...hat.com>
To: pmaldek@...e.com
Cc: williams@...hat.com, john.ogness@...utronix.de, tglx@...utronix.de,
	linux-rt-users@...r.kernel.org, linux-kernel@...r.kernel.org
Subject: A Comparison of printk between upstream and linux-rt-devel

Hi,

TLDR: plain, vanilla 6.11.0-0.rc3 is slower on flush and 
does not print traces in panic/crash context consistently.


The purpose of this email is to share some findings with regards to the latest
available printk changes, in comparison to what is currently available in the
"mainline" upstream torvalds tree.

Specifically, there was concern regarding flushing, flushing speed, and ensuring
that viable information can be displayed to the user in critical context. This
email also assumes that [0] (and the rest of the thread) has been previously read.

Moving on, I've been testing the printk code present in the linux-rt-devel tree
for some time, and have been honing in on comparing behaviors/interactions
between a stock, regular kernel and the linux-rt-devel tree. 

The kernels in question are the following:

1. a stock torvalds kernel, 6.11.0-0.rc3 
2. a linux-rt-devel kernel, 6.11.0-0.rc3-rt2, which has the "newer" printk code

As a note, 6.11.0-0.rc3-rt2 DOES NOT HAVE CONFIG_PREEMPT_RT ENABLED.

I will refer to these kernels as "new printk" vs "stock printk".

I've also attached the configs for these kernels.

Both of these kernels were put through a series of tests, most of which
involve a particular kthread-noise.c reproducer, whose makefile code && makefile is
readily available here:
[printktorture](https://gitlab.com/debarbos/printktorture)

I will also attach the script used to "monitor" the console output via
conserver, and the *very imprecise* timings used for data collection.

The kthread-noise kernel module does nothing too fancy. It is a kernel module
that spams-printk with 4 worker threads, sleeping for a jiffy between each
printk.

On the aforementioned configs, where CONFIG_HZ=1000, this results in a fair
amount of printk's-per-second. My guesswork-napkin-math puts this at about
1msg/msec, meaning we're printk-ing at about (1msg/msec * 1000 msecs per second *
4 workers) 4000 messages a second. 

Additionally, all tests were performed on the following system:

System: Dell PowerEdge R7525 
CPU: AMD EPYC 7252 8-Core Processor (nproc = 16)
Memory: 16384 MB memory 
Console: 8250 UART Serial Console at 115200 baud (ttyS0 monitored via conserver)

Please note that these tests were performed in the very *opposite* of a clean
room. These are mainly rounded figures and estimations used to derive educated
"guesses" on the comparisons of the behaviors between these two kernels, and
should be used as a *starting point* for any investigation *at best*.

Anyway, onto the tests. For the sake of this email, I will include the 4 most recent
tests that I've ran on both kernels.

---- BEGIN TEST SUMMARIES ----

--- Test 1: John Ogness' Console Blast. ---

This test uses a script which calls itself to create a pinned process for each CPU. Those
child processes will run in infinite loops of show-task-states via
/proc/sysrq-trigger. This generates lots of contention on the console. After
some time, we use the sysrq-trigger to crash the machine. 

The success condition would be to be able to view the full crash backtrace via
the serial console. 

For each of the kernels, 10 back-to-back trials were performed. 

In the 6.11.0-0.rc3 stock kernel, we did *not* observe a trace on crash. There were various
other traces scattered/nested throughout the show-task-state noise, but no full
crash backtrace. At times, there were upwards of 13k dropped messages.

In the 6.11.0-0.rc3-rt2 "new printk" kernel, we observed the success condition on each run. At
the "end" of the test (the crash), the full call trace was visible and presented
to us via the serial console.

--- Test 2: Printk Spammer ---

This test uses the aforementioned kthread-noise module to flood messages to the
printk buffers. We insert the module, wait about 30 seconds to ensure we fully
saturate the buffers, and trigger an NMI-induced panic via the OpenIPMI drivers.

The succcess condition would be to be able to view the full panic && NMI traces
via the serial console.

For each kernel, 10 back-to-back trials were performed.

In the 6.11.0-0.rc3 stock kernel, we do not see any dropped messages, but we also do not
witness any traces being printed out to the serial console in this NMI/panic
context.

In the 6.11.0-0.rc3-rt2 "new printk" kernel, we observed the success condition at each run. After
fully saturating the console buffers, we can see anywhere from 1-20 dropped
messages at a time. Once we hit our NMI-induced-panic, we flush the remaining
messages, and are able to view a full trace.

--- Test 3: Pending Message Speed ---

This test also uses the kthread-noise module. Here, we simply insert the kernel
module, wait 30 seconds, then remove the kernel module. 

There is no clear success condition for this test case, we are simply measuring
the average amount of time it takes to print any pending messages after `rmmod`
is invoked.

We keep track of when the module was inserted, note the elapsed time at module
removal, and note the elapsed time when pending messages are printed, and the
worker-completion confirmation message is printed.

In summary, invoking rmmod while the system is bogged and the consoles are
hammered doesn't immediately remove the module, so we are measuring how long *on
average* it takes to receive "final confirmation" from the serial console after
inserting the module, and waiting 30 seconds.

For each kernel, 10 back-to-back trials were performed.

For the 6.11.0-0.rc3 stock kernel, we observe an average of 71 seconds from module insertion
to final confirmation, with an average of 41 seconds to print any
remaining/pending messages. The standard devation was 2 seconds, with a variance
of 4 seconds. Meaning that after invoking rmmod, we need to wait
41 seconds for the actual removal of the module to reach completion.

For the 6.11.0-0.rc3-rt2 "new printk" kernel, we observed an average of 47 seconds from module
insertion, to final confirmation, with an average of 17 seconds to print any
remaining/pending messages. The standard deviation and variance here were
minimal.

One more interesting note here, is that invoking `rmmod` on the stock kernel
after roughly 30 seconds will frequently cause the command line to become
unresponsive, with no way to kill said process or invoke any other commands in
the terminal. As it takes over 30 seconds, on average, to finish printing any
remaining messages, it has been observed that it may take well over 30 seconds
to regain any "control" of the system via the command line. 

Additionally, with the 6.11.0-0.rc3 stock kernel, leaving this kmod in any longer 
than say, 60 seconds, and then removing it via `rmmod` can, sporadically, 
cause an RCU stall to be printed to the serial console. I have attached it 
below for reference.

--- Test 4: Number of Messages printed ---

Similar to the previous test case, we are doing a *handwavey, estimated
comparison* of how fast we actually print to the serial console (up until
`rmmod` is invoked).

This test inserts the kernel module, waits 30 seconds, then removes the kernel
module. We are only measuring the amount of printed messages up until module
removal, as we have seen that time elapsed for printing pending messages may
vary drastically.

For each kernel, 5 back-to-back trials were performed.

For the stock kernel, we observed an average of about 14,263 messages printed
within 30 seconds. The standard deviation here hovers at around 1.52 messages,
with a variance of 2.3 messages.

For the "new printk" kernel, we observed an average of about 12,693 messages
printed within 30 seconds. The standard devation here hovers at about 131.2  
messages, with a variance of 17211 messages. 

We observe a rough 12-13 percent overall delta between new printk and the
stock kernel in this test case, with a larger disparity in standard
deviation/variance.

---- END TEST SUMMARIES ----

Of course, my testing methodologies could not only be heinously horrid, but also
innacurate. In that case, I urge you to discard them.


Cheers,


[0] https://lore.kernel.org/lkml/CAHk-=whU_woFnFN-3Jv2hNCmwLg_fkrT42AWwxm-=Ha5BmNX4w@mail.gmail.com/


View attachment "stock_rcu_stall" of type "text/plain" (3084 bytes)

View attachment "config-6.11.0-0.rc3.f8dba31b0a82.30.test.fc41.x86_64" of type "text/plain" (277816 bytes)

View attachment "config-6.11.0-0.rc3.20240814git6b0f8db921ab.32.eln142.x86_64" of type "text/plain" (244185 bytes)

Download attachment "monitor_script.sh" of type "application/x-sh" (1080 bytes)

Powered by blists - more mailing lists