Re: [PATCH v10 1/2] printk: Make printk() completely async

[Sergey Senozhatsky]

Hello,

On (08/20/16 14:24), Sergey Senozhatsky wrote:
> On (08/19/16 21:00), Jan Kara wrote:
> > > > depending on .config BUG() may never return back -- passing control
> > > > to do_exit(), so printk_deferred_exit() won't be executed. thus we
> > > > probably need to have a per-cpu variable that would indicate that
> > > > we are in deferred_bug. hm... but do we really need deferred BUG()
> > > > in the first place?
> > > 
> > > Good question. I am not aware of any BUG_ON() that would be called from
> > > wake_up_process() but it is hard to check everything.
> > > 
> > > A conservative approach would be to force synchronous printk from
> > > BUG_ON().
> > 
> > Just a quick thought: Cannot we just do printk_deferred_enter() when we are
> > about to call into the scheduler from printk code and printk_deferred_exit()
> > when leaving it? That would look like the least error-prone way how
> > handling this kind of recursion...
> 
> interesting idea.
> printk_deferred_enter() increments preempt count, so there may be additional
> obstacles and, as a result, ad-hocs, that scheduler people will sincerely hate.
> need to think more.

so we probably can try something like this

---

diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 2add7c5..b23f919 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2014,6 +2014,7 @@ try_to_wake_up(struct task_struct *p, unsigned int state, int wake_flags)
         * set_current_state() the waiting thread does.
         */
        smp_mb__before_spinlock();
+       printk_deferred_enter();
        raw_spin_lock_irqsave(&p->pi_lock, flags);
        if (!(p->state & state))
                goto out;
@@ -2073,6 +2074,7 @@ stat:
                ttwu_stat(p, cpu, wake_flags);
 out:
        raw_spin_unlock_irqrestore(&p->pi_lock, flags);
+       printk_deferred_exit();
 
        return success;
 }


---

since we are basically interested in wake_up_process() only from
printk() POV. not sure how acceptable 2 * preempt_count and 2 * per-CPU
writes for every try_to_wake_up().


the other thing I just thought of is doing something as follows
!!!not tested, will not compile, just an idea!!!

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6e260a0..bb8d719 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1789,6 +1789,7 @@ asmlinkage int vprintk_emit(int facility, int level,
        printk_delay();
 
        local_irq_save(flags);
+       printk_nmi_enter();
        this_cpu = smp_processor_id();
 
        /*
@@ -1804,6 +1805,7 @@ asmlinkage int vprintk_emit(int facility, int level,
                 */
                if (!oops_in_progress && !lockdep_recursing(current)) {
                        recursion_bug = true;
+                       printk_nmi_exit();
                        local_irq_restore(flags);
                        return 0;
                }
@@ -1920,6 +1922,7 @@ asmlinkage int vprintk_emit(int facility, int level,
        logbuf_cpu = UINT_MAX;
        raw_spin_unlock(&logbuf_lock);
        lockdep_on();
+       printk_nmi_exit();
        local_irq_restore(flags);
 
        /* If called from the scheduler, we can not call up(). */
---

so may be we will not blow up in case of spin_dump() on logbuf_lock.
well, if logbuf_lock was corrupted then nothing will help us -- it's over.
but if raw_spin_lock(&logbuf_lock), for instance, spin_dump()-s because
logbuf_lock was not released after `loops_per_jiffy * HZ' then deferred
printing may help.


probably we can make NMI printk_func to be more general way of using
an alternative-printk buffer and, for example, rename API it to
printk_alternative_enter() and printk_alternative_exit(), not to confuse
anyone. (yes, NMIs are not available on every platform)


and even more. we can start dump_stack() from recursion detection path
to that alternative printk-buffer, which is a bit more helpful than
"BUG: recent printk recursion!"
!!!not tested, will not compile, just an idea!!!

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6e260a0..ebce39a 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1789,6 +1789,7 @@ asmlinkage int vprintk_emit(int facility, int level,
        printk_delay();
 
        local_irq_save(flags);
+       printk_nmi_enter();
        this_cpu = smp_processor_id();
 
        /*
@@ -1804,6 +1805,8 @@ asmlinkage int vprintk_emit(int facility, int level,
                 */
                if (!oops_in_progress && !lockdep_recursing(current)) {
                        recursion_bug = true;
+                       WARN_ON(1);		/* <<< dump_stack to alternative buffer */
+                       printk_nmi_exit();
                        local_irq_restore(flags);
                        return 0;
                }
@@ -1816,14 +1819,8 @@ asmlinkage int vprintk_emit(int facility, int level,
        logbuf_cpu = this_cpu;
 
        if (unlikely(recursion_bug)) {
-               static const char recursion_msg[] =
-                       "BUG: recent printk recursion!";
-
                recursion_bug = false;
-               /* emit KERN_CRIT message */
-               printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
-                                        NULL, 0, recursion_msg,
-                                        strlen(recursion_msg));
+               printk_nmi_flush();
        }
 
        nmi_message_lost = get_nmi_message_lost();
@@ -1920,6 +1917,7 @@ asmlinkage int vprintk_emit(int facility, int level,
        logbuf_cpu = UINT_MAX;
        raw_spin_unlock(&logbuf_lock);
        lockdep_on();
+       printk_nmi_exit();
        local_irq_restore(flags);
 
        /* If called from the scheduler, we can not call up(). */

---

just some quick thoughts.


	-ss