Re: [PATCH printk v5 17/17] printk: Avoid false positive lockdep report for legacy printing

[Petr Mladek <pmladek@suse.com>]

On Fri 2024-08-30 17:35:16, John Ogness wrote:
> Legacy console printing from printk() caller context may invoke
> the console driver from atomic context. This leads to a lockdep
> splat because the console driver will acquire a sleeping lock
> and the caller may already hold a spinning lock. This is noticed
> by lockdep on !PREEMPT_RT configurations because it will lead to
> a problem on PREEMPT_RT.
> 
> However, on PREEMPT_RT the printing path from atomic context is
> always avoided and the console driver is always invoked from a
> dedicated thread. Thus the lockdep splat on !PREEMPT_RT is a
> false positive.
> 
> For !PREEMPT_RT override the lock-context before invoking the
> console driver to avoid the false positive.
> 
> Do not override the lock-context for PREEMPT_RT in order to
> allow lockdep to catch any real locking context issues related
> to the write callback usage.
> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3030,31 +3058,46 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
>  		con->dropped = 0;
>  	}
>  
> -	/*
> -	 * While actively printing out messages, if another printk()
> -	 * were to occur on another CPU, it may wait for this one to
> -	 * finish. This task can not be preempted if there is a
> -	 * waiter waiting to take over.
> -	 *
> -	 * Interrupts are disabled because the hand over to a waiter
> -	 * must not be interrupted until the hand over is completed
> -	 * (@console_waiter is cleared).
> -	 */
> -	printk_safe_enter_irqsave(flags);
> -	console_lock_spinning_enable();
> +	/* Write everything out to the hardware. */
>  
> -	/* Do not trace print latency. */
> -	stop_critical_timings();
> +	if (force_legacy_kthread() && !panic_in_progress()) {
> +		/*
> +		 * With forced threading this function is in a task context
> +		 * (either legacy kthread or get_init_console_seq()). There
> +		 * is no need for concern about printk reentrance, handovers,
> +		 * or lockdep complaints.
> +		 */

The legacy kthread is used only when it is running.
What about early boot messages?
And what about NBCON_PRIO_EMERGENCY?

Hmm, it seems that force_legacy_kthread() really prevents calling this
in interrupt context because is_printk_legacy_deferred() always
returns true in this case. Is this correct? I actually reported this
as a bug, see https://lore.kernel.org/r/ZtcRZpLjCjWeC4nG@pathway.suse.cz

Or is this the only possible way to avoid taking sleeping spinlock
under raw spinlock in RT, please?


> -	/* Write everything out to the hardware. */
> -	con->write(con, outbuf, pmsg.outbuf_len);
> +		con->write(con, outbuf, pmsg.outbuf_len);
> +		con->seq = pmsg.seq + 1;
> +	} else {
> +		/*
> +		 * While actively printing out messages, if another printk()
> +		 * were to occur on another CPU, it may wait for this one to
> +		 * finish. This task can not be preempted if there is a
> +		 * waiter waiting to take over.
> +		 *
> +		 * Interrupts are disabled because the hand over to a waiter
> +		 * must not be interrupted until the hand over is completed
> +		 * (@console_waiter is cleared).
> +		 */
> +		printk_safe_enter_irqsave(flags);
> +		console_lock_spinning_enable();
>  
> -	start_critical_timings();
> +		/* Do not trace print latency. */
> +		stop_critical_timings();
>  
> -	con->seq = pmsg.seq + 1;
> +		printk_legacy_allow_spinlock_enter();
> +		con->write(con, outbuf, pmsg.outbuf_len);
> +		printk_legacy_allow_spinlock_exit();
>  
> -	*handover = console_lock_spinning_disable_and_check(cookie);
> -	printk_safe_exit_irqrestore(flags);
> +		start_critical_timings();
> +
> +		con->seq = pmsg.seq + 1;
> +
> +		*handover = console_lock_spinning_disable_and_check(cookie);
> +		printk_safe_exit_irqrestore(flags);
> +	}
>  skip:
>  	return true;
>  }

Best Regards,
Petr