Re: [PREEMPT_RT]: Using printk-rt-aware.patch in non-rt kernel

Re: [PREEMPT_RT]: Using printk-rt-aware.patch in non-rt kernel

[Pintu Kumar]

Hi All,

I have a question about PREEMPT_RT patch for 3.10 kernel.
I am trying to port this rt patch: 0224-printk-rt-aware.patch.patch
(see the patch below), in non-rt kernel.
I could able to successfully apply this patch after replacing:
migrate_enable/disable with preempt_enable/disable.
Things were working fine so far.

Then, I noticed that "printk" from interrupt context is not appearing
on console (minicom), if console shell is active.
However, it appears on the dmesg output.

So, I am wondering, what could be the cause of this patch for this
behavior in non-rt kernel?
Is this the expected behavior, even on PREEMPT_RT kernel?
Is there a way we can fix this issue on non-rt kernel?

Please help us with your suggestions.

Thanks,
Pintu

On Wed, Jun 13, 2018 at 8:02 PM Pintu Kumar <pintu.ping@gmail.com> wrote:
>
> Dear Thomas,
>
> I was looking into this RT patches for 3.10 kernel:
> https://mirrors.edge.kernel.org/pub/linux/kernel/projects/rt/3.10/patches-3.10.108-rt123.tar.gz
>
> And I came across your patch: 0224-printk-rt-aware.patch.patch
> I guess, this patch is related to improving irq latency during printk.
> And this patch can work only if PREEMPT_RT_FULL is enabled.
>
> But, I have 3.10 non-RT kernel, and still I want to use this feature
> for non-RT case and achieve the same functionality.
> Can you give me some idea, how to convert this RT patch to non-RT
> kernel and still achieve the same behavior.
> I know this is weird but it is our internal requirement.
>

