Re: A Comparison of printk between upstream and linux-rt-devel

[Sebastian Andrzej Siewior <bigeasy@linutronix.de>]

On 2024-08-22 12:32:15 [-0400], Derek Barbosa wrote:
> Hi,
Hi,

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

Thank you for testing.

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

I am a bit confused. You write here ~14k messages within 30secs for
"stock" aka 6.11.0-0.rc3 and then ~12k messages for "new printk" aka
from the latest RT tree. At the top you write "6.11.0-0.rc3 is slower on
flush". This means something else I guess.

Regarding your RCU stall: You stuff a _lot_ into the printk buffer. And
then printk is forced print everything out in a single sitting. The
whole printing job is done within a preempt_disable region so RCU has to
wait until it is done. If printing of the whole buffer takes >60sec then
you see your RCU stall.
The current RT tree will do the printing from a kthread which remains
preemptible because your printing threads don't print any errors/ panics
for 30seconds. So RCU gets its turn.

Sebastian