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 <[email protected]> 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 <[email protected]>
> Date: Wed, 19 Sep 2012 14:50:37 +0200
> Subject: [PATCH 224/405] printk-rt-aware.patch
>
> Signed-off-by: Thomas Gleixner <[email protected]>
> ---
> 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
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
On Thu, Jul 26, 2018 at 9:08 PM Sebastian Andrzej Siewior
<[email protected]> 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
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