> So, if you have any suggestions, it will be really helpful.
>
> Thank You!
>
> Regards,
> Pintu
>
> This is the patch details:
> -----------------------------------
> rt-patches/patches$ cat 0224-printk-rt-aware.patch.patch
> From ec944721d45454681485906615affa9368e0dfae Mon Sep 17 00:00:00 2001
> From: Thomas Gleixner <tglx@linutronix.de>
> Date: Wed, 19 Sep 2012 14:50:37 +0200
> Subject: [PATCH 224/405] printk-rt-aware.patch
>
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> ---
>  kernel/printk.c | 34 +++++++++++++++++++++++++++++-----
>  1 file changed, 29 insertions(+), 5 deletions(-)
>
> diff --git a/kernel/printk.c b/kernel/printk.c
> index e879b8615a0f..07d32a2c8a5f 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -1277,6 +1277,7 @@ static void call_console_drivers(int level,
> const char *text, size_t len)
>         if (!console_drivers)
>                 return;
>
> +       migrate_disable();
>         for_each_console(con) {
>                 if (exclusive_console && con != exclusive_console)
>                         continue;
> @@ -1289,6 +1290,7 @@ static void call_console_drivers(int level,
> const char *text, size_t len)
>                         continue;
>                 con->write(con, text, len);
>         }
> +       migrate_enable();
>  }
>
>  /*
> @@ -1348,12 +1350,18 @@ static inline int can_use_console(unsigned int cpu)
>   * interrupts disabled. It should return with 'lockbuf_lock'
>   * released but interrupts still disabled.
>   */
> -static int console_trylock_for_printk(unsigned int cpu)
> +static int console_trylock_for_printk(unsigned int cpu, unsigned long flags)
>         __releases(&logbuf_lock)
>  {
>         int retval = 0, wake = 0;
> +#ifdef CONFIG_PREEMPT_RT_FULL
> +       int lock = !early_boot_irqs_disabled && !irqs_disabled_flags(flags) &&
> +               (preempt_count() <= 1);
> +#else
> +       int lock = 1;
> +#endif
>
> -       if (console_trylock()) {
> +       if (lock && console_trylock()) {
>                 retval = 1;
>
>                 /*
> @@ -1688,8 +1696,15 @@ asmlinkage int vprintk_emit(int facility, int level,
>          * The console_trylock_for_printk() function will release 'logbuf_lock'
>          * regardless of whether it actually gets the console semaphore or not.
>          */
> -       if (console_trylock_for_printk(this_cpu))
> +       if (console_trylock_for_printk(this_cpu, flags)) {
> +#ifndef CONFIG_PREEMPT_RT_FULL
>                 console_unlock();
> +#else
> +               raw_local_irq_restore(flags);
> +               console_unlock();
> +               raw_local_irq_save(flags);
> +#endif
> +       }
>
>         lockdep_on();
>  out_restore_irqs:
> @@ -2043,11 +2058,16 @@ static void console_cont_flush(char *text, size_t size)
>                 goto out;
>
>         len = cont_print_text(text, size);
> +#ifndef CONFIG_PREEMPT_RT_FULL
>         raw_spin_unlock(&logbuf_lock);
>         stop_critical_timings();
>         call_console_drivers(cont.level, text, len);
>         start_critical_timings();
>         local_irq_restore(flags);
> +#else
> +       raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> +       call_console_drivers(cont.level, text, len);
> +#endif
>         return;
>  out:
>         raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> @@ -2141,13 +2161,17 @@ skip:
>                 console_idx = log_next(console_idx);
>                 console_seq++;
>                 console_prev = msg->flags;
> -               raw_spin_unlock(&logbuf_lock);
>
> +#ifndef CONFIG_PREEMPT_RT_FULL
> +               raw_spin_unlock(&logbuf_lock);
>                 stop_critical_timings();        /* don't trace print latency */
>                 call_console_drivers(level, text, len);
>                 start_critical_timings();
>                 local_irq_restore(flags);
> -
> +#else
> +               raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> +               call_console_drivers(level, text, len);
> +#endif
>                 if (do_cond_resched)
>                         cond_resched();
>         }
> --
> 2.13.2

Re: [PREEMPT_RT]: Using printk-rt-aware.patch in non-rt kernel

[Sebastian Andrzej Siewior]

On 2018-07-18 20:19:15 [+0530], Pintu Kumar wrote:
> Hi All,
Hi,

> I have a question about PREEMPT_RT patch for 3.10 kernel.
> I am trying to port this rt patch: 0224-printk-rt-aware.patch.patch
> (see the patch below), in non-rt kernel.
> I could able to successfully apply this patch after replacing:
> migrate_enable/disable with preempt_enable/disable.
> Things were working fine so far.

Why? 

> Then, I noticed that "printk" from interrupt context is not appearing
> on console (minicom), if console shell is active.
> However, it appears on the dmesg output.
> 
> So, I am wondering, what could be the cause of this patch for this
> behavior in non-rt kernel?
> Is this the expected behavior, even on PREEMPT_RT kernel?

I *think* it is but there are hardly any prints from atomic context for
anyone to notice. And the next print from non-atomic context should
flush it out.

> Is there a way we can fix this issue on non-rt kernel?
I would guess that a wakeup to klogd would fix it.

> Please help us with your suggestions.
> 
> Thanks,
> Pintu

Sebastian

Re: [PREEMPT_RT]: Using printk-rt-aware.patch in non-rt kernel

[Pintu Kumar]

On Thu, Jul 26, 2018 at 9:08 PM Sebastian Andrzej Siewior
<sebastian.siewior@linutronix.de> wrote:
>
> On 2018-07-18 20:19:15 [+0530], Pintu Kumar wrote:
> > Hi All,
> Hi,
>
> > I have a question about PREEMPT_RT patch for 3.10 kernel.
> > I am trying to port this rt patch: 0224-printk-rt-aware.patch.patch
> > (see the patch below), in non-rt kernel.
> > I could able to successfully apply this patch after replacing:
> > migrate_enable/disable with preempt_enable/disable.
> > Things were working fine so far.
>
> Why?
>
> > Then, I noticed that "printk" from interrupt context is not appearing
> > on console (minicom), if console shell is active.
> > However, it appears on the dmesg output.
> >
> > So, I am wondering, what could be the cause of this patch for this
> > behavior in non-rt kernel?
> > Is this the expected behavior, even on PREEMPT_RT kernel?
>
> I *think* it is but there are hardly any prints from atomic context for
> anyone to notice. And the next print from non-atomic context should
> flush it out.
>
Yes, we observed the same behavior with CONFIG_PREEMPT_RT_FULL with
beagle bone-rt kernel 4.9.
And yes, after doing : echo "1234" > /dev/kmsg the content were flushed.
So, I guess this is the expected behavior with this patch.

> > Is there a way we can fix this issue on non-rt kernel?
> I would guess that a wakeup to klogd would fix it.
>
Sorry, can you elaborate more about "wakeup to klogd".
I wanted to try it and check.

> > Please help us with your suggestions.
> >
> > Thanks,
> > Pintu
>
> Sebastian

Re: [PREEMPT_RT]: Using printk-rt-aware.patch in non-rt kernel

[Sebastian Andrzej Siewior]

On 2018-07-26 23:38:05 [+0530], Pintu Kumar wrote:
> > > Is there a way we can fix this issue on non-rt kernel?
> > I would guess that a wakeup to klogd would fix it.
> >
> Sorry, can you elaborate more about "wakeup to klogd".
> I wanted to try it and check.

Something like this should do the work.

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 179ad787a08c..411f9ed5f051 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1927,6 +1927,8 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
 }
 
+static void printk_flush_pending_output(void);
+
 asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
 			    const char *fmt, va_list args)
@@ -2026,6 +2028,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (may_trylock && console_trylock_spinning())
 			console_unlock();
+		else if (!may_trylock)
+			printk_flush_pending_output();
+
 		migrate_enable();
 	}
 
@@ -2987,6 +2992,13 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 	.flags = IRQ_WORK_LAZY,
 };
 
+static void printk_flush_pending_output(void)
+{
+	/* preemption or interrupts need to be disabled */
+	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
+	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+}
+
 void wake_up_klogd(void)
 {
 	preempt_disable();

Sebastian