On Wed 2018-10-24 19:11:10, Tetsuo Handa wrote: > Sometimes we want to print a whole line without being disturbed by > concurrent printk() from interrupts and/or other threads, for printk() > which does not end with '\n' can be disturbed. > > Since mixed printk() output makes it hard to interpret, this patch > introduces API for line-buffered printk() output (so that we can make > sure that printk() ends with '\n'). > > Since functions introduced by this patch are merely wrapping > printk()/vprintk() calls in order to minimize possibility of using > "struct cont", it is safe to replace printk()/vprintk() with this API. > Since we want to remove "struct cont" eventually, we will try to remove > both "implicit printk() users who are expecting KERN_CONT behavior" and > "explicit pr_cont()/printk(KERN_CONT) users". Therefore, converting to > this API is recommended. > > After this patch, we will consider how we can add context identifier to > each line of printk() output (so that we can group multiple lines into > one block when parsing). Therefore, if converting to this API does not > fit for some reason, you might be able to consider converting to multiple > printk() calls which end with '\n'.
The buffered printk API is for continuous lines. It is more complicated than a simple printk. You need to get, use, and put the buffer. It might be acceptable for continuous lines that should be rare and the related calls typically located in a single function. I prefer to solve the related lines on another level, for example, by storing/showing PID+context_mask for each printed line. This way it would work transparently even for normal printk(). > Details: > > A structure named "struct printk_buffer" is introduced for buffering > up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'. > > get_printk_buffer() tries to assign a "struct printk_buffer" from > statically preallocated array. get_printk_buffer() returns NULL if > all "struct printk_buffer" are in use, but the caller does not need to > check for NULL. > > put_printk_buffer() flushes and releases the "struct printk_buffer". > put_printk_buffer() must match corresponding get_printk_buffer() as with > rcu_read_unlock() must match corresponding rcu_read_lock(). > > Three functions vprintk_buffered(), printk_buffered() and > flush_printk_buffer() are provided for using "struct printk_buffer". > These are like vfprintf(), fprintf(), fflush() except that these receive > "struct printk_buffer *" for the first argument. > > vprintk_buffered() and printk_buffered() behave like vprintk() and > printk() respectively if "struct printk_buffer *" argument is NULL. I have troubles the distinguish the meaning of above sentence and the previous paragraph. It might help to use "fall back" instead of "behave like". > flush_printk_buffer() and put_printk_buffer() become no-op if > "struct printk_buffer *" argument is NULL. Therefore, the caller of > get_printk_buffer() does not need to check for NULL. > [...] > --- /dev/null > +++ b/kernel/printk/printk_buffered.c > @@ -0,0 +1,279 @@ /* SPDX-License-Identifier: GPL-2.0+ */ > +/* > + * printk_buffered.c - Line buffered printk() for avoiding KERN_CONT usage. > + * > + * This program is free software; you can redistribute it and/or > + * modify it under the terms of the GNU General Public License > + * as published by the Free Software Foundation; either version 2 > + * of the License, or (at your option) any later version. > + * > + * This program is distributed in the hope that it will be useful, > + * but WITHOUT ANY WARRANTY; without even the implied warranty of > + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the > + * GNU General Public License for more details. > + * > + * You should have received a copy of the GNU General Public License > + * along with this program; if not, see <http://www.gnu.org/licenses/>. > + */ > + > +#include <linux/types.h> /* DECLARE_BITMAP() */ > +#include <linux/preempt.h> /* in_nmi() */ > +#include <linux/workqueue.h> /* queue_work() */ > +#include <linux/stacktrace.h> /* save_stack_trace() */ > +#include <linux/sched.h> /* cond_resched() */ > +#include <linux/printk.h> > + > +/* > + * Should be sync with definitions in printk.c in order to avoid truncated > + * printk() output due to limitations. > + */ > +#define PREFIX_MAX 32 > +#define LOG_LINE_MAX (1024 - PREFIX_MAX) This might be shared via kernel/printk/internal.h > +/* A structure for line-buffered printk() output. */ > +struct printk_buffer { > + unsigned short int used; /* Valid bytes in buf[]. */ > + char buf[LOG_LINE_MAX]; > +} __aligned(1024); > + > +/* > + * Number of statically preallocated buffers. > + * > + * We can introduce a kernel config option if someone wants to tune this > value. > + * But since "struct printk_buffer" makes difference only when there are > + * multiple threads concurrently calling printk() which does not end with > '\n', > + * and this API will fallback to normal printk() when all buffers are in use, > + * it is possible that nobody needs to tune this value. > + */ > +#define NUM_LINE_BUFFERS 16 > + > +static struct printk_buffer printk_buffers[NUM_LINE_BUFFERS]; > +static DECLARE_BITMAP(printk_buffers_in_use, NUM_LINE_BUFFERS); > + > +#ifdef CONFIG_DEBUG_PRINTK_BUFFERED > +#define PRINTK_BUFFERS_MAX_TRACE_ENTRIES 20 > +static struct { > + unsigned long stamp; > + struct stack_trace trace; > + unsigned long entries[PRINTK_BUFFERS_MAX_TRACE_ENTRIES]; > +} printk_buffers_dump[NUM_LINE_BUFFERS]; > +static int buffer_users_report_scheduled; > + > +static void report_buffer_users(struct work_struct *work) > +{ > + long i; > + unsigned int j; > + > + /* > + * This report is racy. But it does not worth introducing a lock > + * dependency. > + */ > + pr_info("printk: All line buffers are in use.\n"); nit: It need not longer be true. I would use "were in use". > + for (i = 0; i < NUM_LINE_BUFFERS; i++) { > + if (!test_bit(i, printk_buffers_in_use)) > + continue; > + pr_info("buffer[%lu] was reserved %lu jiffies ago by\n", > + i, jiffies - printk_buffers_dump[i].stamp); nit: It is not a big deal. But I would convert this to a human readable time, e.g. by jiffies_to_msecs() or jiffies_to_timeval(). > + for (j = 0; j < printk_buffers_dump[i].trace.nr_entries; j++) > + pr_info(" %pS\n", (void *) > + printk_buffers_dump[i].entries[j]); This duplicates print_stack_trace(). > + cond_resched(); > + } > +} > +#endif > + > +static inline void save_caller_info(const long i) > +{ > +#ifdef CONFIG_DEBUG_PRINTK_BUFFERED > + if (buffer_users_report_scheduled) > + return; > + printk_buffers_dump[i].stamp = jiffies; > + printk_buffers_dump[i].trace.nr_entries = 0; > + printk_buffers_dump[i].trace.entries = printk_buffers_dump[i].entries; > + printk_buffers_dump[i].trace.max_entries = > + PRINTK_BUFFERS_MAX_TRACE_ENTRIES; > + printk_buffers_dump[i].trace.skip = 0; > + save_stack_trace(&printk_buffers_dump[i].trace); > +#endif > +} > + > +static void dump_caller_info(void) > +{ > +#ifdef CONFIG_DEBUG_PRINTK_BUFFERED > + static DECLARE_WORK(work, report_buffer_users); > + > + /* > + * Oops, out of "struct printk_buffer" happened. Fallback to normal > + * printk(). > + * > + * If you think that it might be due to missing put_printk_buffer() > + * calls, you can enable CONFIG_DEBUG_PRINTK_BUFFERED. > + * Then, who is using the buffers will be reported (from workqueue > + * context because reporting NUM_LINE_BUFFERS entries > + * from atomic context might be too slow). If it does not look like > + * missing put_printk_buffer() calls, you might want to increase > + * NUM_LINE_BUFFERS. > + * > + * But if it turns out that allocating "struct printk_buffer" on stack > + * or in .bss section or from kzalloc() is more suitable than tuning > + * NUM_LINE_BUFFERS, we can update to do so. > + */ > + if (!in_nmi() && !cmpxchg(&buffer_users_report_scheduled, 0, 1)) > + queue_work(system_unbound_wq, &work); Please, add a comment that buffer_users_report_scheduled is never cleared by intention. > +#elif defined(CONFIG_STACKTRACE) The warning should not depend on CONFIG_STACKTRACE. It is enough that CONFIG_DEBUG_PRINTK_BUFFERED depends on it. > + printk_once("Out of printk buffers. Please consider > CONFIG_DEBUG_PRINTK_BUFFERED=y\n"); pr_warn_once() > +#endif > +} > + > +/** > + * get_printk_buffer - Try to get printk_buffer. > + * > + * Returns pointer to "struct printk_buffer" on success, NULL otherwise. > + * > + * If this function returned "struct printk_buffer", the caller is > responsible > + * for passing it to put_printk_buffer() so that "struct printk_buffer" can > be > + * reused in the future. > + * > + * Even if this function returned NULL, the caller does not need to check for > + * NULL, for passing NULL to printk_buffered() simply acts like normal > printk() > + * and passing NULL to flush_printk_buffer()/put_printk_buffer() is a no-op. > + */ > +struct printk_buffer *get_printk_buffer(void) > +{ > + long i; > + > + for (i = 0; i < NUM_LINE_BUFFERS; i++) { > + if (test_and_set_bit_lock(i, printk_buffers_in_use)) > + continue; > + printk_buffers[i].used = 0; nit: I tend to get confused by the meaning of buffer.used vs. printk_buffers_in_use bit. Please, use ".len" instead. It is used for this purpose, for example, in struct seq_buf or struct cont. > + save_caller_info(i); > + return &printk_buffers[i]; > + } > + dump_caller_info(); > + return NULL; > +} > +EXPORT_SYMBOL(get_printk_buffer); > + > +/** > + * vprintk_buffered - Try to vprintk() in line buffered mode. > + * > + * @ptr: Pointer to "struct printk_buffer". It can be NULL. > + * @fmt: printk() format string. > + * @args: va_list structure. > + * > + * Returns the return value of vprintk(). > + * > + * Try to store to @ptr first. If it fails, flush @ptr and then try to store > to > + * @ptr again. If it still fails, use unbuffered printing. > + */ > +int vprintk_buffered(struct printk_buffer *ptr, const char *fmt, va_list > args) > +{ > + va_list tmp_args; > + int fmt_offset; > + int r; > + > + if (!ptr) > + goto unbuffered; nit: We could directly return vprintk(fmt, args). > + /* > + * Skip KERN_CONT here based on an assumption that KERN_CONT will be > + * given via "fmt" argument when KERN_CONT is given. > + */ > + fmt_offset = (printk_get_level(fmt) == 'c') ? 2 : 0; > + retry: > + va_copy(tmp_args, args); > + r = vsnprintf(ptr->buf + ptr->used, sizeof(ptr->buf) - ptr->used, > + fmt + fmt_offset, tmp_args); > + va_end(tmp_args); > + if (r + ptr->used < sizeof(ptr->buf)) { > + ptr->used += r; > + /* Flush already completed lines if any. */ > + for (r = ptr->used - 1; r >= 0; r--) { > + if (ptr->buf[r] != '\n') > + continue; I thought about using strrchr(). But this is more effective because we know the length of the string. It might deserve a comment though. > + ptr->buf[r++] = '\0'; > + printk("%s\n", ptr->buf); > + ptr->used -= r; > + memmove(ptr->buf, ptr->buf + r, ptr->used); This does not copy the trailing '\0'. I know that you enter it in flush_printk_buffer() but it looks rather error prone when modifying or debugging the code in the future. > + break; > + } > + return r; We need to use another variable in the for-cycle. Otherwise, we would not return the number of printed characters here. > + } > + /* > + * Since this "ptr" is dedicated to the caller, there is no possibility > + * of retrying more than once in one vprintk_buffered() call. > + */ > + if (flush_printk_buffer(ptr)) > + goto retry; nit: I would personally invert the logic and move this above. The following might be even more readable. if (ptr->used && ptr->used + r >= sizeof(ptr->buf)) { flush_printk_buffer(ptr); goto retry; } Then we could continue with flushing complete lines. > + unbuffered: > + return vprintk(fmt, args); > +} > + [...] > +/** > + * flush_printk_buffer - Flush incomplete line in printk_buffer. > + * > + * @ptr: Pointer to "struct printk_buffer". It can be NULL. > + * > + * Returns true if flushed something, false otherwise. > + * > + * Flush if @ptr contains partial data. But usually there is no need to call > + * this function because @ptr is flushed by put_printk_buffer(). > + */ > +bool flush_printk_buffer(struct printk_buffer *ptr) > +{ > + if (!ptr || !ptr->used) > + return false; > + /* vprintk_buffered() keeps 0 <= ptr->used < sizeof(ptr->buf) true. */ > + ptr->buf[ptr->used] = '\0'; We do not need this when there is always the trailing '\0' in non-empty buffer. It looks more sane to me. > + printk("%s", ptr->buf); > + ptr->used = 0; > + return true; > +} > +EXPORT_SYMBOL(flush_printk_buffer); We are getting close. Please, split the debugging stuff into separate patch. Also it would be great to do add a sample conversion from pr_cont() to this API in another separate patch. Thanks for working on it. Best Regards, Petr
