On 2019-08-15 14:33:41 [+0200], John Ogness wrote:

On 2019-08-15, Sebastian Andrzej Siewior [off-list ref] wrote:

quoted

quoted

The attachment is here:
https://bugzilla.kernel.org/attachment.cgi?id=284391

both traces have `printk' in it. Could you please explain what it is
doing?  It should print something to the console. The printk code in
v4.19 vs later changed and now (by default) ERR levels are printed
immediately and will cause latency spikes.

This would explain the spike but I don't understand how lazy preempt
is related here.

Where in this trace is there a latency spike? I could not see one.

|   printk-873     1....111 84243670us : cdns_uart_console_putchar <-uart_console_write
|   printk-873     1....111 84243711us : cdns_uart_console_putchar <-uart_console_write
|   printk-873     1d...111 84243731us : gic_handle_irq <-el1_irq
…
|   printk-873     1dN..111 84243791us : idle_cpu <-irq_exit
|   printk-873     1dN..111 84243792us : rcu_irq_exit <-irq_exit
|   printk-873     1dN..111 84244822us : gic_handle_irq <-el1_irq

it prints. Then an interrupts arrives, gets handled, wakes cyclictest.
But instead switching to cyclictest from the irq_exit it gets back to
printing and another interrupt arrives. And then it says that preempt
disable, migrate disable, lazy preempt disable is all one. But
preemption should be enabled. Looking at the whole trace, the preemption
counter is always >= 1 so this might be arm64 specific increment during
recording.

Emergency messages are not involved here. You can see at 84239098us that

Right, we don't have that. Let me boot my arm64, print something and
check how it goes…

John Ogness

Sebastian