[PATCH] printk: Add atomic context check inside console_unlock()

[PATCH] printk: Add atomic context check inside console_unlock()

[Mukesh Ojha]

Situation of schedule while atomic context can happen in a
scenario if CPU-Y executing a async probe of ufs and while
printing a line it is started spinning for console lock
after preemption disable on CPU-Y and later it got the handover
of console lock from CPU-X and in console_unlock() it get
schedule with preempt disable as console_may_schedule was one
and due to which do_cond_resched was one.

         CPU-X                          CPU-Y

                                      worker_thread
                                       process_one_work
                                        async_run_entry_fn
                                         ufshcd_async_scan
                                          ufshcd_device_init
really_probe+0x1c8                         ufshcd_probe_hba
 platform_probe+0xc0                        ufshcd_config_mcq
  qcom_geni_serial_probe+0x374               _dev_info
   uart_add_one_port+0x10                     __dev_printk
    serial_ctrl_register_port+0x10             dev_printk_emit
     serial_core_register_port+0x5dc            dev_vprintk_emit
      register_console+0x284                      vprintk_emit
       console_init_seq()                          preempt_disable();
	                                           console_trylock_spinning()
        console_lock();
         console_flush_all()

Hand over of console lock happen from CPU-X to CPU-Y
                                                   console_unlock()
          console_lock+0x74                         console_flush_all
	   down[jt]+0x40                             __might_resched
	    __down+0x18
             __down_common+0x68
              ___down_common+0xdc
               schedule_timeout+0x4c
                schedule+0x78
                 __schedule+0x6c0

Signed-off-by: Mukesh Ojha <quic_mojha@quicinc.com>
---
 kernel/printk/printk.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index f2444b581e16..8b666feff65d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3028,7 +3028,7 @@ void console_unlock(void)
 	 * messages practically incapacitating the system. Therefore, create
 	 * a local to use for the printing loop.
 	 */
-	do_cond_resched = console_may_schedule;
+	do_cond_resched = in_atomic() || console_may_schedule;
 
 	do {
 		console_may_schedule = 0;
-- 
2.43.0.254.ga26002b62827

Re: [PATCH] printk: Add atomic context check inside console_unlock()

[John Ogness]

On 2024-02-22, Mukesh Ojha <quic_mojha@quicinc.com> wrote:
> Situation of schedule while atomic context can happen in a
> scenario if CPU-Y executing a async probe of ufs and while
> printing a line it is started spinning for console lock
> after preemption disable on CPU-Y and later it got the handover
> of console lock from CPU-X and in console_unlock() it get
> schedule with preempt disable as console_may_schedule was one
> and due to which do_cond_resched was one.

Nice catch. But I think the below patch is the appropriate fix:

John Ogness

-------8<--------
Subject: [PATCH] printk: Update @console_may_schedule in
 console_trylock_spinning()

console_trylock_spinning() may takeover the console lock from a
scheduable context. Update @console_may_schedule to make sure it
reflects a trylock acquire.

Reported-by: Mukesh Ojha <quic_mojha@quicinc.com>
Link: https://lore.kernel.org/lkml/20240222090538.23017-1-quic_mojha@quicinc.com
Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
 kernel/printk/printk.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1685a71f3f71..1612b50b2374 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2020,6 +2020,12 @@ static int console_trylock_spinning(void)
 	 */
 	mutex_acquire(&console_lock_dep_map, 0, 1, _THIS_IP_);
 
+	/*
+	 * Update @console_may_schedule for trylock because the previous
+	 * owner may have been scheduable.
+	 */
+	console_may_schedule = 0;
+
 	return 1;
 }
 

base-commit: e7081d5a9d976b84f61f497316d7c940a4a2e67a
-- 
2.30.2

Re: [PATCH] printk: Add atomic context check inside console_unlock()

[Mukesh Ojha]

On 2/22/2024 8:23 PM, John Ogness wrote:
> On 2024-02-22, Mukesh Ojha <quic_mojha@quicinc.com> wrote:
>> Situation of schedule while atomic context can happen in a
>> scenario if CPU-Y executing a async probe of ufs and while
>> printing a line it is started spinning for console lock
>> after preemption disable on CPU-Y and later it got the handover
>> of console lock from CPU-X and in console_unlock() it get
>> schedule with preempt disable as console_may_schedule was one
>> and due to which do_cond_resched was one.
> 
> Nice catch. But I think the below patch is the appropriate fix:

Thanks for the change @john, would you be sending this as proper
patch.

-Mukesh
> 
> John Ogness
> 
> -------8<--------
> Subject: [PATCH] printk: Update @console_may_schedule in
>   console_trylock_spinning()
> 
> console_trylock_spinning() may takeover the console lock from a
> scheduable context. Update @console_may_schedule to make sure it
> reflects a trylock acquire.
> 
> Reported-by: Mukesh Ojha <quic_mojha@quicinc.com>
> Link: https://lore.kernel.org/lkml/20240222090538.23017-1-quic_mojha@quicinc.com
> Signed-off-by: John Ogness <john.ogness@linutronix.de>
> ---
>   kernel/printk/printk.c | 6 ++++++
>   1 file changed, 6 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 1685a71f3f71..1612b50b2374 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2020,6 +2020,12 @@ static int console_trylock_spinning(void)
>   	 */
>   	mutex_acquire(&console_lock_dep_map, 0, 1, _THIS_IP_);
>   
> +	/*
> +	 * Update @console_may_schedule for trylock because the previous
> +	 * owner may have been scheduable.
> +	 */
> +	console_may_schedule = 0;
> +
>   	return 1;
>   }
>   
> 
> base-commit: e7081d5a9d976b84f61f497316d7c940a4a2e67a

