lkml.org 
[lkml]   [2018]   [Oct]   [1]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    Date
    From
    SubjectRe: [PATCH] printk: inject caller information into the body of message
    On (09/29/18 20:13), Sergey Senozhatsky wrote:
    > We used to flush "incomplete" cont lines (fragments) from console_unlock().
    >
    > void console_unlock(void)
    > {
    > ...
    > /* flush buffered message fragment immediately to console */
    > console_cont_flush(text, sizeof(text));
    > again:
    > for (;;) {
    > ...
    > }
    > ...
    > }
    >
    > Unless I'm missing something, we don't anymore.
    > Since 5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb.
    > Now we print only log_buf entries. So we either wait for a \n to flush
    > a complete cont buffer, or for a race to preliminary flush cont buffer.

    BTW, it just crossed my mind:

    Previously, we would do console_cont_flush() for each pr_cont(),
    so console_unlock() would print data:

    pr_cont();
    console_lock();
    console_unlock()
    console_cont_flush(); // print cont fragment
    ...
    pr_cont();
    console_lock();
    console_unlock()
    console_cont_flush(); // print cont fragment

    We don't console_cont_flush() anymore, so when we do pr_cont()
    console_unlock() does nothing (unless we flushed the cont buffer):

    pr_cont();
    console_lock();
    console_unlock(); // noop
    ...
    pr_cont();
    console_lock();
    console_unlock(); // noop
    ...
    pr_cont();
    cont_flush();
    console_lock();
    console_unlock(); // print data

    console_lock()/console_unlock() makes sense only when we flush cont
    buffer.

    We also wakeup klogd purposelessly for pr_cont() output - un-flushed
    is not stored in log_buf; there is nothing to pull.

    So we can console_lock()/console_unlock()/wake_up_klogd() only when we
    know that we log_stor()-ed a message.

    A quick-n-dirty patch (I can send a formal one) which compares log_next_seq
    before and after vprintk_store(). log_next_seq is getting incremented each
    time we log_store() a new log_buf message:

    ---

    diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
    index 308497194bd4..53d9134f02a6 100644
    --- a/kernel/printk/printk.c
    +++ b/kernel/printk/printk.c
    @@ -1931,6 +1931,7 @@ asmlinkage int vprintk_emit(int facility, int level,
    int printed_len;
    bool in_sched = false;
    unsigned long flags;
    + u64 curr_log_seq;

    if (level == LOGLEVEL_SCHED) {
    level = LOGLEVEL_DEFAULT;
    @@ -1942,11 +1943,12 @@ asmlinkage int vprintk_emit(int facility, int level,

    /* This stops the holder of console_sem just where we want him */
    logbuf_lock_irqsave(flags);
    + curr_log_seq = log_next_seq;
    printed_len = vprintk_store(facility, level, dict, dictlen, fmt, args);
    logbuf_unlock_irqrestore(flags);

    /* If called from the scheduler, we can not call up(). */
    - if (!in_sched) {
    + if (!in_sched && (curr_log_seq != log_next_seq)) {
    /*
    * Disable preemption to avoid being preempted while holding
    * console_sem which would prevent anyone from printing to
    @@ -1963,7 +1965,8 @@ asmlinkage int vprintk_emit(int facility, int level,
    preempt_enable();
    }

    - wake_up_klogd();
    + if (curr_log_seq != log_next_seq)
    + wake_up_klogd();
    return printed_len;
    }
    EXPORT_SYMBOL(vprintk_emit);
    ---
    -ss

    \
     
     \ /
      Last update: 2018-10-01 07:52    [W:4.154 / U:0.940 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site