[PATCH] printk: Update @console_may_schedule in console_trylock_spinning()

[John Ogness]

console_trylock_spinning() may takeover the console lock from a
schedulable context. Update @console_may_schedule to make sure it
reflects a trylock acquire.

Reported-by: Mukesh Ojha <quic_mojha@quicinc.com>
Link: https://lore.kernel.org/lkml/20240222090538.23017-1-quic_mojha@quicinc.com
Fixes: dbdda842fe96 ("printk: Add console owner and waiter logic to load balance console writes")
Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
 kernel/printk/printk.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1685a71f3f71..1612b50b2374 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2020,6 +2020,12 @@ static int console_trylock_spinning(void)
 	 */
 	mutex_acquire(&console_lock_dep_map, 0, 1, _THIS_IP_);
 
+	/*
+	 * Update @console_may_schedule for trylock because the previous
+	 * owner may have been schedulable.
+	 */
+	console_may_schedule = 0;
+
 	return 1;
 }
 

base-commit: e7081d5a9d976b84f61f497316d7c940a4a2e67a
-- 
2.30.2

Re: [PATCH] printk: Update @console_may_schedule in console_trylock_spinning()

[Mukesh Ojha]

On 2/26/2024 5:31 PM, John Ogness wrote:
> console_trylock_spinning() may takeover the console lock from a
> schedulable context. Update @console_may_schedule to make sure it
> reflects a trylock acquire.
> 
> Reported-by: Mukesh Ojha <quic_mojha@quicinc.com>
> Link: https://lore.kernel.org/lkml/20240222090538.23017-1-quic_mojha@quicinc.com
> Fixes: dbdda842fe96 ("printk: Add console owner and waiter logic to load balance console writes")
> Signed-off-by: John Ogness <john.ogness@linutronix.de>

Thanks for prompt response..

Yes, this looks fine..
As spinning code runs with preemption disabled context
and should reset the console_may_schedule to 0 .

what if console_trylock_spinning() gets the lock which makes 
console_may_schedule =1 and it is still schedulable ?

-Mukesh

> ---
>   kernel/printk/printk.c | 6 ++++++
>   1 file changed, 6 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 1685a71f3f71..1612b50b2374 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2020,6 +2020,12 @@ static int console_trylock_spinning(void)
>   	 */
>   	mutex_acquire(&console_lock_dep_map, 0, 1, _THIS_IP_);
>   
> +	/*
> +	 * Update @console_may_schedule for trylock because the previous
> +	 * owner may have been schedulable.
> +	 */
> +	console_may_schedule = 0;
> +
>   	return 1;
>   }
>   
> 
> base-commit: e7081d5a9d976b84f61f497316d7c940a4a2e67a

Re: [PATCH] printk: Update @console_may_schedule in console_trylock_spinning()

[John Ogness]

On 2024-02-26, Mukesh Ojha <quic_mojha@quicinc.com> wrote:
> what if console_trylock_spinning() gets the lock which makes 
> console_may_schedule =1 and it is still schedulable ?

I am afraid I do not understand the question.

console_trylock_spinning() is only called from the printk caller
context. In this context, console_may_schedule is always set to 0.

Only if another context acquires the console lock per sleeping wait,
console_lock(), can console_may_schedule be set to 1.

Note that the value of console_may_schedule is only relevant for the
console lock owner when console_unlock() is called. That is why its
value is set when locking the console (or, with this patch, when
transferring console lock ownerhip).

John

Re: [PATCH] printk: Update @console_may_schedule in console_trylock_spinning()

[Mukesh Ojha]

On 2/26/2024 6:32 PM, John Ogness wrote:
> On 2024-02-26, Mukesh Ojha <quic_mojha@quicinc.com> wrote:
>> what if console_trylock_spinning() gets the lock which makes
>> console_may_schedule =1 and it is still schedulable ?
> 
> I am afraid I do not understand the question.
> 
> console_trylock_spinning() is only called from the printk caller
> context. In this context, console_may_schedule is always set to 0.
> 
> Only if another context acquires the console lock per sleeping wait,
> console_lock(), can console_may_schedule be set to 1.
> 
> Note that the value of console_may_schedule is only relevant for the
> console lock owner when console_unlock() is called. That is why its
> value is set when locking the console (or, with this patch, when
> transferring console lock ownerhip).

I overlooked it, thanks.
Patch LGTM.

Reviewed-by: Mukesh Ojha <quic_mojha@quicinc.com>

-Mukesh
> 
> John

Re: [PATCH] printk: Update @console_may_schedule in console_trylock_spinning()

[Petr Mladek]

On Mon 2024-02-26 13:07:24, John Ogness wrote:
> console_trylock_spinning() may takeover the console lock from a
> schedulable context. Update @console_may_schedule to make sure it
> reflects a trylock acquire.
> 
> Reported-by: Mukesh Ojha <quic_mojha@quicinc.com>
> Link: https://lore.kernel.org/lkml/20240222090538.23017-1-quic_mojha@quicinc.com
> Fixes: dbdda842fe96 ("printk: Add console owner and waiter logic to load balance console writes")
> Signed-off-by: John Ogness <john.ogness@linutronix.de>

Makes perfect sense:

Reviewed-by: Petr Mladek <pmladek@suse.com>

JFYI, the patch has been committed into printk/linux.git, for-6.9
branch.

I am going to give it a spin in for-next and get it into 6.9
either in the 2nd half of the merge window or in rc1.

Best Regards,
Petr