Replace the existing ringbuffer usage and implementation with
lockless ringbuffer usage. Even though the new ringbuffer does not
require locking, all existing locking is left in place. Therefore,
this change is purely replacing the underlining ringbuffer.
Changes that exist due to the ringbuffer replacement:
- The VMCOREINFO has been updated for the new structures.
- Dictionary data is now stored in a separate data buffer from the
human-readable messages. The dictionary data buffer is set to the
same size as the message buffer. Therefore, the total required
memory for both dictionary and message data is
2 * (2 ^ CONFIG_LOG_BUF_SHIFT) for the initial static buffers and
2 * log_buf_len (the kernel parameter) for the dynamic buffers.
- Record meta-data is now stored in a separate array of descriptors.
This is an additional 72 * (2 ^ (CONFIG_LOG_BUF_SHIFT - 5)) bytes
for the static array and 72 * (log_buf_len >> 5) bytes for the
dynamic array.
Signed-off-by: John Ogness <[email protected]>
Reviewed-by: Petr Mladek <[email protected]>
---
kernel/printk/printk.c | 940 +++++++++++++++++++++--------------------
1 file changed, 493 insertions(+), 447 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1b41e1b98221..fec71229169e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -55,6 +55,7 @@
#define CREATE_TRACE_POINTS
#include <trace/events/printk.h>
+#include "printk_ringbuffer.h"
#include "console_cmdline.h"
#include "braille.h"
#include "internal.h"
@@ -294,30 +295,24 @@ enum con_msg_format_flags {
static int console_msg_format = MSG_FORMAT_DEFAULT;
/*
- * The printk log buffer consists of a chain of concatenated variable
- * length records. Every record starts with a record header, containing
- * the overall length of the record.
+ * The printk log buffer consists of a sequenced collection of records, each
+ * containing variable length message and dictionary text. Every record
+ * also contains its own meta-data (@info).
*
- * The heads to the first and last entry in the buffer, as well as the
- * sequence numbers of these entries are maintained when messages are
- * stored.
+ * Every record meta-data carries the timestamp in microseconds, as well as
+ * the standard userspace syslog level and syslog facility. The usual kernel
+ * messages use LOG_KERN; userspace-injected messages always carry a matching
+ * syslog facility, by default LOG_USER. The origin of every message can be
+ * reliably determined that way.
*
- * If the heads indicate available messages, the length in the header
- * tells the start next message. A length == 0 for the next message
- * indicates a wrap-around to the beginning of the buffer.
+ * The human readable log message of a record is available in @text, the
+ * length of the message text in @text_len. The stored message is not
+ * terminated.
*
- * Every record carries the monotonic timestamp in microseconds, as well as
- * the standard userspace syslog level and syslog facility. The usual
- * kernel messages use LOG_KERN; userspace-injected messages always carry
- * a matching syslog facility, by default LOG_USER. The origin of every
- * message can be reliably determined that way.
- *
- * The human readable log message directly follows the message header. The
- * length of the message text is stored in the header, the stored message
- * is not terminated.
- *
- * Optionally, a message can carry a dictionary of properties (key/value pairs),
- * to provide userspace with a machine-readable message context.
+ * Optionally, a record can carry a dictionary of properties (key/value
+ * pairs), to provide userspace with a machine-readable message context. The
+ * length of the dictionary is available in @dict_len. The dictionary is not
+ * terminated.
*
* Examples for well-defined, commonly used property names are:
* DEVICE=b12:8 device identifier
@@ -331,21 +326,19 @@ static int console_msg_format = MSG_FORMAT_DEFAULT;
* follows directly after a '=' character. Every property is terminated by
* a '\0' character. The last property is not terminated.
*
- * Example of a message structure:
- * 0000 ff 8f 00 00 00 00 00 00 monotonic time in nsec
- * 0008 34 00 record is 52 bytes long
- * 000a 0b 00 text is 11 bytes long
- * 000c 1f 00 dictionary is 23 bytes long
- * 000e 03 00 LOG_KERN (facility) LOG_ERR (level)
- * 0010 69 74 27 73 20 61 20 6c "it's a l"
- * 69 6e 65 "ine"
- * 001b 44 45 56 49 43 "DEVIC"
- * 45 3d 62 38 3a 32 00 44 "E=b8:2\0D"
- * 52 49 56 45 52 3d 62 75 "RIVER=bu"
- * 67 "g"
- * 0032 00 00 00 padding to next message header
- *
- * The 'struct printk_log' buffer header must never be directly exported to
+ * Example of record values:
+ * record.text_buf = "it's a line" (unterminated)
+ * record.dict_buf = "DEVICE=b8:2\0DRIVER=bug" (unterminated)
+ * record.info.seq = 56
+ * record.info.ts_nsec = 36863
+ * record.info.text_len = 11
+ * record.info.dict_len = 22
+ * record.info.facility = 0 (LOG_KERN)
+ * record.info.flags = 0
+ * record.info.level = 3 (LOG_ERR)
+ * record.info.caller_id = 299 (task 299)
+ *
+ * The 'struct printk_info' buffer must never be directly exported to
* userspace, it is a kernel-private implementation detail that might
* need to be changed in the future, when the requirements change.
*
@@ -365,23 +358,6 @@ enum log_flags {
LOG_CONT = 8, /* text is a fragment of a continuation line */
};
-struct printk_log {
- u64 ts_nsec; /* timestamp in nanoseconds */
- u16 len; /* length of entire record */
- u16 text_len; /* length of text buffer */
- u16 dict_len; /* length of dictionary buffer */
- u8 facility; /* syslog facility */
- u8 flags:5; /* internal record flags */
- u8 level:3; /* syslog level */
-#ifdef CONFIG_PRINTK_CALLER
- u32 caller_id; /* thread id or processor id */
-#endif
-}
-#ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
-__packed __aligned(4)
-#endif
-;
-
/*
* The logbuf_lock protects kmsg buffer, indices, counters. This can be taken
* within the scheduler's rq lock. It must be released before calling
@@ -421,26 +397,16 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
DECLARE_WAIT_QUEUE_HEAD(log_wait);
/* the next printk record to read by syslog(READ) or /proc/kmsg */
static u64 syslog_seq;
-static u32 syslog_idx;
static size_t syslog_partial;
static bool syslog_time;
-/* index and sequence number of the first record stored in the buffer */
-static u64 log_first_seq;
-static u32 log_first_idx;
-
-/* index and sequence number of the next record to store in the buffer */
-static u64 log_next_seq;
-static u32 log_next_idx;
-
/* the next printk record to write to the console */
static u64 console_seq;
-static u32 console_idx;
static u64 exclusive_console_stop_seq;
+static unsigned long console_dropped;
/* the next printk record to read after the last 'clear' command */
static u64 clear_seq;
-static u32 clear_idx;
#ifdef CONFIG_PRINTK_CALLER
#define PREFIX_MAX 48
@@ -453,13 +419,31 @@ static u32 clear_idx;
#define LOG_FACILITY(v) ((v) >> 3 & 0xff)
/* record buffer */
-#define LOG_ALIGN __alignof__(struct printk_log)
+#define LOG_ALIGN __alignof__(unsigned long)
#define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)
#define LOG_BUF_LEN_MAX (u32)(1 << 31)
static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
static char *log_buf = __log_buf;
static u32 log_buf_len = __LOG_BUF_LEN;
+/*
+ * Define the average message size. This only affects the number of
+ * descriptors that will be available. Underestimating is better than
+ * overestimating (too many available descriptors is better than not enough).
+ * The dictionary buffer will be the same size as the text buffer.
+ */
+#define PRB_AVGBITS 5 /* 32 character average length */
+
+#if CONFIG_LOG_BUF_SHIFT <= PRB_AVGBITS
+#error CONFIG_LOG_BUF_SHIFT value too small.
+#endif
+_DEFINE_PRINTKRB(printk_rb_static, CONFIG_LOG_BUF_SHIFT - PRB_AVGBITS,
+ PRB_AVGBITS, PRB_AVGBITS, &__log_buf[0]);
+
+static struct printk_ringbuffer printk_rb_dynamic;
+
+static struct printk_ringbuffer *prb = &printk_rb_static;
+
/*
* We cannot access per-CPU data (e.g. per-CPU flush irq_work) before
* per_cpu_areas are initialised. This variable is set to true when
@@ -484,108 +468,6 @@ u32 log_buf_len_get(void)
return log_buf_len;
}
-/* human readable text of the record */
-static char *log_text(const struct printk_log *msg)
-{
- return (char *)msg + sizeof(struct printk_log);
-}
-
-/* optional key/value pair dictionary attached to the record */
-static char *log_dict(const struct printk_log *msg)
-{
- return (char *)msg + sizeof(struct printk_log) + msg->text_len;
-}
-
-/* get record by index; idx must point to valid msg */
-static struct printk_log *log_from_idx(u32 idx)
-{
- struct printk_log *msg = (struct printk_log *)(log_buf + idx);
-
- /*
- * A length == 0 record is the end of buffer marker. Wrap around and
- * read the message at the start of the buffer.
- */
- if (!msg->len)
- return (struct printk_log *)log_buf;
- return msg;
-}
-
-/* get next record; idx must point to valid msg */
-static u32 log_next(u32 idx)
-{
- struct printk_log *msg = (struct printk_log *)(log_buf + idx);
-
- /* length == 0 indicates the end of the buffer; wrap */
- /*
- * A length == 0 record is the end of buffer marker. Wrap around and
- * read the message at the start of the buffer as *this* one, and
- * return the one after that.
- */
- if (!msg->len) {
- msg = (struct printk_log *)log_buf;
- return msg->len;
- }
- return idx + msg->len;
-}
-
-/*
- * Check whether there is enough free space for the given message.
- *
- * The same values of first_idx and next_idx mean that the buffer
- * is either empty or full.
- *
- * If the buffer is empty, we must respect the position of the indexes.
- * They cannot be reset to the beginning of the buffer.
- */
-static int logbuf_has_space(u32 msg_size, bool empty)
-{
- u32 free;
-
- if (log_next_idx > log_first_idx || empty)
- free = max(log_buf_len - log_next_idx, log_first_idx);
- else
- free = log_first_idx - log_next_idx;
-
- /*
- * We need space also for an empty header that signalizes wrapping
- * of the buffer.
- */
- return free >= msg_size + sizeof(struct printk_log);
-}
-
-static int log_make_free_space(u32 msg_size)
-{
- while (log_first_seq < log_next_seq &&
- !logbuf_has_space(msg_size, false)) {
- /* drop old messages until we have enough contiguous space */
- log_first_idx = log_next(log_first_idx);
- log_first_seq++;
- }
-
- if (clear_seq < log_first_seq) {
- clear_seq = log_first_seq;
- clear_idx = log_first_idx;
- }
-
- /* sequence numbers are equal, so the log buffer is empty */
- if (logbuf_has_space(msg_size, log_first_seq == log_next_seq))
- return 0;
-
- return -ENOMEM;
-}
-
-/* compute the message size including the padding bytes */
-static u32 msg_used_size(u16 text_len, u16 dict_len, u32 *pad_len)
-{
- u32 size;
-
- size = sizeof(struct printk_log) + text_len + dict_len;
- *pad_len = (-size) & (LOG_ALIGN - 1);
- size += *pad_len;
-
- return size;
-}
-
/*
* Define how much of the log buffer we could take at maximum. The value
* must be greater than two. Note that only half of the buffer is available
@@ -594,22 +476,23 @@ static u32 msg_used_size(u16 text_len, u16 dict_len, u32 *pad_len)
#define MAX_LOG_TAKE_PART 4
static const char trunc_msg[] = "<truncated>";
-static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
- u16 *dict_len, u32 *pad_len)
+static void truncate_msg(u16 *text_len, u16 *trunc_msg_len)
{
/*
* The message should not take the whole buffer. Otherwise, it might
* get removed too soon.
*/
u32 max_text_len = log_buf_len / MAX_LOG_TAKE_PART;
+
if (*text_len > max_text_len)
*text_len = max_text_len;
- /* enable the warning message */
+
+ /* enable the warning message (if there is room) */
*trunc_msg_len = strlen(trunc_msg);
- /* disable the "dict" completely */
- *dict_len = 0;
- /* compute the size again, count also the warning message */
- return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
+ if (*text_len >= *trunc_msg_len)
+ *text_len -= *trunc_msg_len;
+ else
+ *trunc_msg_len = 0;
}
/* insert record into the buffer, discard old ones, update heads */
@@ -618,60 +501,40 @@ static int log_store(u32 caller_id, int facility, int level,
const char *dict, u16 dict_len,
const char *text, u16 text_len)
{
- struct printk_log *msg;
- u32 size, pad_len;
+ struct prb_reserved_entry e;
+ struct printk_record r;
u16 trunc_msg_len = 0;
- /* number of '\0' padding bytes to next message */
- size = msg_used_size(text_len, dict_len, &pad_len);
+ prb_rec_init_wr(&r, text_len, dict_len);
- if (log_make_free_space(size)) {
+ if (!prb_reserve(&e, prb, &r)) {
/* truncate the message if it is too long for empty buffer */
- size = truncate_msg(&text_len, &trunc_msg_len,
- &dict_len, &pad_len);
+ truncate_msg(&text_len, &trunc_msg_len);
+ prb_rec_init_wr(&r, text_len + trunc_msg_len, dict_len);
/* survive when the log buffer is too small for trunc_msg */
- if (log_make_free_space(size))
+ if (!prb_reserve(&e, prb, &r))
return 0;
}
- if (log_next_idx + size + sizeof(struct printk_log) > log_buf_len) {
- /*
- * This message + an additional empty header does not fit
- * at the end of the buffer. Add an empty header with len == 0
- * to signify a wrap around.
- */
- memset(log_buf + log_next_idx, 0, sizeof(struct printk_log));
- log_next_idx = 0;
- }
-
/* fill message */
- msg = (struct printk_log *)(log_buf + log_next_idx);
- memcpy(log_text(msg), text, text_len);
- msg->text_len = text_len;
- if (trunc_msg_len) {
- memcpy(log_text(msg) + text_len, trunc_msg, trunc_msg_len);
- msg->text_len += trunc_msg_len;
- }
- memcpy(log_dict(msg), dict, dict_len);
- msg->dict_len = dict_len;
- msg->facility = facility;
- msg->level = level & 7;
- msg->flags = flags & 0x1f;
+ memcpy(&r.text_buf[0], text, text_len);
+ if (trunc_msg_len)
+ memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len);
+ if (r.dict_buf)
+ memcpy(&r.dict_buf[0], dict, dict_len);
+ r.info->facility = facility;
+ r.info->level = level & 7;
+ r.info->flags = flags & 0x1f;
if (ts_nsec > 0)
- msg->ts_nsec = ts_nsec;
+ r.info->ts_nsec = ts_nsec;
else
- msg->ts_nsec = local_clock();
-#ifdef CONFIG_PRINTK_CALLER
- msg->caller_id = caller_id;
-#endif
- memset(log_dict(msg) + dict_len, 0, pad_len);
- msg->len = size;
+ r.info->ts_nsec = local_clock();
+ r.info->caller_id = caller_id;
/* insert message */
- log_next_idx += msg->len;
- log_next_seq++;
+ prb_commit(&e);
- return msg->text_len;
+ return (text_len + trunc_msg_len);
}
int dmesg_restrict = IS_ENABLED(CONFIG_SECURITY_DMESG_RESTRICT);
@@ -723,13 +586,13 @@ static void append_char(char **pp, char *e, char c)
*(*pp)++ = c;
}
-static ssize_t msg_print_ext_header(char *buf, size_t size,
- struct printk_log *msg, u64 seq)
+static ssize_t info_print_ext_header(char *buf, size_t size,
+ struct printk_info *info)
{
- u64 ts_usec = msg->ts_nsec;
+ u64 ts_usec = info->ts_nsec;
char caller[20];
#ifdef CONFIG_PRINTK_CALLER
- u32 id = msg->caller_id;
+ u32 id = info->caller_id;
snprintf(caller, sizeof(caller), ",caller=%c%u",
id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
@@ -740,8 +603,8 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
do_div(ts_usec, 1000);
return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",
- (msg->facility << 3) | msg->level, seq, ts_usec,
- msg->flags & LOG_CONT ? 'c' : '-', caller);
+ (info->facility << 3) | info->level, info->seq,
+ ts_usec, info->flags & LOG_CONT ? 'c' : '-', caller);
}
static ssize_t msg_print_ext_body(char *buf, size_t size,
@@ -795,10 +658,14 @@ static ssize_t msg_print_ext_body(char *buf, size_t size,
/* /dev/kmsg - userspace message inject/listen interface */
struct devkmsg_user {
u64 seq;
- u32 idx;
struct ratelimit_state rs;
struct mutex lock;
char buf[CONSOLE_EXT_LOG_MAX];
+
+ struct printk_info info;
+ char text_buf[CONSOLE_EXT_LOG_MAX];
+ char dict_buf[CONSOLE_EXT_LOG_MAX];
+ struct printk_record record;
};
static __printf(3, 4) __cold
@@ -881,7 +748,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
size_t count, loff_t *ppos)
{
struct devkmsg_user *user = file->private_data;
- struct printk_log *msg;
+ struct printk_record *r = &user->record;
size_t len;
ssize_t ret;
@@ -893,7 +760,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
return ret;
logbuf_lock_irq();
- while (user->seq == log_next_seq) {
+ if (!prb_read_valid(prb, user->seq, r)) {
if (file->f_flags & O_NONBLOCK) {
ret = -EAGAIN;
logbuf_unlock_irq();
@@ -902,30 +769,26 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
logbuf_unlock_irq();
ret = wait_event_interruptible(log_wait,
- user->seq != log_next_seq);
+ prb_read_valid(prb, user->seq, r));
if (ret)
goto out;
logbuf_lock_irq();
}
- if (user->seq < log_first_seq) {
+ if (user->seq < prb_first_valid_seq(prb)) {
/* our last seen message is gone, return error and reset */
- user->idx = log_first_idx;
- user->seq = log_first_seq;
+ user->seq = prb_first_valid_seq(prb);
ret = -EPIPE;
logbuf_unlock_irq();
goto out;
}
- msg = log_from_idx(user->idx);
- len = msg_print_ext_header(user->buf, sizeof(user->buf),
- msg, user->seq);
+ len = info_print_ext_header(user->buf, sizeof(user->buf), r->info);
len += msg_print_ext_body(user->buf + len, sizeof(user->buf) - len,
- log_dict(msg), msg->dict_len,
- log_text(msg), msg->text_len);
+ &r->dict_buf[0], r->info->dict_len,
+ &r->text_buf[0], r->info->text_len);
- user->idx = log_next(user->idx);
- user->seq++;
+ user->seq = r->info->seq + 1;
logbuf_unlock_irq();
if (len > count) {
@@ -957,8 +820,7 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
switch (whence) {
case SEEK_SET:
/* the first record */
- user->idx = log_first_idx;
- user->seq = log_first_seq;
+ user->seq = prb_first_valid_seq(prb);
break;
case SEEK_DATA:
/*
@@ -966,13 +828,11 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
* like issued by 'dmesg -c'. Reading /dev/kmsg itself
* changes no global state, and does not clear anything.
*/
- user->idx = clear_idx;
user->seq = clear_seq;
break;
case SEEK_END:
/* after the last record */
- user->idx = log_next_idx;
- user->seq = log_next_seq;
+ user->seq = prb_next_seq(prb);
break;
default:
ret = -EINVAL;
@@ -992,9 +852,9 @@ static __poll_t devkmsg_poll(struct file *file, poll_table *wait)
poll_wait(file, &log_wait, wait);
logbuf_lock_irq();
- if (user->seq < log_next_seq) {
+ if (prb_read_valid(prb, user->seq, NULL)) {
/* return error when data has vanished underneath us */
- if (user->seq < log_first_seq)
+ if (user->seq < prb_first_valid_seq(prb))
ret = EPOLLIN|EPOLLRDNORM|EPOLLERR|EPOLLPRI;
else
ret = EPOLLIN|EPOLLRDNORM;
@@ -1029,9 +889,12 @@ static int devkmsg_open(struct inode *inode, struct file *file)
mutex_init(&user->lock);
+ prb_rec_init_rd(&user->record, &user->info,
+ &user->text_buf[0], sizeof(user->text_buf),
+ &user->dict_buf[0], sizeof(user->dict_buf));
+
logbuf_lock_irq();
- user->idx = log_first_idx;
- user->seq = log_first_seq;
+ user->seq = prb_first_valid_seq(prb);
logbuf_unlock_irq();
file->private_data = user;
@@ -1072,23 +935,52 @@ const struct file_operations kmsg_fops = {
*/
void log_buf_vmcoreinfo_setup(void)
{
- VMCOREINFO_SYMBOL(log_buf);
- VMCOREINFO_SYMBOL(log_buf_len);
- VMCOREINFO_SYMBOL(log_first_idx);
- VMCOREINFO_SYMBOL(clear_idx);
- VMCOREINFO_SYMBOL(log_next_idx);
+ VMCOREINFO_SYMBOL(prb);
+ VMCOREINFO_SYMBOL(printk_rb_static);
+ VMCOREINFO_SYMBOL(clear_seq);
+
/*
- * Export struct printk_log size and field offsets. User space tools can
+ * Export struct size and field offsets. User space tools can
* parse it and detect any changes to structure down the line.
*/
- VMCOREINFO_STRUCT_SIZE(printk_log);
- VMCOREINFO_OFFSET(printk_log, ts_nsec);
- VMCOREINFO_OFFSET(printk_log, len);
- VMCOREINFO_OFFSET(printk_log, text_len);
- VMCOREINFO_OFFSET(printk_log, dict_len);
-#ifdef CONFIG_PRINTK_CALLER
- VMCOREINFO_OFFSET(printk_log, caller_id);
-#endif
+
+ VMCOREINFO_STRUCT_SIZE(printk_ringbuffer);
+ VMCOREINFO_OFFSET(printk_ringbuffer, desc_ring);
+ VMCOREINFO_OFFSET(printk_ringbuffer, text_data_ring);
+ VMCOREINFO_OFFSET(printk_ringbuffer, dict_data_ring);
+ VMCOREINFO_OFFSET(printk_ringbuffer, fail);
+
+ VMCOREINFO_STRUCT_SIZE(prb_desc_ring);
+ VMCOREINFO_OFFSET(prb_desc_ring, count_bits);
+ VMCOREINFO_OFFSET(prb_desc_ring, descs);
+ VMCOREINFO_OFFSET(prb_desc_ring, head_id);
+ VMCOREINFO_OFFSET(prb_desc_ring, tail_id);
+
+ VMCOREINFO_STRUCT_SIZE(prb_desc);
+ VMCOREINFO_OFFSET(prb_desc, info);
+ VMCOREINFO_OFFSET(prb_desc, state_var);
+ VMCOREINFO_OFFSET(prb_desc, text_blk_lpos);
+ VMCOREINFO_OFFSET(prb_desc, dict_blk_lpos);
+
+ VMCOREINFO_STRUCT_SIZE(prb_data_blk_lpos);
+ VMCOREINFO_OFFSET(prb_data_blk_lpos, begin);
+ VMCOREINFO_OFFSET(prb_data_blk_lpos, next);
+
+ VMCOREINFO_STRUCT_SIZE(printk_info);
+ VMCOREINFO_OFFSET(printk_info, seq);
+ VMCOREINFO_OFFSET(printk_info, ts_nsec);
+ VMCOREINFO_OFFSET(printk_info, text_len);
+ VMCOREINFO_OFFSET(printk_info, dict_len);
+ VMCOREINFO_OFFSET(printk_info, caller_id);
+
+ VMCOREINFO_STRUCT_SIZE(prb_data_ring);
+ VMCOREINFO_OFFSET(prb_data_ring, size_bits);
+ VMCOREINFO_OFFSET(prb_data_ring, data);
+ VMCOREINFO_OFFSET(prb_data_ring, head_lpos);
+ VMCOREINFO_OFFSET(prb_data_ring, tail_lpos);
+
+ VMCOREINFO_SIZE(atomic_long_t);
+ VMCOREINFO_TYPE_OFFSET(atomic_long_t, counter);
}
#endif
@@ -1166,11 +1058,48 @@ static void __init set_percpu_data_ready(void)
__printk_percpu_data_ready = true;
}
+static unsigned int __init add_to_rb(struct printk_ringbuffer *rb,
+ struct printk_record *r)
+{
+ struct prb_reserved_entry e;
+ struct printk_record dest_r;
+
+ prb_rec_init_wr(&dest_r, r->info->text_len, r->info->dict_len);
+
+ if (!prb_reserve(&e, rb, &dest_r))
+ return 0;
+
+ memcpy(&dest_r.text_buf[0], &r->text_buf[0], dest_r.text_buf_size);
+ if (dest_r.dict_buf) {
+ memcpy(&dest_r.dict_buf[0], &r->dict_buf[0],
+ dest_r.dict_buf_size);
+ }
+ dest_r.info->facility = r->info->facility;
+ dest_r.info->level = r->info->level;
+ dest_r.info->flags = r->info->flags;
+ dest_r.info->ts_nsec = r->info->ts_nsec;
+ dest_r.info->caller_id = r->info->caller_id;
+
+ prb_commit(&e);
+
+ return prb_record_text_space(&e);
+}
+
+static char setup_text_buf[CONSOLE_EXT_LOG_MAX] __initdata;
+static char setup_dict_buf[CONSOLE_EXT_LOG_MAX] __initdata;
+
void __init setup_log_buf(int early)
{
+ unsigned int new_descs_count;
+ struct prb_desc *new_descs;
+ struct printk_info info;
+ struct printk_record r;
+ size_t new_descs_size;
unsigned long flags;
+ char *new_dict_buf;
char *new_log_buf;
unsigned int free;
+ u64 seq;
/*
* Some archs call setup_log_buf() multiple times - first is very
@@ -1189,21 +1118,70 @@ void __init setup_log_buf(int early)
if (!new_log_buf_len)
return;
+ new_descs_count = new_log_buf_len >> PRB_AVGBITS;
+ if (new_descs_count == 0) {
+ pr_err("new_log_buf_len: %lu too small\n", new_log_buf_len);
+ return;
+ }
+
new_log_buf = memblock_alloc(new_log_buf_len, LOG_ALIGN);
if (unlikely(!new_log_buf)) {
- pr_err("log_buf_len: %lu bytes not available\n",
- new_log_buf_len);
+ pr_err("log_buf_len: %lu text bytes not available\n",
+ new_log_buf_len);
return;
}
+ new_dict_buf = memblock_alloc(new_log_buf_len, LOG_ALIGN);
+ if (unlikely(!new_dict_buf)) {
+ pr_err("log_buf_len: %lu dict bytes not available\n",
+ new_log_buf_len);
+ memblock_free(__pa(new_log_buf), new_log_buf_len);
+ return;
+ }
+
+ new_descs_size = new_descs_count * sizeof(struct prb_desc);
+ new_descs = memblock_alloc(new_descs_size, LOG_ALIGN);
+ if (unlikely(!new_descs)) {
+ pr_err("log_buf_len: %zu desc bytes not available\n",
+ new_descs_size);
+ memblock_free(__pa(new_dict_buf), new_log_buf_len);
+ memblock_free(__pa(new_log_buf), new_log_buf_len);
+ return;
+ }
+
+ prb_rec_init_rd(&r, &info,
+ &setup_text_buf[0], sizeof(setup_text_buf),
+ &setup_dict_buf[0], sizeof(setup_dict_buf));
+
+ prb_init(&printk_rb_dynamic,
+ new_log_buf, ilog2(new_log_buf_len),
+ new_dict_buf, ilog2(new_log_buf_len),
+ new_descs, ilog2(new_descs_count));
+
logbuf_lock_irqsave(flags);
+
log_buf_len = new_log_buf_len;
log_buf = new_log_buf;
new_log_buf_len = 0;
- free = __LOG_BUF_LEN - log_next_idx;
- memcpy(log_buf, __log_buf, __LOG_BUF_LEN);
+
+ free = __LOG_BUF_LEN;
+ prb_for_each_record(0, &printk_rb_static, seq, &r)
+ free -= add_to_rb(&printk_rb_dynamic, &r);
+
+ /*
+ * This is early enough that everything is still running on the
+ * boot CPU and interrupts are disabled. So no new messages will
+ * appear during the transition to the dynamic buffer.
+ */
+ prb = &printk_rb_dynamic;
+
logbuf_unlock_irqrestore(flags);
+ if (seq != prb_next_seq(&printk_rb_static)) {
+ pr_err("dropped %llu messages\n",
+ prb_next_seq(&printk_rb_static) - seq);
+ }
+
pr_info("log_buf_len: %u bytes\n", log_buf_len);
pr_info("early log buf free: %u(%u%%)\n",
free, (free * 100) / __LOG_BUF_LEN);
@@ -1313,18 +1291,18 @@ static size_t print_caller(u32 id, char *buf)
#define print_caller(id, buf) 0
#endif
-static size_t print_prefix(const struct printk_log *msg, bool syslog,
- bool time, char *buf)
+static size_t info_print_prefix(const struct printk_info *info, bool syslog,
+ bool time, char *buf)
{
size_t len = 0;
if (syslog)
- len = print_syslog((msg->facility << 3) | msg->level, buf);
+ len = print_syslog((info->facility << 3) | info->level, buf);
if (time)
- len += print_time(msg->ts_nsec, buf + len);
+ len += print_time(info->ts_nsec, buf + len);
- len += print_caller(msg->caller_id, buf + len);
+ len += print_caller(info->caller_id, buf + len);
if (IS_ENABLED(CONFIG_PRINTK_CALLER) || time) {
buf[len++] = ' ';
@@ -1334,72 +1312,143 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog,
return len;
}
-static size_t msg_print_text(const struct printk_log *msg, bool syslog,
- bool time, char *buf, size_t size)
+/*
+ * Prepare the record for printing. The text is shifted within the given
+ * buffer to avoid a need for another one. The following operations are
+ * done:
+ *
+ * - Add prefix for each line.
+ * - Add the trailing newline that has been removed in vprintk_store().
+ * - Drop truncated lines that do not longer fit into the buffer.
+ *
+ * Return: The length of the updated/prepared text, including the added
+ * prefixes and the newline. The dropped line(s) are not counted.
+ */
+static size_t record_print_text(struct printk_record *r, bool syslog,
+ bool time)
{
- const char *text = log_text(msg);
- size_t text_size = msg->text_len;
- size_t len = 0;
+ size_t text_len = r->info->text_len;
+ size_t buf_size = r->text_buf_size;
+ char *text = r->text_buf;
char prefix[PREFIX_MAX];
- const size_t prefix_len = print_prefix(msg, syslog, time, prefix);
+ bool truncated = false;
+ size_t prefix_len;
+ size_t line_len;
+ size_t len = 0;
+ char *next;
- do {
- const char *next = memchr(text, '\n', text_size);
- size_t text_len;
+ prefix_len = info_print_prefix(r->info, syslog, time, prefix);
+ /*
+ * @text_len: bytes of unprocessed text
+ * @line_len: bytes of current line _without_ newline
+ * @text: pointer to beginning of current line
+ * @len: number of bytes prepared in r->text_buf
+ */
+ for (;;) {
+ next = memchr(text, '\n', text_len);
if (next) {
- text_len = next - text;
- next++;
- text_size -= next - text;
+ line_len = next - text;
} else {
- text_len = text_size;
+ /* Drop truncated line(s). */
+ if (truncated)
+ break;
+ line_len = text_len;
}
- if (buf) {
- if (prefix_len + text_len + 1 >= size - len)
+ /*
+ * Truncate the text if there is not enough space to add the
+ * prefix and a trailing newline.
+ */
+ if (len + prefix_len + text_len + 1 > buf_size) {
+ /* Drop even the current line if no space. */
+ if (len + prefix_len + line_len + 1 > buf_size)
break;
- memcpy(buf + len, prefix, prefix_len);
- len += prefix_len;
- memcpy(buf + len, text, text_len);
- len += text_len;
- buf[len++] = '\n';
- } else {
- /* SYSLOG_ACTION_* buffer size only calculation */
- len += prefix_len + text_len + 1;
+ text_len = buf_size - len - prefix_len - 1;
+ truncated = true;
}
- text = next;
- } while (text);
+ memmove(text + prefix_len, text, text_len);
+ memcpy(text, prefix, prefix_len);
+
+ len += prefix_len + line_len + 1;
+
+ if (text_len == line_len) {
+ /*
+ * Add the trailing newline removed in
+ * vprintk_store().
+ */
+ text[prefix_len + line_len] = '\n';
+ break;
+ }
+
+ /*
+ * Advance beyond the added prefix and the related line with
+ * its newline.
+ */
+ text += prefix_len + line_len + 1;
+
+ /*
+ * The remaining text has only decreased by the line with its
+ * newline.
+ *
+ * Note that @text_len can become zero. It happens when @text
+ * ended with a newline (either due to truncation or the
+ * original string ending with "\n\n"). The loop is correctly
+ * repeated and (if not truncated) an empty line with a prefix
+ * will be prepared.
+ */
+ text_len -= line_len + 1;
+ }
return len;
}
+static size_t get_record_print_text_size(struct printk_info *info,
+ unsigned int line_count,
+ bool syslog, bool time)
+{
+ char prefix[PREFIX_MAX];
+ size_t prefix_len;
+
+ prefix_len = info_print_prefix(info, syslog, time, prefix);
+
+ /*
+ * Each line will be preceded with a prefix. The intermediate
+ * newlines are already within the text, but a final trailing
+ * newline will be added.
+ */
+ return ((prefix_len * line_count) + info->text_len + 1);
+}
+
static int syslog_print(char __user *buf, int size)
{
+ struct printk_info info;
+ struct printk_record r;
char *text;
- struct printk_log *msg;
int len = 0;
text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
if (!text)
return -ENOMEM;
+ prb_rec_init_rd(&r, &info, text, LOG_LINE_MAX + PREFIX_MAX, NULL, 0);
+
while (size > 0) {
size_t n;
size_t skip;
logbuf_lock_irq();
- if (syslog_seq < log_first_seq) {
- /* messages are gone, move to first one */
- syslog_seq = log_first_seq;
- syslog_idx = log_first_idx;
- syslog_partial = 0;
- }
- if (syslog_seq == log_next_seq) {
+ if (!prb_read_valid(prb, syslog_seq, &r)) {
logbuf_unlock_irq();
break;
}
+ if (r.info->seq != syslog_seq) {
+ /* message is gone, move to next valid one */
+ syslog_seq = r.info->seq;
+ syslog_partial = 0;
+ }
/*
* To keep reading/counting partial line consistent,
@@ -1409,13 +1458,10 @@ static int syslog_print(char __user *buf, int size)
syslog_time = printk_time;
skip = syslog_partial;
- msg = log_from_idx(syslog_idx);
- n = msg_print_text(msg, true, syslog_time, text,
- LOG_LINE_MAX + PREFIX_MAX);
+ n = record_print_text(&r, true, syslog_time);
if (n - syslog_partial <= size) {
/* message fits into buffer, move forward */
- syslog_idx = log_next(syslog_idx);
- syslog_seq++;
+ syslog_seq = r.info->seq + 1;
n -= syslog_partial;
syslog_partial = 0;
} else if (!len){
@@ -1446,11 +1492,12 @@ static int syslog_print(char __user *buf, int size)
static int syslog_print_all(char __user *buf, int size, bool clear)
{
+ struct printk_info info;
+ unsigned int line_count;
+ struct printk_record r;
char *text;
int len = 0;
- u64 next_seq;
u64 seq;
- u32 idx;
bool time;
text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
@@ -1463,38 +1510,28 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
* Find first record that fits, including all following records,
* into the user-provided buffer for this dump.
*/
- seq = clear_seq;
- idx = clear_idx;
- while (seq < log_next_seq) {
- struct printk_log *msg = log_from_idx(idx);
-
- len += msg_print_text(msg, true, time, NULL, 0);
- idx = log_next(idx);
- seq++;
- }
+ prb_for_each_info(clear_seq, prb, seq, &info, &line_count)
+ len += get_record_print_text_size(&info, line_count, true, time);
/* move first record forward until length fits into the buffer */
- seq = clear_seq;
- idx = clear_idx;
- while (len > size && seq < log_next_seq) {
- struct printk_log *msg = log_from_idx(idx);
-
- len -= msg_print_text(msg, true, time, NULL, 0);
- idx = log_next(idx);
- seq++;
+ prb_for_each_info(clear_seq, prb, seq, &info, &line_count) {
+ if (len <= size)
+ break;
+ len -= get_record_print_text_size(&info, line_count, true, time);
}
- /* last message fitting into this dump */
- next_seq = log_next_seq;
+ prb_rec_init_rd(&r, &info, text, LOG_LINE_MAX + PREFIX_MAX, NULL, 0);
len = 0;
- while (len >= 0 && seq < next_seq) {
- struct printk_log *msg = log_from_idx(idx);
- int textlen = msg_print_text(msg, true, time, text,
- LOG_LINE_MAX + PREFIX_MAX);
+ prb_for_each_record(seq, prb, seq, &r) {
+ int textlen;
- idx = log_next(idx);
- seq++;
+ textlen = record_print_text(&r, true, time);
+
+ if (len + textlen > size) {
+ seq--;
+ break;
+ }
logbuf_unlock_irq();
if (copy_to_user(buf + len, text, textlen))
@@ -1503,17 +1540,12 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
len += textlen;
logbuf_lock_irq();
- if (seq < log_first_seq) {
- /* messages are gone, move to next one */
- seq = log_first_seq;
- idx = log_first_idx;
- }
+ if (len < 0)
+ break;
}
- if (clear) {
- clear_seq = log_next_seq;
- clear_idx = log_next_idx;
- }
+ if (clear)
+ clear_seq = seq;
logbuf_unlock_irq();
kfree(text);
@@ -1523,8 +1555,7 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
static void syslog_clear(void)
{
logbuf_lock_irq();
- clear_seq = log_next_seq;
- clear_idx = log_next_idx;
+ clear_seq = prb_next_seq(prb);
logbuf_unlock_irq();
}
@@ -1551,7 +1582,7 @@ int do_syslog(int type, char __user *buf, int len, int source)
if (!access_ok(buf, len))
return -EFAULT;
error = wait_event_interruptible(log_wait,
- syslog_seq != log_next_seq);
+ prb_read_valid(prb, syslog_seq, NULL));
if (error)
return error;
error = syslog_print(buf, len);
@@ -1600,10 +1631,9 @@ int do_syslog(int type, char __user *buf, int len, int source)
/* Number of chars in the log buffer */
case SYSLOG_ACTION_SIZE_UNREAD:
logbuf_lock_irq();
- if (syslog_seq < log_first_seq) {
+ if (syslog_seq < prb_first_valid_seq(prb)) {
/* messages are gone, move to first one */
- syslog_seq = log_first_seq;
- syslog_idx = log_first_idx;
+ syslog_seq = prb_first_valid_seq(prb);
syslog_partial = 0;
}
if (source == SYSLOG_FROM_PROC) {
@@ -1612,20 +1642,18 @@ int do_syslog(int type, char __user *buf, int len, int source)
* for pending data, not the size; return the count of
* records, not the length.
*/
- error = log_next_seq - syslog_seq;
+ error = prb_next_seq(prb) - syslog_seq;
} else {
- u64 seq = syslog_seq;
- u32 idx = syslog_idx;
bool time = syslog_partial ? syslog_time : printk_time;
-
- while (seq < log_next_seq) {
- struct printk_log *msg = log_from_idx(idx);
-
- error += msg_print_text(msg, true, time, NULL,
- 0);
+ struct printk_info info;
+ unsigned int line_count;
+ u64 seq;
+
+ prb_for_each_info(syslog_seq, prb, seq, &info,
+ &line_count) {
+ error += get_record_print_text_size(&info, line_count,
+ true, time);
time = printk_time;
- idx = log_next(idx);
- seq++;
}
error -= syslog_partial;
}
@@ -1796,10 +1824,22 @@ static int console_trylock_spinning(void)
static void call_console_drivers(const char *ext_text, size_t ext_len,
const char *text, size_t len)
{
+ static char dropped_text[64];
+ size_t dropped_len = 0;
struct console *con;
trace_console_rcuidle(text, len);
+ if (!console_drivers)
+ return;
+
+ if (console_dropped) {
+ dropped_len = snprintf(dropped_text, sizeof(dropped_text),
+ "** %lu printk messages dropped **\n",
+ console_dropped);
+ console_dropped = 0;
+ }
+
for_each_console(con) {
if (exclusive_console && con != exclusive_console)
continue;
@@ -1812,8 +1852,11 @@ static void call_console_drivers(const char *ext_text, size_t ext_len,
continue;
if (con->flags & CON_EXTENDED)
con->write(con, ext_text, ext_len);
- else
+ else {
+ if (dropped_len)
+ con->write(con, dropped_text, dropped_len);
con->write(con, text, len);
+ }
}
}
@@ -2076,21 +2119,24 @@ EXPORT_SYMBOL(printk);
#define PREFIX_MAX 0
#define printk_time false
+#define prb_read_valid(rb, seq, r) false
+#define prb_first_valid_seq(rb) 0
+
static u64 syslog_seq;
-static u32 syslog_idx;
static u64 console_seq;
-static u32 console_idx;
static u64 exclusive_console_stop_seq;
-static u64 log_first_seq;
-static u32 log_first_idx;
-static u64 log_next_seq;
-static char *log_text(const struct printk_log *msg) { return NULL; }
-static char *log_dict(const struct printk_log *msg) { return NULL; }
-static struct printk_log *log_from_idx(u32 idx) { return NULL; }
-static u32 log_next(u32 idx) { return 0; }
-static ssize_t msg_print_ext_header(char *buf, size_t size,
- struct printk_log *msg,
- u64 seq) { return 0; }
+static unsigned long console_dropped;
+
+static size_t record_print_text(const struct printk_record *r,
+ bool syslog, bool time)
+{
+ return 0;
+}
+static ssize_t info_print_ext_header(char *buf, size_t size,
+ struct printk_info *info)
+{
+ return 0;
+}
static ssize_t msg_print_ext_body(char *buf, size_t size,
char *dict, size_t dict_len,
char *text, size_t text_len) { return 0; }
@@ -2098,8 +2144,6 @@ static void console_lock_spinning_enable(void) { }
static int console_lock_spinning_disable_and_check(void) { return 0; }
static void call_console_drivers(const char *ext_text, size_t ext_len,
const char *text, size_t len) {}
-static size_t msg_print_text(const struct printk_log *msg, bool syslog,
- bool time, char *buf, size_t size) { return 0; }
static bool suppress_message_printing(int level) { return false; }
#endif /* CONFIG_PRINTK */
@@ -2384,14 +2428,19 @@ void console_unlock(void)
{
static char ext_text[CONSOLE_EXT_LOG_MAX];
static char text[LOG_LINE_MAX + PREFIX_MAX];
+ static char dict[LOG_LINE_MAX];
unsigned long flags;
bool do_cond_resched, retry;
+ struct printk_info info;
+ struct printk_record r;
if (console_suspended) {
up_console_sem();
return;
}
+ prb_rec_init_rd(&r, &info, text, sizeof(text), dict, sizeof(dict));
+
/*
* Console drivers are called with interrupts disabled, so
* @console_may_schedule should be cleared before; however, we may
@@ -2422,35 +2471,26 @@ void console_unlock(void)
}
for (;;) {
- struct printk_log *msg;
size_t ext_len = 0;
size_t len;
printk_safe_enter_irqsave(flags);
raw_spin_lock(&logbuf_lock);
- if (console_seq < log_first_seq) {
- len = snprintf(text, sizeof(text),
- "** %llu printk messages dropped **\n",
- log_first_seq - console_seq);
-
- /* messages are gone, move to first one */
- console_seq = log_first_seq;
- console_idx = log_first_idx;
- } else {
- len = 0;
- }
skip:
- if (console_seq == log_next_seq)
+ if (!prb_read_valid(prb, console_seq, &r))
break;
- msg = log_from_idx(console_idx);
- if (suppress_message_printing(msg->level)) {
+ if (console_seq != r.info->seq) {
+ console_dropped += r.info->seq - console_seq;
+ console_seq = r.info->seq;
+ }
+
+ if (suppress_message_printing(r.info->level)) {
/*
* Skip record we have buffered and already printed
* directly to the console when we received it, and
* record that has level above the console loglevel.
*/
- console_idx = log_next(console_idx);
console_seq++;
goto skip;
}
@@ -2461,19 +2501,24 @@ void console_unlock(void)
exclusive_console = NULL;
}
- len += msg_print_text(msg,
- console_msg_format & MSG_FORMAT_SYSLOG,
- printk_time, text + len, sizeof(text) - len);
+ /*
+ * Handle extended console text first because later
+ * record_print_text() will modify the record buffer in-place.
+ */
if (nr_ext_console_drivers) {
- ext_len = msg_print_ext_header(ext_text,
+ ext_len = info_print_ext_header(ext_text,
sizeof(ext_text),
- msg, console_seq);
+ r.info);
ext_len += msg_print_ext_body(ext_text + ext_len,
sizeof(ext_text) - ext_len,
- log_dict(msg), msg->dict_len,
- log_text(msg), msg->text_len);
+ &r.dict_buf[0],
+ r.info->dict_len,
+ &r.text_buf[0],
+ r.info->text_len);
}
- console_idx = log_next(console_idx);
+ len = record_print_text(&r,
+ console_msg_format & MSG_FORMAT_SYSLOG,
+ printk_time);
console_seq++;
raw_spin_unlock(&logbuf_lock);
@@ -2513,7 +2558,7 @@ void console_unlock(void)
* flush, no worries.
*/
raw_spin_lock(&logbuf_lock);
- retry = console_seq != log_next_seq;
+ retry = prb_read_valid(prb, console_seq, NULL);
raw_spin_unlock(&logbuf_lock);
printk_safe_exit_irqrestore(flags);
@@ -2582,8 +2627,7 @@ void console_flush_on_panic(enum con_flush_mode mode)
unsigned long flags;
logbuf_lock_irqsave(flags);
- console_seq = log_first_seq;
- console_idx = log_first_idx;
+ console_seq = prb_first_valid_seq(prb);
logbuf_unlock_irqrestore(flags);
}
console_unlock();
@@ -2826,7 +2870,6 @@ void register_console(struct console *newcon)
exclusive_console = newcon;
exclusive_console_stop_seq = console_seq;
console_seq = syslog_seq;
- console_idx = syslog_idx;
logbuf_unlock_irqrestore(flags);
}
console_unlock();
@@ -3215,9 +3258,7 @@ void kmsg_dump(enum kmsg_dump_reason reason)
logbuf_lock_irqsave(flags);
dumper->cur_seq = clear_seq;
- dumper->cur_idx = clear_idx;
- dumper->next_seq = log_next_seq;
- dumper->next_idx = log_next_idx;
+ dumper->next_seq = prb_next_seq(prb);
logbuf_unlock_irqrestore(flags);
/* invoke dumper which will iterate over records */
@@ -3251,28 +3292,33 @@ void kmsg_dump(enum kmsg_dump_reason reason)
bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog,
char *line, size_t size, size_t *len)
{
- struct printk_log *msg;
+ struct printk_info info;
+ unsigned int line_count;
+ struct printk_record r;
size_t l = 0;
bool ret = false;
+ prb_rec_init_rd(&r, &info, line, size, NULL, 0);
+
if (!dumper->active)
goto out;
- if (dumper->cur_seq < log_first_seq) {
- /* messages are gone, move to first available one */
- dumper->cur_seq = log_first_seq;
- dumper->cur_idx = log_first_idx;
- }
-
- /* last entry */
- if (dumper->cur_seq >= log_next_seq)
- goto out;
+ /* Read text or count text lines? */
+ if (line) {
+ if (!prb_read_valid(prb, dumper->cur_seq, &r))
+ goto out;
+ l = record_print_text(&r, syslog, printk_time);
+ } else {
+ if (!prb_read_valid_info(prb, dumper->cur_seq,
+ &info, &line_count)) {
+ goto out;
+ }
+ l = get_record_print_text_size(&info, line_count, syslog,
+ printk_time);
- msg = log_from_idx(dumper->cur_idx);
- l = msg_print_text(msg, syslog, printk_time, line, size);
+ }
- dumper->cur_idx = log_next(dumper->cur_idx);
- dumper->cur_seq++;
+ dumper->cur_seq = r.info->seq + 1;
ret = true;
out:
if (len)
@@ -3333,23 +3379,25 @@ EXPORT_SYMBOL_GPL(kmsg_dump_get_line);
bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
char *buf, size_t size, size_t *len)
{
+ struct printk_info info;
+ unsigned int line_count;
+ struct printk_record r;
unsigned long flags;
u64 seq;
- u32 idx;
u64 next_seq;
- u32 next_idx;
size_t l = 0;
bool ret = false;
bool time = printk_time;
- if (!dumper->active)
+ prb_rec_init_rd(&r, &info, buf, size, NULL, 0);
+
+ if (!dumper->active || !buf || !size)
goto out;
logbuf_lock_irqsave(flags);
- if (dumper->cur_seq < log_first_seq) {
+ if (dumper->cur_seq < prb_first_valid_seq(prb)) {
/* messages are gone, move to first available one */
- dumper->cur_seq = log_first_seq;
- dumper->cur_idx = log_first_idx;
+ dumper->cur_seq = prb_first_valid_seq(prb);
}
/* last entry */
@@ -3360,41 +3408,41 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
/* calculate length of entire buffer */
seq = dumper->cur_seq;
- idx = dumper->cur_idx;
- while (seq < dumper->next_seq) {
- struct printk_log *msg = log_from_idx(idx);
-
- l += msg_print_text(msg, true, time, NULL, 0);
- idx = log_next(idx);
- seq++;
+ while (prb_read_valid_info(prb, seq, &info, &line_count)) {
+ if (r.info->seq >= dumper->next_seq)
+ break;
+ l += get_record_print_text_size(&info, line_count, true, time);
+ seq = r.info->seq + 1;
}
/* move first record forward until length fits into the buffer */
seq = dumper->cur_seq;
- idx = dumper->cur_idx;
- while (l >= size && seq < dumper->next_seq) {
- struct printk_log *msg = log_from_idx(idx);
-
- l -= msg_print_text(msg, true, time, NULL, 0);
- idx = log_next(idx);
- seq++;
+ while (l >= size && prb_read_valid_info(prb, seq,
+ &info, &line_count)) {
+ if (r.info->seq >= dumper->next_seq)
+ break;
+ l -= get_record_print_text_size(&info, line_count, true, time);
+ seq = r.info->seq + 1;
}
/* last message in next interation */
next_seq = seq;
- next_idx = idx;
+ /* actually read text into the buffer now */
l = 0;
- while (seq < dumper->next_seq) {
- struct printk_log *msg = log_from_idx(idx);
+ while (prb_read_valid(prb, seq, &r)) {
+ if (r.info->seq >= dumper->next_seq)
+ break;
+
+ l += record_print_text(&r, syslog, time);
+
+ /* adjust record to store to remaining buffer space */
+ prb_rec_init_rd(&r, &info, buf + l, size - l, NULL, 0);
- l += msg_print_text(msg, syslog, time, buf + l, size - l);
- idx = log_next(idx);
- seq++;
+ seq = r.info->seq + 1;
}
dumper->next_seq = next_seq;
- dumper->next_idx = next_idx;
ret = true;
logbuf_unlock_irqrestore(flags);
out:
@@ -3417,9 +3465,7 @@ EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper)
{
dumper->cur_seq = clear_seq;
- dumper->cur_idx = clear_idx;
- dumper->next_seq = log_next_seq;
- dumper->next_idx = log_next_idx;
+ dumper->next_seq = prb_next_seq(prb);
}
/**
--
2.20.1
Greeting,
FYI, we noticed a 8.3% improvement of stress-ng.timerfd.ops_per_sec due to commit:
commit: 96d5c61b1fff364edfae607e2bf2a66ee9616ff2 ("[PATCH v5 4/4] printk: use the lockless ringbuffer")
url: https://github.com/0day-ci/linux/commits/John-Ogness/printk-replace-ringbuffer/20200709-212623
base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git 9ebcfadb0610322ac537dd7aa5d9cbc2b2894c68
in testcase: stress-ng
on test machine: 96 threads Intel(R) Xeon(R) Gold 6252 CPU @ 2.10GHz with 256G memory
with following parameters:
nr_threads: 100%
disk: 1HDD
testtime: 30s
class: interrupt
cpufreq_governor: performance
ucode: 0x5002f01
Details are as below:
-------------------------------------------------------------------------------------------------->
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp install job.yaml # job file is attached in this email
bin/lkp run job.yaml
=========================================================================================
class/compiler/cpufreq_governor/disk/kconfig/nr_threads/rootfs/tbox_group/testcase/testtime/ucode:
interrupt/gcc-9/performance/1HDD/x86_64-rhel-8.3/100%/debian-10.4-x86_64-20200603.cgz/lkp-csl-2sp6/stress-ng/30s/0x5002f01
commit:
72621a0b10 ("Revert "printk: lock/unlock console only for new logbuf entries"")
96d5c61b1f ("printk: use the lockless ringbuffer")
72621a0b1077a8ad 96d5c61b1fff364edfae607e2bf
---------------- ---------------------------
%stddev %change %stddev
\ | \
2.274e+08 +18.6% 2.697e+08 stress-ng.sigq.ops
7580582 +18.6% 8991276 stress-ng.sigq.ops_per_sec
1.513e+08 ± 5% -8.3% 1.387e+08 ± 2% stress-ng.time.involuntary_context_switches
3.768e+08 ± 3% -5.9% 3.544e+08 ± 2% stress-ng.time.voluntary_context_switches
1.598e+09 ± 2% +8.3% 1.73e+09 stress-ng.timerfd.ops
53265971 ± 2% +8.3% 57674750 stress-ng.timerfd.ops_per_sec
3.716e+08 ± 2% +10.7% 4.115e+08 ± 3% cpuidle.C1.time
174505 ± 10% -14.5% 149157 ± 13% numa-meminfo.node0.AnonHugePages
32959 +2.1% 33668 proc-vmstat.nr_slab_reclaimable
90647 ± 43% -60.2% 36039 ±124% numa-vmstat.node0.numa_other
71315 ± 55% +76.4% 125804 ± 35% numa-vmstat.node1.numa_other
1075081 ± 3% -5.6% 1014755 vmstat.system.cs
3762322 +4.7% 3940838 vmstat.system.in
61530 ± 3% -12.1% 54104 ± 4% slabinfo.Acpi-State.active_objs
1209 ± 3% -11.9% 1065 ± 4% slabinfo.Acpi-State.active_slabs
61710 ± 3% -11.9% 54359 ± 4% slabinfo.Acpi-State.num_objs
1209 ± 3% -11.9% 1065 ± 4% slabinfo.Acpi-State.num_slabs
47136 ± 5% +6.0% 49962 ± 6% softirqs.CPU11.SCHED
45028 ± 2% +22.3% 55067 ± 10% softirqs.CPU16.SCHED
44744 ± 2% +22.1% 54634 ± 5% softirqs.CPU19.SCHED
45345 ± 2% +20.7% 54736 ± 8% softirqs.CPU23.SCHED
51163 ± 8% -10.2% 45932 softirqs.CPU30.SCHED
50701 ± 9% -10.2% 45552 softirqs.CPU36.SCHED
50848 ± 3% -11.0% 45253 softirqs.CPU41.SCHED
46949 ± 6% +17.2% 55030 ± 4% softirqs.CPU51.SCHED
45567 ± 2% +15.4% 52589 ± 11% softirqs.CPU55.SCHED
45734 +13.5% 51922 ± 9% softirqs.CPU64.SCHED
45342 +15.4% 52344 ± 5% softirqs.CPU67.SCHED
45901 +13.4% 52030 ± 9% softirqs.CPU68.SCHED
45578 +16.8% 53235 ± 7% softirqs.CPU69.SCHED
50784 ± 8% -9.3% 46080 softirqs.CPU77.SCHED
1187223 ± 26% -47.3% 626108 ± 43% sched_debug.cfs_rq:/.MIN_vruntime.avg
44095 ± 13% -37.3% 27628 ± 16% sched_debug.cfs_rq:/.load.avg
87004 ± 2% -24.3% 65828 ± 13% sched_debug.cfs_rq:/.load.stddev
1187223 ± 26% -47.3% 626108 ± 43% sched_debug.cfs_rq:/.max_vruntime.avg
87.24 ± 10% -17.7% 71.80 ± 7% sched_debug.cfs_rq:/.nr_spread_over.avg
10.92 ± 8% -25.6% 8.12 ± 10% sched_debug.cfs_rq:/.nr_spread_over.min
95.86 ± 12% -15.1% 81.42 ± 9% sched_debug.cfs_rq:/.nr_spread_over.stddev
133.70 ± 30% -81.5% 24.68 ±173% sched_debug.cfs_rq:/.removed.load_avg.max
58.28 ± 25% -80.1% 11.62 ±173% sched_debug.cfs_rq:/.removed.runnable_avg.max
6.81 ± 25% -77.8% 1.51 ±173% sched_debug.cfs_rq:/.removed.runnable_avg.stddev
744305 ± 35% -57.0% 319901 ± 93% sched_debug.cfs_rq:/.spread0.avg
27562 ± 8% -48.5% 14191 ± 13% sched_debug.cpu.curr->pid.avg
35526 ± 5% -42.5% 20423 ± 11% sched_debug.cpu.curr->pid.max
14383 ± 47% -55.9% 6346 ± 36% sched_debug.cpu.curr->pid.min
39.65 ± 4% +16.5% 46.19 ± 7% sched_debug.cpu.nr_running.avg
1.17 ± 25% -76.2% 0.28 ±163% sched_debug.cpu.nr_uninterruptible.avg
3769782 ± 4% -8.4% 3451639 ± 3% sched_debug.cpu.sched_count.max
0.00 +2.2e+104% 216.75 ±138% interrupts.102:PCI-MSI.31981635-edge.i40e-eth0-TxRx-66
8246728 ± 4% +7.0% 8826785 interrupts.CAL:Function_call_interrupts
65853 ± 7% +35.4% 89155 ± 18% interrupts.CPU19.CAL:Function_call_interrupts
133669 ± 7% +79.6% 240043 ± 33% interrupts.CPU19.RES:Rescheduling_interrupts
85710 ± 6% +13.6% 97401 interrupts.CPU32.CAL:Function_call_interrupts
201257 ± 3% -12.8% 175586 ± 4% interrupts.CPU42.RES:Rescheduling_interrupts
7732 -38.0% 4798 ± 34% interrupts.CPU45.NMI:Non-maskable_interrupts
7732 -38.0% 4798 ± 34% interrupts.CPU45.PMI:Performance_monitoring_interrupts
197808 ± 4% -7.1% 183824 ± 6% interrupts.CPU46.RES:Rescheduling_interrupts
149600 ± 16% +70.4% 254923 ± 25% interrupts.CPU54.RES:Rescheduling_interrupts
150479 ± 16% +64.7% 247795 ± 37% interrupts.CPU57.RES:Rescheduling_interrupts
150695 ± 16% +48.9% 224356 ± 22% interrupts.CPU60.RES:Rescheduling_interrupts
60718 ± 6% +18.7% 72058 ± 3% interrupts.CPU62.CAL:Function_call_interrupts
68390 ± 4% +20.6% 82506 ± 10% interrupts.CPU63.CAL:Function_call_interrupts
0.00 +2.2e+104% 216.25 ±138% interrupts.CPU66.102:PCI-MSI.31981635-edge.i40e-eth0-TxRx-66
62888 ± 4% +22.3% 76902 ± 8% interrupts.CPU7.CAL:Function_call_interrupts
62071 ± 10% +29.5% 80355 ± 10% interrupts.CPU71.CAL:Function_call_interrupts
231484 ± 21% -25.0% 173696 ± 3% interrupts.CPU75.RES:Rescheduling_interrupts
234587 ± 12% -17.0% 194613 ± 13% interrupts.CPU77.RES:Rescheduling_interrupts
209574 ± 3% -15.0% 178038 ± 4% interrupts.CPU83.RES:Rescheduling_interrupts
87531 ± 4% +31.1% 114721 ± 7% interrupts.CPU88.CAL:Function_call_interrupts
7732 -37.8% 4806 ± 34% interrupts.CPU89.NMI:Non-maskable_interrupts
7732 -37.8% 4806 ± 34% interrupts.CPU89.PMI:Performance_monitoring_interrupts
94766 ± 7% +19.1% 112844 ± 10% interrupts.CPU91.CAL:Function_call_interrupts
91308 ± 6% +22.9% 112175 ± 8% interrupts.CPU92.CAL:Function_call_interrupts
87571 ± 11% +31.6% 115238 ± 14% interrupts.CPU94.CAL:Function_call_interrupts
7.54 +13.5% 8.56 ± 19% perf-stat.i.MPKI
1.312e+10 -2.8% 1.276e+10 perf-stat.i.branch-instructions
1.246e+08 -1.4% 1.228e+08 perf-stat.i.branch-misses
71092689 ± 3% -19.7% 57085156 ± 2% perf-stat.i.cache-misses
2.672e+08 -10.2% 2.4e+08 perf-stat.i.cache-references
100471 -4.4% 96054 perf-stat.i.cpu-clock
2.436e+11 -5.8% 2.295e+11 perf-stat.i.cpu-cycles
28918 ± 2% +8.8% 31448 ± 2% perf-stat.i.cycles-between-cache-misses
0.03 ± 5% +0.0 0.05 ± 68% perf-stat.i.dTLB-load-miss-rate%
3585193 ± 5% -17.4% 2960337 ± 3% perf-stat.i.dTLB-load-misses
0.06 +0.0 0.06 ± 11% perf-stat.i.dTLB-store-miss-rate%
6767973 -6.1% 6356168 ± 2% perf-stat.i.dTLB-store-misses
1.05e+10 -1.4% 1.036e+10 perf-stat.i.dTLB-stores
7143251 ± 4% -7.7% 6593711 ± 2% perf-stat.i.iTLB-loads
6.422e+10 -2.4% 6.265e+10 perf-stat.i.instructions
2.55 -2.7% 2.48 perf-stat.i.metric.GHz
0.63 ± 3% +10.7% 0.70 ± 5% perf-stat.i.metric.K/sec
92744 -3.1% 89912 perf-stat.i.minor-faults
87.88 -1.4 86.43 perf-stat.i.node-load-miss-rate%
8868728 ± 13% -46.6% 4739379 ± 3% perf-stat.i.node-loads
94.74 -3.0 91.76 ± 2% perf-stat.i.node-store-miss-rate%
2508354 ± 11% -33.3% 1673742 perf-stat.i.node-stores
691526 -1.6% 680596 perf-stat.i.page-faults
99599 -3.6% 96043 perf-stat.i.task-clock
4.23 -4.5% 4.04 perf-stat.overall.MPKI
0.95 +0.0 0.96 perf-stat.overall.branch-miss-rate%
3.84 -2.4% 3.74 perf-stat.overall.cpi
0.02 ± 3% -0.0 0.02 ± 2% perf-stat.overall.dTLB-load-miss-rate%
0.06 -0.0 0.06 ± 2% perf-stat.overall.dTLB-store-miss-rate%
0.26 +2.5% 0.27 perf-stat.overall.ipc
47.96 +4.3 52.28 ± 3% perf-stat.overall.node-load-miss-rate%
70.13 +2.3 72.43 ± 2% perf-stat.overall.node-store-miss-rate%
1.232e+10 +2.0% 1.257e+10 perf-stat.ps.branch-instructions
1.166e+08 +3.3% 1.205e+08 perf-stat.ps.branch-misses
67786783 -5.2% 64234227 ± 4% perf-stat.ps.cache-misses
1078561 ± 3% -5.5% 1019000 perf-stat.ps.context-switches
1.714e+10 +2.3% 1.753e+10 perf-stat.ps.dTLB-loads
9.794e+09 +2.6% 1.005e+10 perf-stat.ps.dTLB-stores
87676758 +4.4% 91553262 perf-stat.ps.iTLB-load-misses
6.02e+10 +2.2% 6.15e+10 perf-stat.ps.instructions
9026151 -12.8% 7873090 ± 10% perf-stat.ps.node-loads
2511686 -9.8% 2265767 ± 6% perf-stat.ps.node-stores
642630 +1.6% 652856 perf-stat.ps.page-faults
3.27e+13 +2.2% 3.341e+13 perf-stat.total.instructions
26.27 ± 2% -2.7 23.56 ± 2% perf-profile.calltrace.cycles-pp.security_task_kill.group_send_sig_info.kill_pid_info.do_rt_sigqueueinfo.__x64_sys_rt_sigqueueinfo
26.23 ± 2% -2.7 23.52 ± 2% perf-profile.calltrace.cycles-pp.apparmor_task_kill.security_task_kill.group_send_sig_info.kill_pid_info.do_rt_sigqueueinfo
26.45 ± 2% -2.7 23.74 ± 2% perf-profile.calltrace.cycles-pp.group_send_sig_info.kill_pid_info.do_rt_sigqueueinfo.__x64_sys_rt_sigqueueinfo.do_syscall_64
13.52 ± 2% -2.4 11.11 ± 2% perf-profile.calltrace.cycles-pp.aa_get_task_label.apparmor_task_kill.security_task_kill.group_send_sig_info.kill_pid_info
47.08 -2.4 44.67 perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe
47.16 -2.4 44.76 perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe
46.12 -2.3 43.82 perf-profile.calltrace.cycles-pp.kill_pid_info.do_rt_sigqueueinfo.__x64_sys_rt_sigqueueinfo.do_syscall_64.entry_SYSCALL_64_after_hwframe
46.36 -2.3 44.07 perf-profile.calltrace.cycles-pp.do_rt_sigqueueinfo.__x64_sys_rt_sigqueueinfo.do_syscall_64.entry_SYSCALL_64_after_hwframe
46.71 -2.3 44.43 perf-profile.calltrace.cycles-pp.__x64_sys_rt_sigqueueinfo.do_syscall_64.entry_SYSCALL_64_after_hwframe
2.99 ± 14% -1.0 1.98 ± 14% perf-profile.calltrace.cycles-pp.__lll_unlock_wake
2.83 ± 14% -1.0 1.83 ± 15% perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe.__lll_unlock_wake
2.80 ± 14% -1.0 1.81 ± 15% perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe.__lll_unlock_wake
2.67 ± 14% -0.9 1.73 ± 15% perf-profile.calltrace.cycles-pp.__x64_sys_futex.do_syscall_64.entry_SYSCALL_64_after_hwframe.__lll_unlock_wake
2.63 ± 14% -0.9 1.70 ± 15% perf-profile.calltrace.cycles-pp.do_futex.__x64_sys_futex.do_syscall_64.entry_SYSCALL_64_after_hwframe.__lll_unlock_wake
7.36 ± 3% -0.7 6.70 ± 2% perf-profile.calltrace.cycles-pp.__lll_lock_wait
6.73 ± 3% -0.6 6.14 ± 2% perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe.__lll_lock_wait
6.71 ± 3% -0.6 6.13 ± 2% perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe.__lll_lock_wait
4.23 ± 4% -0.5 3.77 ± 3% perf-profile.calltrace.cycles-pp.__x64_sys_futex.do_syscall_64.entry_SYSCALL_64_after_hwframe.__lll_lock_wait
4.19 ± 4% -0.5 3.74 ± 3% perf-profile.calltrace.cycles-pp.do_futex.__x64_sys_futex.do_syscall_64.entry_SYSCALL_64_after_hwframe.__lll_lock_wait
5.59 ± 2% -0.4 5.22 ± 2% perf-profile.calltrace.cycles-pp.futex_wait.do_futex.__x64_sys_futex.do_syscall_64.entry_SYSCALL_64_after_hwframe
4.78 ± 2% -0.3 4.47 ± 2% perf-profile.calltrace.cycles-pp.futex_wait_queue_me.futex_wait.do_futex.__x64_sys_futex.do_syscall_64
0.52 ± 2% -0.3 0.25 ±100% perf-profile.calltrace.cycles-pp.__lock_task_sighand.do_send_sig_info.kill_pid_info.do_rt_sigqueueinfo.__x64_sys_rt_sigqueueinfo
4.12 ± 2% -0.2 3.88 ± 2% perf-profile.calltrace.cycles-pp.schedule.futex_wait_queue_me.futex_wait.do_futex.__x64_sys_futex
4.06 ± 2% -0.2 3.81 ± 2% perf-profile.calltrace.cycles-pp.__sched_text_start.schedule.futex_wait_queue_me.futex_wait.do_futex
0.76 ± 4% -0.1 0.62 ± 6% perf-profile.calltrace.cycles-pp._raw_spin_lock.__sched_text_start.schedule.futex_wait_queue_me.futex_wait
0.69 ± 4% -0.1 0.56 ± 6% perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock.__sched_text_start.schedule.futex_wait_queue_me
1.08 ± 3% -0.1 0.99 perf-profile.calltrace.cycles-pp.get_signal.do_signal.__prepare_exit_to_usermode.do_syscall_64.entry_SYSCALL_64_after_hwframe
1.32 ± 2% -0.1 1.24 perf-profile.calltrace.cycles-pp.stack_trace_save_tsk.__account_scheduler_latency.update_stats_enqueue_sleeper.enqueue_entity.enqueue_task_fair
0.75 ± 4% -0.1 0.68 ± 3% perf-profile.calltrace.cycles-pp.dequeue_signal.get_signal.do_signal.__prepare_exit_to_usermode.do_syscall_64
0.96 ± 3% -0.1 0.90 perf-profile.calltrace.cycles-pp.generic_file_buffered_read.new_sync_read.vfs_read.ksys_pread64.do_syscall_64
1.08 ± 3% -0.1 1.02 perf-profile.calltrace.cycles-pp.new_sync_read.vfs_read.ksys_pread64.do_syscall_64.entry_SYSCALL_64_after_hwframe
0.77 -0.1 0.71 perf-profile.calltrace.cycles-pp.__pthread_mutex_lock
0.73 ± 2% -0.0 0.68 ± 3% perf-profile.calltrace.cycles-pp.dequeue_task_fair.__sched_text_start.schedule.futex_wait_queue_me.futex_wait
0.55 +0.0 0.56 perf-profile.calltrace.cycles-pp.select_idle_sibling.select_task_rq_fair.try_to_wake_up.signal_wake_up_state.__send_signal
0.64 ± 2% +0.1 0.70 ± 2% perf-profile.calltrace.cycles-pp.aa_may_signal.apparmor_task_kill.security_task_kill.group_send_sig_info.kill_pid_info
1.47 +0.1 1.55 perf-profile.calltrace.cycles-pp.__x64_sys_futex.do_syscall_64.entry_SYSCALL_64_after_hwframe.pthread_cond_timedwait@@GLIBC_2.3.2
1.43 +0.1 1.51 perf-profile.calltrace.cycles-pp.do_futex.__x64_sys_futex.do_syscall_64.entry_SYSCALL_64_after_hwframe.pthread_cond_timedwait@@GLIBC_2.3.2
1.56 +0.1 1.65 perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe.pthread_cond_timedwait@@GLIBC_2.3.2
1.58 +0.1 1.67 perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe.pthread_cond_timedwait@@GLIBC_2.3.2
1.79 +0.1 1.88 perf-profile.calltrace.cycles-pp.pthread_cond_timedwait@@GLIBC_2.3.2
0.74 ± 9% +0.2 0.98 ± 4% perf-profile.calltrace.cycles-pp.enqueue_entity.enqueue_task_fair.activate_task.ttwu_do_activate.sched_ttwu_pending
0.76 ± 8% +0.2 1.00 ± 4% perf-profile.calltrace.cycles-pp.ttwu_do_activate.sched_ttwu_pending.__sysvec_call_function_single.asm_call_on_stack.sysvec_call_function_single
0.76 ± 8% +0.2 1.00 ± 4% perf-profile.calltrace.cycles-pp.activate_task.ttwu_do_activate.sched_ttwu_pending.__sysvec_call_function_single.asm_call_on_stack
0.76 ± 8% +0.2 1.00 ± 4% perf-profile.calltrace.cycles-pp.enqueue_task_fair.activate_task.ttwu_do_activate.sched_ttwu_pending.__sysvec_call_function_single
0.81 ± 8% +0.3 1.07 ± 4% perf-profile.calltrace.cycles-pp.sched_ttwu_pending.__sysvec_call_function_single.asm_call_on_stack.sysvec_call_function_single.asm_sysvec_call_function_single
0.84 ± 8% +0.3 1.09 ± 4% perf-profile.calltrace.cycles-pp.asm_call_on_stack.sysvec_call_function_single.asm_sysvec_call_function_single.finish_task_switch.__sched_text_start
0.85 ± 7% +0.3 1.11 ± 4% perf-profile.calltrace.cycles-pp.sysvec_call_function_single.asm_sysvec_call_function_single.finish_task_switch.__sched_text_start.schedule_idle
0.83 ± 8% +0.3 1.09 ± 4% perf-profile.calltrace.cycles-pp.__sysvec_call_function_single.asm_call_on_stack.sysvec_call_function_single.asm_sysvec_call_function_single.finish_task_switch
0.91 ± 7% +0.3 1.18 ± 4% perf-profile.calltrace.cycles-pp.finish_task_switch.__sched_text_start.schedule_idle.do_idle.cpu_startup_entry
0.88 ± 7% +0.3 1.15 ± 4% perf-profile.calltrace.cycles-pp.asm_sysvec_call_function_single.finish_task_switch.__sched_text_start.schedule_idle.do_idle
1.57 ± 10% +0.4 1.95 ± 5% perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock.try_to_wake_up.wake_up_q.futex_wake
1.60 ± 10% +0.4 1.98 ± 5% perf-profile.calltrace.cycles-pp._raw_spin_lock.try_to_wake_up.wake_up_q.futex_wake.do_futex
4.32 ± 7% +0.7 5.00 ± 3% perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock.__sched_text_start.schedule_idle.do_idle
4.38 ± 6% +0.7 5.06 ± 3% perf-profile.calltrace.cycles-pp._raw_spin_lock.__sched_text_start.schedule_idle.do_idle.cpu_startup_entry
6.08 ± 6% +1.0 7.08 ± 3% perf-profile.calltrace.cycles-pp.__sched_text_start.schedule_idle.do_idle.cpu_startup_entry.start_secondary
6.10 ± 6% +1.0 7.10 ± 3% perf-profile.calltrace.cycles-pp.schedule_idle.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
5.92 ± 6% +1.1 7.03 ± 3% perf-profile.calltrace.cycles-pp.do_futex.__x64_sys_futex.do_syscall_64.entry_SYSCALL_64_after_hwframe.pthread_cond_signal@@GLIBC_2.3.2
5.94 ± 6% +1.1 7.05 ± 3% perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe.pthread_cond_signal@@GLIBC_2.3.2
5.95 ± 6% +1.1 7.07 ± 3% perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe.pthread_cond_signal@@GLIBC_2.3.2
5.93 ± 6% +1.1 7.04 ± 3% perf-profile.calltrace.cycles-pp.__x64_sys_futex.do_syscall_64.entry_SYSCALL_64_after_hwframe.pthread_cond_signal@@GLIBC_2.3.2
6.08 ± 6% +1.1 7.20 ± 3% perf-profile.calltrace.cycles-pp.pthread_cond_signal@@GLIBC_2.3.2
9.26 ± 7% +1.8 11.02 ± 3% perf-profile.calltrace.cycles-pp.intel_idle.cpuidle_enter_state.cpuidle_enter.do_idle.cpu_startup_entry
9.55 ± 7% +1.8 11.38 ± 3% perf-profile.calltrace.cycles-pp.cpuidle_enter_state.cpuidle_enter.do_idle.cpu_startup_entry.start_secondary
9.56 ± 7% +1.8 11.40 ± 3% perf-profile.calltrace.cycles-pp.cpuidle_enter.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
16.74 ± 6% +3.0 19.71 ± 3% perf-profile.calltrace.cycles-pp.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64
16.75 ± 6% +3.0 19.73 ± 3% perf-profile.calltrace.cycles-pp.cpu_startup_entry.start_secondary.secondary_startup_64
16.75 ± 6% +3.0 19.73 ± 3% perf-profile.calltrace.cycles-pp.start_secondary.secondary_startup_64
16.90 ± 6% +3.0 19.93 ± 3% perf-profile.calltrace.cycles-pp.secondary_startup_64
76.06 -2.9 73.12 perf-profile.children.cycles-pp.do_syscall_64
76.41 -2.9 73.48 perf-profile.children.cycles-pp.entry_SYSCALL_64_after_hwframe
26.27 ± 2% -2.7 23.56 ± 2% perf-profile.children.cycles-pp.security_task_kill
26.25 ± 2% -2.7 23.54 ± 2% perf-profile.children.cycles-pp.apparmor_task_kill
26.45 ± 2% -2.7 23.75 ± 2% perf-profile.children.cycles-pp.group_send_sig_info
13.53 ± 2% -2.4 11.12 ± 2% perf-profile.children.cycles-pp.aa_get_task_label
46.12 -2.3 43.83 perf-profile.children.cycles-pp.kill_pid_info
46.36 -2.3 44.07 perf-profile.children.cycles-pp.do_rt_sigqueueinfo
46.72 -2.3 44.44 perf-profile.children.cycles-pp.__x64_sys_rt_sigqueueinfo
3.02 ± 14% -1.0 2.01 ± 14% perf-profile.children.cycles-pp.__lll_unlock_wake
7.39 ± 3% -0.7 6.73 ± 2% perf-profile.children.cycles-pp.__lll_lock_wait
5.47 ± 3% -0.4 5.04 ± 3% perf-profile.children.cycles-pp.schedule
5.59 ± 2% -0.4 5.22 ± 2% perf-profile.children.cycles-pp.futex_wait
4.30 ± 5% -0.4 3.94 ± 2% perf-profile.children.cycles-pp.__prepare_exit_to_usermode
4.79 ± 2% -0.3 4.48 ± 2% perf-profile.children.cycles-pp.futex_wait_queue_me
1.53 ± 3% -0.1 1.41 perf-profile.children.cycles-pp.get_signal
0.66 ± 5% -0.1 0.56 ± 3% perf-profile.children.cycles-pp.switch_mm_irqs_off
1.09 ± 3% -0.1 0.99 ± 2% perf-profile.children.cycles-pp.dequeue_signal
0.62 ± 4% -0.1 0.54 ± 4% perf-profile.children.cycles-pp.__task_rq_lock
0.89 ± 4% -0.1 0.80 ± 2% perf-profile.children.cycles-pp.__set_current_blocked
0.53 ± 5% -0.1 0.45 ± 3% perf-profile.children.cycles-pp.recalc_sigpending
0.67 ± 5% -0.1 0.60 ± 3% perf-profile.children.cycles-pp.__switch_to
0.52 ± 4% -0.1 0.45 ± 5% perf-profile.children.cycles-pp.futex_wait_setup
1.09 ± 2% -0.1 1.03 perf-profile.children.cycles-pp.new_sync_read
0.97 ± 3% -0.1 0.91 perf-profile.children.cycles-pp.generic_file_buffered_read
0.65 ± 4% -0.1 0.59 ± 2% perf-profile.children.cycles-pp._raw_spin_lock_irq
0.20 ± 5% -0.0 0.15 ± 3% perf-profile.children.cycles-pp.put_task_stack
0.51 ± 3% -0.0 0.46 ± 2% perf-profile.children.cycles-pp.__sigqueue_free
0.77 -0.0 0.72 perf-profile.children.cycles-pp.__pthread_mutex_lock
0.41 ± 4% -0.0 0.36 ± 2% perf-profile.children.cycles-pp.__set_task_blocked
0.64 ± 2% -0.0 0.60 perf-profile.children.cycles-pp.pagecache_get_page
0.30 ± 5% -0.0 0.26 ± 4% perf-profile.children.cycles-pp.fpregs_mark_activate
0.13 ± 9% -0.0 0.10 ± 7% perf-profile.children.cycles-pp.switch_fpu_return
0.24 ± 4% -0.0 0.21 ± 3% perf-profile.children.cycles-pp.kmem_cache_free
0.52 ± 2% -0.0 0.49 ± 2% perf-profile.children.cycles-pp.__lock_task_sighand
0.46 ± 2% -0.0 0.44 ± 2% perf-profile.children.cycles-pp.signal_setup_done
0.26 -0.0 0.23 ± 2% perf-profile.children.cycles-pp.mark_wake_futex
0.20 ± 2% -0.0 0.18 ± 2% perf-profile.children.cycles-pp.file_remove_privs
0.15 -0.0 0.13 ± 3% perf-profile.children.cycles-pp.dentry_needs_remove_privs
0.14 ± 3% -0.0 0.12 perf-profile.children.cycles-pp.__unwind_start
0.07 ± 5% -0.0 0.06 ± 7% perf-profile.children.cycles-pp.clockevents_program_event
0.12 ± 4% -0.0 0.11 perf-profile.children.cycles-pp.security_inode_need_killpriv
0.07 ± 7% -0.0 0.05 perf-profile.children.cycles-pp.__vfs_getxattr
0.18 ± 2% -0.0 0.17 ± 4% perf-profile.children.cycles-pp.__orc_find
0.08 +0.0 0.09 perf-profile.children.cycles-pp.task_curr
0.10 ± 4% +0.0 0.11 perf-profile.children.cycles-pp.hrtimer_cancel
0.15 +0.0 0.16 ± 2% perf-profile.children.cycles-pp.check_kill_permission
0.06 ± 7% +0.0 0.07 perf-profile.children.cycles-pp.set_next_task_idle
0.15 ± 4% +0.0 0.17 ± 3% perf-profile.children.cycles-pp.__might_sleep
0.08 ± 5% +0.0 0.10 ± 4% perf-profile.children.cycles-pp.__next_timer_interrupt
0.13 ± 3% +0.0 0.15 ± 2% perf-profile.children.cycles-pp._find_next_bit
0.81 +0.0 0.82 perf-profile.children.cycles-pp.select_idle_sibling
0.28 +0.0 0.30 perf-profile.children.cycles-pp.__copy_siginfo_from_user
0.73 +0.0 0.75 perf-profile.children.cycles-pp.getuid
0.41 +0.0 0.43 perf-profile.children.cycles-pp.available_idle_cpu
0.43 ± 2% +0.0 0.46 perf-profile.children.cycles-pp._copy_from_user
0.93 +0.0 0.97 perf-profile.children.cycles-pp.dequeue_entity
0.42 +0.0 0.46 perf-profile.children.cycles-pp.menu_select
0.11 ± 6% +0.0 0.16 ± 5% perf-profile.children.cycles-pp.flush_smp_call_function_from_idle
0.64 ± 2% +0.1 0.70 ± 2% perf-profile.children.cycles-pp.aa_may_signal
1.79 +0.1 1.89 perf-profile.children.cycles-pp.pthread_cond_timedwait@@GLIBC_2.3.2
1.83 ± 3% +0.3 2.11 perf-profile.children.cycles-pp.finish_task_switch
2.64 ± 3% +0.3 2.98 ± 2% perf-profile.children.cycles-pp.asm_call_on_stack
2.03 ± 4% +0.4 2.39 ± 2% perf-profile.children.cycles-pp.sysvec_call_function_single
1.99 ± 4% +0.4 2.35 ± 2% perf-profile.children.cycles-pp.__sysvec_call_function_single
2.09 ± 4% +0.4 2.46 ± 2% perf-profile.children.cycles-pp.asm_sysvec_call_function_single
2.04 ± 4% +0.4 2.45 ± 2% perf-profile.children.cycles-pp.sched_ttwu_pending
11.57 +0.6 12.15 perf-profile.children.cycles-pp.__sched_text_start
17.81 +0.6 18.45 perf-profile.children.cycles-pp.enqueue_task_fair
17.83 +0.6 18.47 perf-profile.children.cycles-pp.activate_task
17.83 +0.6 18.48 perf-profile.children.cycles-pp.ttwu_do_activate
16.12 +0.6 16.77 perf-profile.children.cycles-pp.update_stats_enqueue_sleeper
16.08 +0.6 16.72 perf-profile.children.cycles-pp.__account_scheduler_latency
17.16 +0.7 17.84 perf-profile.children.cycles-pp.enqueue_entity
25.29 +0.7 26.00 perf-profile.children.cycles-pp.try_to_wake_up
14.49 +0.7 15.20 perf-profile.children.cycles-pp._raw_spin_lock_irqsave
13.01 ± 4% +0.9 13.90 perf-profile.children.cycles-pp._raw_spin_lock
6.16 ± 6% +1.0 7.18 ± 3% perf-profile.children.cycles-pp.schedule_idle
6.09 ± 6% +1.1 7.20 ± 3% perf-profile.children.cycles-pp.pthread_cond_signal@@GLIBC_2.3.2
25.45 ± 3% +1.7 27.18 perf-profile.children.cycles-pp.native_queued_spin_lock_slowpath
9.33 ± 7% +1.8 11.12 ± 3% perf-profile.children.cycles-pp.intel_idle
9.64 ± 7% +1.9 11.50 ± 3% perf-profile.children.cycles-pp.cpuidle_enter_state
9.64 ± 7% +1.9 11.50 ± 3% perf-profile.children.cycles-pp.cpuidle_enter
16.75 ± 6% +3.0 19.73 ± 3% perf-profile.children.cycles-pp.start_secondary
16.90 ± 6% +3.0 19.93 ± 3% perf-profile.children.cycles-pp.secondary_startup_64
16.90 ± 6% +3.0 19.93 ± 3% perf-profile.children.cycles-pp.cpu_startup_entry
16.89 ± 6% +3.0 19.91 ± 3% perf-profile.children.cycles-pp.do_idle
13.42 ± 2% -2.4 11.04 ± 2% perf-profile.self.cycles-pp.aa_get_task_label
0.88 ± 4% -0.1 0.77 perf-profile.self.cycles-pp._raw_spin_lock
0.51 ± 5% -0.1 0.41 ± 3% perf-profile.self.cycles-pp.switch_mm_irqs_off
0.43 ± 5% -0.1 0.35 ± 4% perf-profile.self.cycles-pp.futex_wait_queue_me
0.44 ± 6% -0.1 0.37 ± 3% perf-profile.self.cycles-pp.recalc_sigpending
0.63 ± 5% -0.1 0.56 ± 3% perf-profile.self.cycles-pp.__switch_to
0.52 ± 4% -0.1 0.45 ± 2% perf-profile.self.cycles-pp._raw_spin_lock_irq
0.73 -0.1 0.67 perf-profile.self.cycles-pp.__pthread_mutex_lock
0.20 ± 5% -0.0 0.15 ± 3% perf-profile.self.cycles-pp.put_task_stack
0.51 ± 3% -0.0 0.46 ± 2% perf-profile.self.cycles-pp.__sigqueue_free
0.30 ± 3% -0.0 0.26 ± 9% perf-profile.self.cycles-pp.futex_wait_setup
0.21 ± 3% -0.0 0.17 ± 4% perf-profile.self.cycles-pp.pagecache_get_page
0.29 ± 4% -0.0 0.25 ± 4% perf-profile.self.cycles-pp.__lll_lock_wait
0.29 ± 5% -0.0 0.25 ± 4% perf-profile.self.cycles-pp.fpregs_mark_activate
0.35 ± 3% -0.0 0.32 perf-profile.self.cycles-pp.generic_file_buffered_read
0.13 ± 8% -0.0 0.10 ± 8% perf-profile.self.cycles-pp.switch_fpu_return
0.18 -0.0 0.16 ± 4% perf-profile.self.cycles-pp.simple_write_end
0.12 ± 3% -0.0 0.10 ± 8% perf-profile.self.cycles-pp.ktime_get
0.10 ± 10% -0.0 0.08 ± 5% perf-profile.self.cycles-pp.wake_up_q
0.15 ± 3% -0.0 0.13 perf-profile.self.cycles-pp.select_task_rq_fair
0.08 -0.0 0.07 ± 7% perf-profile.self.cycles-pp.generic_file_write_iter
0.18 ± 2% -0.0 0.17 ± 4% perf-profile.self.cycles-pp.__orc_find
0.11 ± 3% -0.0 0.10 perf-profile.self.cycles-pp.__unqueue_futex
0.08 -0.0 0.07 perf-profile.self.cycles-pp.arch_stack_walk
0.08 +0.0 0.09 perf-profile.self.cycles-pp.task_curr
0.19 ± 2% +0.0 0.21 ± 2% perf-profile.self.cycles-pp.prepare_signal
0.13 ± 3% +0.0 0.15 ± 3% perf-profile.self.cycles-pp.__dequeue_signal
0.13 ± 3% +0.0 0.14 ± 3% perf-profile.self.cycles-pp._find_next_bit
0.09 ± 4% +0.0 0.11 perf-profile.self.cycles-pp.menu_select
0.41 +0.0 0.42 ± 2% perf-profile.self.cycles-pp.available_idle_cpu
0.63 ± 3% +0.1 0.70 ± 2% perf-profile.self.cycles-pp.aa_may_signal
25.44 ± 3% +1.7 27.17 perf-profile.self.cycles-pp.native_queued_spin_lock_slowpath
9.33 ± 7% +1.8 11.12 ± 3% perf-profile.self.cycles-pp.intel_idle
stress-ng.sigq.ops
3e+08 +-----------------------------------------------------------------+
| O O O O O O O O O O O O O O O O O O O O O O O |
2.5e+08 |-+ O |
|..+.+..+.+..+.+.. .+.. .+..+.+..+.+..+ |
| + +.+..+.+. |
2e+08 |-+ |
| |
1.5e+08 |-+ |
| |
1e+08 |-+ |
| |
| |
5e+07 |-+ |
| |
0 +-----------------------------------------------------------------+
stress-ng.sigq.ops_per_sec
1e+07 +-------------------------------------------------------------------+
9e+06 |-+O O O O O O O O O O O O O O O O O O O O O O O |
| O |
8e+06 |..+.+..+.+..+..+. .+.. .+..+.+..+.+..+ |
7e+06 |-+ +. +.+..+.+. |
| |
6e+06 |-+ |
5e+06 |-+ |
4e+06 |-+ |
| |
3e+06 |-+ |
2e+06 |-+ |
| |
1e+06 |-+ |
0 +-------------------------------------------------------------------+
[*] bisect-good sample
[O] bisect-bad sample
Disclaimer:
Results have been estimated based on internal Intel analysis and are provided
for informational purposes only. Any difference in system hardware or software
design or configuration may affect actual performance.
Thanks,
Rong Chen
On Thu, Jul 09, 2020 at 03:29PM +0206, John Ogness wrote:
> Replace the existing ringbuffer usage and implementation with
> lockless ringbuffer usage. Even though the new ringbuffer does not
> require locking, all existing locking is left in place. Therefore,
> this change is purely replacing the underlining ringbuffer.
>
> Changes that exist due to the ringbuffer replacement:
>
> - The VMCOREINFO has been updated for the new structures.
>
> - Dictionary data is now stored in a separate data buffer from the
> human-readable messages. The dictionary data buffer is set to the
> same size as the message buffer. Therefore, the total required
> memory for both dictionary and message data is
> 2 * (2 ^ CONFIG_LOG_BUF_SHIFT) for the initial static buffers and
> 2 * log_buf_len (the kernel parameter) for the dynamic buffers.
>
> - Record meta-data is now stored in a separate array of descriptors.
> This is an additional 72 * (2 ^ (CONFIG_LOG_BUF_SHIFT - 5)) bytes
> for the static array and 72 * (log_buf_len >> 5) bytes for the
> dynamic array.
>
> Signed-off-by: John Ogness <[email protected]>
> Reviewed-by: Petr Mladek <[email protected]>
It seems this causes a regression observed at least with newline-only
printks. I noticed this during -next testing because various debugging
tools (K*SAN, lockdep, etc.) use e.g. pr_{err,warn,info}("\n") to format
reports.
Without wanting to wait for a report from one of these debugging tools,
a simple reproducer is below. Without this patch, the expected newline
is printed.
Thanks,
-- Marco
------ >8 ------
--- a/init/main.c
+++ b/init/main.c
@@ -1039,6 +1039,10 @@ asmlinkage __visible void __init start_kernel(void)
sfi_init_late();
kcsan_init();
+ pr_info("EXPECT BLANK LINE --vv\n");
+ pr_info("\n");
+ pr_info("EXPECT BLANK LINE --^^\n");
+
/* Do the rest non-__init'ed, we're now alive */
arch_call_rest_init();
Hi Marco,
On (20/07/18 14:10), Marco Elver wrote:
>
> It seems this causes a regression observed at least with newline-only
> printks. I noticed this during -next testing because various debugging
> tools (K*SAN, lockdep, etc.) use e.g. pr_{err,warn,info}("\n") to format
> reports.
>
> Without wanting to wait for a report from one of these debugging tools,
> a simple reproducer is below. Without this patch, the expected newline
> is printed.
Empty/blank lines carry no valuable payload, could you please explain
why do you consider this to be a regression?
-ss
On Sun, Jul 19, 2020 at 12:43PM +0900, Sergey Senozhatsky wrote:
> Hi Marco,
>
> On (20/07/18 14:10), Marco Elver wrote:
> >
> > It seems this causes a regression observed at least with newline-only
> > printks. I noticed this during -next testing because various debugging
> > tools (K*SAN, lockdep, etc.) use e.g. pr_{err,warn,info}("\n") to format
> > reports.
> >
> > Without wanting to wait for a report from one of these debugging tools,
> > a simple reproducer is below. Without this patch, the expected newline
> > is printed.
>
> Empty/blank lines carry no valuable payload, could you please explain
> why do you consider this to be a regression?
Empty/blank lines are visually valuable.
Did I miss a discussion somewhere that this change is acceptable?
Unfortunately, I can't find it mentioned in the commit message, and
therefore assumed it's a regression.
As I said, a number of debugging tools use them to format reports to be
more readable (visually separate title and report body, and separate
parts of the report). Also, such reports are often parsed by CI systems,
and by changing the reports, these CI systems may break. But those are
just the usecases I'm acutely aware of -- please see a full list of
newline-print users below.
Breaking the observable behaviour of a widely used interface such as
printk doesn't seem right. Where the newline-print is inappropriate,
wouldn't removing that newline-print be more appropriate (instead of
forcing this behaviour on everyone)?
Thanks,
-- Marco
------ >8 ------
$> git grep -En '\<(printk|pr_err|pr_warn|pr_info)\>\("\\n"\)'
arch/alpha/kernel/core_wildfire.c:650: printk("\n");
arch/alpha/kernel/core_wildfire.c:658: printk("\n");
arch/alpha/kernel/traps.c:120: printk("\n");
arch/arm/mach-footbridge/dc21285.c:168: printk("\n");
arch/arm/mach-footbridge/dc21285.c:185: printk("\n");
arch/arm/mach-footbridge/dc21285.c:214: printk("\n");
arch/arm/mach-footbridge/dc21285.c:229: printk("\n");
arch/arm/plat-orion/mpp.c:44: printk("\n");
arch/arm/plat-orion/mpp.c:81: printk("\n");
arch/arm/probes/kprobes/test-core.c:576: pr_info("\n");
arch/c6x/kernel/traps.c:30: pr_err("\n");
arch/h8300/kernel/process.c:101: printk("\n");
arch/h8300/kernel/traps.c:84: pr_info("\n");
arch/h8300/kernel/traps.c:93: pr_info("\n");
arch/ia64/kernel/acpi.c:514: printk("\n");
arch/ia64/kernel/process.c:105: printk("\n");
arch/ia64/kernel/sal.c:173: printk("\n");
arch/ia64/kernel/time.c:306: printk("\n");
arch/ia64/kernel/unaligned.c:48: printk("\n");
arch/m68k/mm/kmap.c:283: printk("\n");
arch/m68k/mm/motorola.c:383: printk("\n");
arch/microblaze/pci/xilinx_pci.c:109: pr_info("\n");
arch/mips/jazz/jazzdma.c:170: printk("\n");
arch/mips/jazz/jazzdma.c:276: printk("\n");
arch/mips/jazz/jazzdma.c:345: printk("\n");
arch/mips/jazz/jazzdma.c:351: printk("\n");
arch/mips/kernel/sysrq.c:31: pr_info("\n");
arch/mips/kernel/sysrq.c:33: pr_info("\n");
arch/mips/kernel/traps.c:378: printk("\n");
arch/mips/kernel/traps.c:1588: pr_info("\n");
arch/mips/kvm/tlb.c:81: pr_info("\n");
arch/mips/lib/dump_tlb.c:187: printk("\n");
arch/mips/lib/r3k_dump_tlb.c:67: printk("\n");
arch/mips/math-emu/ieee754d.c:58: printk("\n");
arch/mips/math-emu/ieee754d.c:97: printk("\n");
arch/mips/mm/cerr-sb1.c:74: printk("\n");
arch/mips/mm/cerr-sb1.c:85: printk("\n");
arch/mips/mm/cerr-sb1.c:126: printk("\n");
arch/mips/mm/cerr-sb1.c:416: printk("\n");
arch/mips/mm/cerr-sb1.c:561: printk("\n");
arch/mips/netlogic/xlr/fmn-config.c:64: pr_info("\n");
arch/mips/netlogic/xlr/fmn-config.c:78: pr_info("\n");
arch/mips/sni/setup.c:106: printk("\n");
arch/openrisc/kernel/traps.c:120: printk("\n");
arch/openrisc/kernel/traps.c:168: printk("\n");
arch/openrisc/kernel/traps.c:183: printk("\n");
arch/openrisc/kernel/traps.c:196: printk("\n");
arch/parisc/kernel/drivers.c:1007: pr_info("\n");
arch/parisc/kernel/pci-dma.c:70: printk("\n");
arch/parisc/kernel/traps.c:452: printk("\n");
arch/parisc/mm/fault.c:245: pr_warn("\n");
arch/powerpc/kernel/traps.c:213: printk("\n");
arch/powerpc/math-emu/fabs.c:15: printk("\n");
arch/powerpc/math-emu/fctiw.c:24: printk("\n");
arch/powerpc/math-emu/fctiwz.c:31: printk("\n");
arch/powerpc/math-emu/fmr.c:15: printk("\n");
arch/powerpc/math-emu/fnabs.c:15: printk("\n");
arch/powerpc/math-emu/fneg.c:15: printk("\n");
arch/powerpc/math-emu/lfd.c:17: printk("\n");
arch/powerpc/math-emu/stfd.c:13: printk("\n");
arch/powerpc/mm/book3s64/slb.c:271: pr_err("\n");
arch/powerpc/mm/nohash/44x.c:194: printk("\n");
arch/powerpc/platforms/52xx/efika.c:111: printk("\n");
arch/powerpc/platforms/chrp/pci.c:257: printk("\n");
arch/powerpc/platforms/embedded6xx/ls_uart.c:53: printk("\n");
arch/powerpc/platforms/powermac/pfunc_core.c:88: printk("\n");
arch/powerpc/platforms/ps3/setup.c:100: printk("\n");
arch/powerpc/platforms/ps3/setup.c:103: printk("\n");
arch/sh/drivers/pci/common.c:137: printk("\n");
arch/sh/drivers/pci/common.c:146: printk("\n");
arch/sh/drivers/pci/pci-sh7780.c:151: printk("\n");
arch/sh/kernel/disassemble.c:567: printk("\n");
arch/sh/kernel/disassemble.c:570: printk("\n");
arch/sh/kernel/process_32.c:33: printk("\n");
arch/sh/kernel/process_32.c:44: printk("\n");
arch/sparc/kernel/perf_event.c:1602: pr_info("\n");
arch/sparc/kernel/setup_32.c:383: printk("\n");
arch/sparc/kernel/traps_32.c:44: printk("\n");
arch/sparc/kernel/traps_64.c:2435: printk("\n");
arch/sparc/kernel/traps_64.c:2452: printk("\n");
arch/um/drivers/daemon_kern.c:39: printk("\n");
arch/um/drivers/slirp_kern.c:44: printk("\n");
arch/um/drivers/vde_kern.c:36: printk("\n");
arch/um/os-Linux/skas/mem.c:101: printk("\n");
arch/x86/events/core.c:1428: pr_info("\n");
arch/x86/kernel/apm_32.c:2305: printk("\n");
arch/x86/kernel/cpu/mtrr/cleanup.c:768: pr_info("\n");
arch/x86/um/sysrq_32.c:17: printk("\n");
arch/x86/um/sysrq_64.c:18: printk("\n");
block/genhd.c:1115: printk("\n");
drivers/ata/pata_marvell.c:50: printk("\n");
drivers/ata/sata_mv.c:1258: printk("\n");
drivers/ata/sata_mv.c:1275: printk("\n");
drivers/atm/eni.c:1723: printk("\n");
drivers/atm/eni.c:1734: printk("\n");
drivers/atm/idt77252.c:543: printk("\n");
drivers/atm/idt77252.c:1281: printk("\n");
drivers/atm/idt77252.c:3494: printk("\n");
drivers/atm/iphase.c:1347: printk("\n");)
drivers/atm/iphase.c:2413: printk("\n");
drivers/atm/iphase.c:3001: printk("\n");)
drivers/block/floppy.c:1830: pr_info("\n");
drivers/block/floppy.c:1867: pr_info("\n");
drivers/block/paride/bpck.c:340: printk("\n");
drivers/block/paride/pcd.c:590: printk("\n");
drivers/block/paride/pd.c:294: printk("\n");
drivers/block/paride/pf.c:585: printk("\n");
drivers/block/paride/pg.c:349: printk("\n");
drivers/block/paride/pg.c:415: printk("\n");
drivers/block/paride/pt.c:477: printk("\n");
drivers/block/umem.c:200: printk("\n");
drivers/block/umem.c:226: printk("\n");
drivers/block/xsysace.c:384: printk("\n");
drivers/bluetooth/dtl1_cs.c:188: printk("\n");
drivers/char/applicom.c:333: printk("\n");
drivers/char/applicom.c:420: printk("\n");
drivers/char/applicom.c:533: printk("\n");
drivers/char/applicom.c:820: printk("\n");
drivers/char/dtlk.c:457: printk("\n");
drivers/char/dtlk.c:460: printk("\n");
drivers/char/dtlk.c:483: printk("\n");
drivers/char/dtlk.c:486: printk("\n");
drivers/char/dtlk.c:530: printk("\n");
drivers/char/pcmcia/synclink_cs.c:3825: printk("\n");
drivers/crypto/hifn_795x.c:1833: pr_info("\n");
drivers/gpu/drm/i915/gvt/cmd_parser.c:698: pr_err("\n");
drivers/i2c/busses/i2c-viapro.c:116: printk("\n");
drivers/i2c/busses/scx200_acb.c:358: printk("\n");
drivers/ide/cmd640.c:376: printk("\n");
drivers/infiniband/hw/mlx4/qp.c:3245: pr_err("\n");
drivers/infiniband/hw/mthca/mthca_cmd.c:1802: printk("\n");
drivers/infiniband/hw/mthca/mthca_cmd.c:1819: printk("\n");
drivers/infiniband/hw/mthca/mthca_eq.c:614: printk("\n");
drivers/infiniband/hw/mthca/mthca_mr.c:487: printk("\n");
drivers/input/keyboard/lkkbd.c:380: printk("\n");
drivers/input/mouse/appletouch.c:225: printk("\n"); \
drivers/iommu/iommu-debugfs.c:35: pr_warn("\n");
drivers/isdn/hardware/mISDN/hfcmulti.c:2338: printk("\n");
drivers/isdn/hardware/mISDN/hfcsusb.c:900: printk("\n");
drivers/isdn/hardware/mISDN/hfcsusb.c:924: printk("\n");
drivers/isdn/hardware/mISDN/hfcsusb.c:1025: printk("\n");
drivers/isdn/hardware/mISDN/hfcsusb.c:1119: printk("\n");
drivers/isdn/hardware/mISDN/hfcsusb.c:1331: printk("\n");
drivers/isdn/mISDN/dsp_cmx.c:174: printk("\n");
drivers/macintosh/adb-iop.c:120: printk("\n");
drivers/macintosh/adb-iop.c:181: printk("\n");
drivers/macintosh/adb.c:120: printk("\n");
drivers/macintosh/therm_windtunnel.c:395: printk("\n");
drivers/media/dvb-frontends/mt312.c:78: printk("\n");
drivers/media/dvb-frontends/mt312.c:102: printk("\n");
drivers/media/pci/bt8xx/dst.c:550: pr_err("\n");
drivers/media/tuners/mt2060.c:25:#define dprintk(args...) do { if (debug) {printk(KERN_DEBUG "MT2060: " args); printk("\n"); }} while (0)
drivers/media/tuners/mt2266.c:45:#define dprintk(args...) do { if (debug) {printk(KERN_DEBUG "MT2266: " args); printk("\n"); }} while (0)
drivers/message/fusion/mptdebug.h:158: printk("\n");
drivers/message/fusion/mptdebug.h:175: printk("\n");
drivers/message/fusion/mptdebug.h:178: printk("\n");
drivers/message/fusion/mptdebug.h:192: printk("\n");
drivers/message/fusion/mptdebug.h:205: printk("\n");
drivers/message/fusion/mptdebug.h:208: printk("\n");
drivers/message/fusion/mptdebug.h:222: printk("\n");
drivers/message/fusion/mptdebug.h:236: printk("\n");
drivers/message/fusion/mptdebug.h:250: printk("\n");
drivers/message/fusion/mptdebug.h:253: printk("\n");
drivers/message/fusion/mptdebug.h:267: printk("\n");
drivers/message/fusion/mptdebug.h:270: printk("\n");
drivers/message/fusion/mptsas.c:953: dsaswideprintk(ioc, printk("\n"));
drivers/mfd/wm8350-core.c:42: printk("\n"); \
drivers/mmc/host/wbsd.c:1718: printk("\n");
drivers/mtd/nand/raw/diskonchip.c:317: printk("\n");
drivers/mtd/nand/raw/diskonchip.c:467: printk("\n");
drivers/mtd/nand/raw/diskonchip.c:500: printk("\n");
drivers/mtd/tests/nandbiterrs.c:332: printk("\n");
drivers/mtd/tests/subpagetest.c:113: printk("\n");
drivers/mtd/tests/torturetest.c:442: printk("\n");
drivers/net/appletalk/ltpc.c:322: printk("\n");
drivers/net/appletalk/ltpc.c:583: printk("\n");
drivers/net/appletalk/ltpc.c:911: printk("\n");
drivers/net/appletalk/ltpc.c:921: printk("\n");
drivers/net/ethernet/amd/7990.c:563: printk("\n");
drivers/net/ethernet/amd/ni65.c:909: printk("\n");
drivers/net/ethernet/amd/ni65.c:1144: printk("\n");
drivers/net/ethernet/amd/pcnet32.c:2469: printk("\n");
drivers/net/ethernet/apple/bmac.c:1351: printk("\n");
drivers/net/ethernet/apple/mace.c:616: printk("\n");
drivers/net/ethernet/dec/tulip/de4x5.c:5012: printk("\n");
drivers/net/ethernet/dec/tulip/de4x5.c:5349: printk("\n");
drivers/net/ethernet/dlink/sundance.c:1474: printk("\n");
drivers/net/ethernet/dnet.c:500: printk("\n");
drivers/net/ethernet/i825xx/sun3_82586.c:1185: printk("\n");
drivers/net/ethernet/i825xx/sun3_82586.c:1187: printk("\n");
drivers/net/ethernet/packetengines/hamachi.c:1691: printk("\n");
drivers/net/ethernet/qlogic/qlcnic/qlcnic_83xx_hw.c:812: pr_info("\n");
drivers/net/ethernet/qlogic/qlcnic/qlcnic_83xx_hw.c:815: pr_info("\n");
drivers/net/ethernet/qlogic/qlcnic/qlcnic_83xx_hw.c:820: pr_info("\n");
drivers/net/ethernet/qlogic/qlcnic/qlcnic_83xx_hw.c:823: pr_info("\n");
drivers/net/ethernet/realtek/atp.c:291: printk("\n");
drivers/net/ethernet/seeq/ether3.c:255: printk("\n");
drivers/net/ethernet/stmicro/stmmac/enh_desc.c:437: pr_info("\n");
drivers/net/ethernet/stmicro/stmmac/norm_desc.c:289: pr_info("\n");
drivers/net/ethernet/sun/sungem.c:2792: printk("\n");
drivers/net/ethernet/ti/cpmac.c:220: printk("\n");
drivers/net/ethernet/ti/cpmac.c:225: printk("\n");
drivers/net/ethernet/ti/cpmac.c:235: printk("\n");
drivers/net/ethernet/ti/cpmac.c:257: printk("\n");
drivers/net/ethernet/ti/cpmac.c:262: printk("\n");
drivers/net/ethernet/toshiba/tc35815.c:905: printk("\n");
drivers/net/ethernet/toshiba/tc35815.c:1065: printk("\n");
drivers/net/ethernet/toshiba/tc35815.c:1086: printk("\n");
drivers/net/ethernet/toshiba/tc35815.c:1105: printk("\n");
drivers/net/ethernet/toshiba/tc35815.c:1355: printk("\n");
drivers/net/ethernet/via/via-velocity.h:1328: printk("\n");\
drivers/net/ethernet/xscale/ixp4xx_eth.c:594: printk("\n");
drivers/net/hamradio/scc.c:1476: printk("\n");
drivers/net/hippi/rrunner.c:1286: printk("\n");
drivers/net/hippi/rrunner.c:1289: printk("\n");
drivers/net/hippi/rrunner.c:1303: printk("\n");
drivers/net/hippi/rrunner.c:1306: printk("\n");
drivers/net/sb1000.c:725: printk("\n");
drivers/net/wan/ixp4xx_hss.c:566: printk("\n");
drivers/net/wireless/broadcom/b43/main.c:1139: printk("\n");
drivers/net/wireless/broadcom/b43/main.c:1934: printk("\n");
drivers/net/wireless/broadcom/b43/main.c:1938: printk("\n");
drivers/net/wireless/intersil/hostap/hostap_80211_rx.c:45: printk("\n");
drivers/net/wireless/intersil/hostap/hostap_80211_rx.c:57: printk("\n");
drivers/net/wireless/intersil/hostap/hostap_80211_tx.c:42: printk("\n");
drivers/net/wireless/intersil/hostap/hostap_80211_tx.c:54: printk("\n");
drivers/net/wireless/intersil/hostap/hostap_hw.c:2152: printk("\n");
drivers/net/wireless/intersil/orinoco/orinoco_plx.c:151: printk("\n");
drivers/net/wireless/intersil/prism54/islpci_mgt.c:46: printk("\n");
drivers/net/wireless/marvell/libertas/defs.h:97: printk("\n");
drivers/net/wireless/marvell/libertas/defs.h:103: printk("\n");
drivers/net/wireless/ray_cs.c:648: printk("\n");
drivers/net/wireless/ray_cs.c:2347: printk("\n");
drivers/net/wireless/st/cw1200/cw1200_spi.c:105: printk("\n");
drivers/net/wireless/st/cw1200/cw1200_spi.c:170: printk("\n");
drivers/parisc/gsc.c:225: printk("\n");
drivers/parisc/iosapic.c:633: printk("\n");
drivers/parisc/iosapic.c:645:printk("\n");
drivers/parisc/lba_pci.c:1379: printk("\n");
drivers/pcmcia/i82365.c:680: if (base == 0) printk("\n");
drivers/scsi/53c700.c:832: printk("\n");
drivers/scsi/53c700.c:863: printk("\n");
drivers/scsi/53c700.c:917: printk("\n");
drivers/scsi/NCR5380.c:2098: printk("\n");
drivers/scsi/advansys.c:2489: printk("\n");
drivers/scsi/aha152x.c:1739: printk("\n");
drivers/scsi/aha1740.c:344: printk("\n");
drivers/scsi/aha1740.c:439: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:2731: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:3953: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9611: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9722: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9766: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9776: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9786: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9797: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9806: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9833: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9843: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9864: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9876: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9880: printk("\n");
drivers/scsi/aic7xxx/aic79xx_core.c:9934: printk("\n");
drivers/scsi/aic7xxx/aic79xx_osm.c:793: printk("\n");
drivers/scsi/aic7xxx/aic79xx_osm.c:1821: printk("\n");
drivers/scsi/aic7xxx/aic79xx_osm.c:1942: printk("\n");
drivers/scsi/aic7xxx/aic79xx_osm.c:1945: printk("\n");
drivers/scsi/aic7xxx/aic79xx_osm.c:2165: printk("\n");
drivers/scsi/aic7xxx/aic79xx_pci.c:614: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7067: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7165: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7184: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7194: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7204: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7214: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7224: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7236: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7256: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7265: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_core.c:7279: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_osm.c:1745: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_osm.c:1849: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_osm.c:1852: printk("\n");
drivers/scsi/aic7xxx/aic7xxx_osm.c:2062: printk("\n");
drivers/scsi/arm/acornscsi.c:248: printk("\n");
drivers/scsi/arm/acornscsi.c:538: printk("\n");
drivers/scsi/arm/acornscsi.c:1395: printk("\n");
drivers/scsi/arm/acornscsi.c:1476: printk("\n");
drivers/scsi/arm/acornscsi.c:1870: printk("\n");
drivers/scsi/arm/fas216.c:330: printk("\n");
drivers/scsi/arm/fas216.c:344: printk("\n");
drivers/scsi/arm/fas216.c:388: printk("\n");
drivers/scsi/arm/fas216.c:391: printk("\n");
drivers/scsi/arm/fas216.c:399: printk("\n");
drivers/scsi/arm/fas216.c:1043: printk("\n");
drivers/scsi/arm/fas216.c:1147: printk("\n");
drivers/scsi/arm/fas216.c:1264: printk("\n");
drivers/scsi/arm/fas216.c:1702: printk("\n");
drivers/scsi/arm/fas216.c:2021://{ int i; for (i = 0; i < 32; i++) printk("%02x ", SCpnt->sense_buffer[i]); printk("\n"); }
drivers/scsi/atp870u.c:337: printk("\n");
drivers/scsi/atp870u.c:746: printk("\n");
drivers/scsi/dc395x.c:2197: printk("\n");
drivers/scsi/dc395x.c:2393: printk("\n");
drivers/scsi/dc395x.c:3447: printk("\n");
drivers/scsi/dc395x.c:4194: printk("\n");
drivers/scsi/dpt_i2o.c:3160: printk("\n");
drivers/scsi/gdth.c:2720: printk("\n");
drivers/scsi/gdth.c:3107: printk("\n");
drivers/scsi/lpfc/lpfc_debugfs.c:5827: pr_err("\n");
drivers/scsi/lpfc/lpfc_debugfs.c:5855: pr_err("\n");
drivers/scsi/mesh.c:258: printk("\n");
drivers/scsi/mesh.c:283: printk("\n");
drivers/scsi/mesh.c:720: printk("\n");
drivers/scsi/mesh.c:1170: printk("\n");
drivers/scsi/mesh.c:1249: printk("\n");
drivers/scsi/mpt3sas/mpt3sas_debug.h:165: pr_info("\n");
drivers/scsi/mpt3sas/mpt3sas_debug.h:184: pr_info("\n");
drivers/scsi/mpt3sas/mpt3sas_debug.h:203: pr_info("\n");
drivers/scsi/ncr53c8xx.c:3672: printk("\n");
drivers/scsi/nsp32_debug.c:137: printk("\n");
drivers/scsi/nsp32_debug.c:225: printk("\n");
drivers/scsi/nsp32_debug.c:254: printk("\n");
drivers/scsi/nsp32_debug.c:259: printk("\n");
drivers/scsi/pcmcia/nsp_debug.c:138: printk("\n");
drivers/scsi/pcmcia/nsp_debug.c:212: printk("\n");
drivers/scsi/pcmcia/sym53c500_cs.c:556: VDEB(printk("\n"));
drivers/scsi/qla1280.c:3928: printk("\n");
drivers/scsi/qla1280.c:3950: printk("\n");
drivers/scsi/qla1280.c:3955: printk("\n");
drivers/scsi/qla4xxx/ql4_83xx.c:1423: DEBUG2(pr_info("\n"));
drivers/scsi/qla4xxx/ql4_83xx.c:1434: DEBUG2(pr_info("\n"));
drivers/scsi/qla4xxx/ql4_83xx.c:1445: DEBUG2(pr_info("\n"));
drivers/scsi/qla4xxx/ql4_83xx.c:1456: DEBUG2(pr_info("\n"));
drivers/scsi/qla4xxx/ql4_83xx.c:1474: DEBUG2(pr_info("\n"));
drivers/scsi/qla4xxx/ql4_83xx.c:1492: DEBUG2(pr_info("\n"));
drivers/scsi/qla4xxx/ql4_dbg.c:25: printk("\n");
drivers/scsi/wd33c93.c:2048: printk("\n");
drivers/staging/rtl8192u/ieee80211/ieee80211.h:464: printk("\n"); \
drivers/staging/rtl8192u/ieee80211/ieee80211.h:466: printk("\n"); \
drivers/staging/rtl8192u/r8192U.h:120: printk("\n"); \
drivers/staging/rtl8192u/r8192U.h:122: printk("\n"); \
drivers/staging/rtl8723bs/core/rtw_mlme.c:2387: printk("\n");
drivers/staging/rtl8723bs/core/rtw_mlme_ext.c:2189: printk("\n");
drivers/staging/rtl8723bs/hal/hal_com.c:1651: printk("\n");
drivers/staging/rtl8723bs/hal/rtl8723b_cmd.c:1686: printk("\n");
drivers/staging/rtl8723bs/hal/rtl8723b_cmd.c:1708: printk("\n");
drivers/staging/rtl8723bs/hal/rtl8723b_cmd.c:1728: printk("\n");
drivers/staging/rtl8723bs/hal/rtl8723b_cmd.c:1747: printk("\n");
drivers/staging/rtl8723bs/hal/rtl8723b_hal_init.c:901: printk("\n");
drivers/staging/rtl8723bs/hal/rtl8723b_hal_init.c:904: printk("\n");
drivers/staging/rtl8723bs/hal/rtl8723b_hal_init.c:972: printk("\n");
drivers/staging/rtl8723bs/hal/rtl8723b_hal_init.c:975: printk("\n");
drivers/staging/rtl8723bs/os_dep/ioctl_linux.c:251: printk("\n");
drivers/staging/rtl8723bs/os_dep/ioctl_linux.c:579: printk("\n");*/
drivers/staging/wlan-ng/p80211netdev.c:989: /* printk("\n"); */
drivers/staging/wlan-ng/p80211netdev.c:1031: /* printk("\n"); */
drivers/tty/hvc/hvsi.c:203: printk("\n");
drivers/tty/n_r3964.c:273: printk("\n");
drivers/tty/serial/zs.c:203: printk("\n");
drivers/tty/synclink.c:7437: printk("\n");
drivers/tty/synclink_gt.c:568: printk("\n");
drivers/tty/synclinkmp.c:5446: printk("\n");
drivers/usb/atm/speedtch.c:625: printk("\n");
drivers/usb/host/isp116x.h:572: printk("\n");
drivers/usb/host/isp116x.h:584: printk("\n");
drivers/usb/host/isp1362.h:903: printk("\n");
drivers/usb/host/isp1362.h:913: printk("\n");
drivers/usb/storage/sddr09.c:1478: printk("\n");
drivers/video/fbdev/intelfb/intelfbhw.c:827: printk("\n");
drivers/video/fbdev/intelfb/intelfbhw.c:834: printk("\n");
drivers/video/fbdev/vesafb.c:343: printk("\n");
drivers/w1/masters/ds2490.c:225: pr_info("\n");
drivers/w1/masters/ds2490.c:347: printk("\n");
drivers/w1/masters/ds2490.c:436: printk("\n");
drivers/xen/xenbus/xenbus_probe_frontend.c:328: printk("\n");
fs/btrfs/check-integrity.c:1689: pr_info("\n");
fs/btrfs/check-integrity.c:2486: printk("\n");
fs/cachefiles/internal.h:322: pr_err("\n"); \
fs/cachefiles/internal.h:331: pr_err("\n"); \
fs/cachefiles/internal.h:342: pr_err("\n"); \
fs/cachefiles/internal.h:351: pr_err("\n"); \
fs/cachefiles/namei.c:121: pr_err("\n");
fs/cachefiles/namei.c:187: pr_err("\n");
fs/cachefiles/namei.c:233: pr_err("\n");
fs/dlm/dlm_internal.h:99: printk("\n"); \
fs/ext2/xattr.c:79: printk("\n"); \
fs/ext2/xattr.c:85: printk("\n"); \
fs/fscache/internal.h:446: pr_err("\n"); \
fs/fscache/internal.h:455: pr_err("\n"); \
fs/fscache/internal.h:466: pr_err("\n"); \
fs/fscache/internal.h:475: pr_err("\n"); \
fs/jffs2/debug.c:428: printk("\n");
fs/jffs2/debug.c:756: printk("\n");
fs/jffs2/debug.c:766: printk("\n");
fs/reiserfs/item_ops.c:617: printk("\n");
fs/reiserfs/prints.c:471: printk("\n");
fs/reiserfs/prints.c:473: printk("\n");
fs/ubifs/debug.c:926: pr_err("\n");
include/linux/hdlc.h:85: printk("\n");
init/do_mounts.c:472: printk("\n");
kernel/kcsan/report.c:314: pr_err("\n");
kernel/kcsan/report.c:379: pr_err("\n");
kernel/kcsan/report.c:397: pr_err("\n");
kernel/kcsan/report.c:420: pr_err("\n");
kernel/locking/lockdep.c:1644: pr_warn("\n");
kernel/locking/lockdep.c:1974: printk("\n");
kernel/locking/lockdep.c:2057: pr_warn("\n");
kernel/locking/lockdep.c:2375: pr_warn("\n");
kernel/locking/lockdep.c:2947: printk("\n");
kernel/locking/lockdep.c:2955: pr_warn("\n");
kernel/locking/lockdep.c:3323: pr_warn("\n");
kernel/locking/lockdep.c:3384: pr_warn("\n");
kernel/locking/lockdep.c:4053: pr_warn("\n");
kernel/locking/lockdep.c:4240: pr_warn("\n");
kernel/locking/lockdep.c:4456: pr_warn("\n");
kernel/locking/lockdep.c:5107: pr_warn("\n");
kernel/locking/lockdep.c:5736: pr_warn("\n");
kernel/locking/lockdep.c:5794: pr_warn("\n");
kernel/locking/lockdep.c:5833: pr_warn("\n");
kernel/locking/lockdep.c:5860: pr_warn("\n");
kernel/locking/lockdep.c:5882: pr_warn("\n");
kernel/locking/rtmutex-debug.c:56: printk("\n");
kernel/locking/rtmutex-debug.c:106: pr_warn("\n");
kernel/sched/topology.c:49: printk("\n");
kernel/trace/trace.c:3158: pr_warn("\n");
mm/kasan/report.c:177: pr_err("\n");
mm/kasan/report.c:181: pr_err("\n");
mm/kasan/report.c:188: pr_err("\n");
mm/kasan/report.c:193: pr_err("\n");
mm/kasan/report.c:267: pr_err("\n");
mm/kasan/report.c:368: pr_err("\n");
mm/kasan/report.c:384: pr_err("\n");
mm/kasan/report.c:476: pr_err("\n");
mm/kasan/report.c:478: pr_err("\n");
mm/kasan/report.c:510: pr_err("\n");
mm/kasan/report.c:514: pr_err("\n");
net/atm/lec.c:1185: pr_info("\n");
On Mon, Jul 20, 2020 at 9:45 AM Marco Elver <[email protected]> wrote:
> On Sun, Jul 19, 2020 at 12:43PM +0900, Sergey Senozhatsky wrote:
> > On (20/07/18 14:10), Marco Elver wrote:
> > >
> > > It seems this causes a regression observed at least with newline-only
> > > printks. I noticed this during -next testing because various debugging
> > > tools (K*SAN, lockdep, etc.) use e.g. pr_{err,warn,info}("\n") to format
> > > reports.
> > >
> > > Without wanting to wait for a report from one of these debugging tools,
> > > a simple reproducer is below. Without this patch, the expected newline
> > > is printed.
> >
> > Empty/blank lines carry no valuable payload, could you please explain
> > why do you consider this to be a regression?
>
> Empty/blank lines are visually valuable.
>
> Did I miss a discussion somewhere that this change is acceptable?
> Unfortunately, I can't find it mentioned in the commit message, and
> therefore assumed it's a regression.
>
> As I said, a number of debugging tools use them to format reports to be
> more readable (visually separate title and report body, and separate
> parts of the report).
While I can find it useful in some cases, though messages can be
interleaved, ...
> Also, such reports are often parsed by CI systems,
> and by changing the reports, these CI systems may break. But those are
> just the usecases I'm acutely aware of -- please see a full list of
> newline-print users below.
...but this is a weak argument. If your CI relies on message rather on
the ABI, you earn the breakage.
Go and fix your CI to do sane things instead.
> Breaking the observable behaviour of a widely used interface such as
> printk doesn't seem right. Where the newline-print is inappropriate,
> wouldn't removing that newline-print be more appropriate (instead of
> forcing this behaviour on everyone)?
--
With Best Regards,
Andy Shevchenko
On (20/07/20 08:43), Marco Elver wrote:
[..]
> please see a full list of newline-print users below.
[..]
> $> git grep -En '\<(printk|pr_err|pr_warn|pr_info)\>\("\\n"\)'
> arch/alpha/kernel/core_wildfire.c:650: printk("\n");
> arch/alpha/kernel/core_wildfire.c:658: printk("\n");
> arch/alpha/kernel/traps.c:120: printk("\n");
[..]
In many cases printk("\n") is not for "print a blank line", but
rather for "flush pr_cont buffer".
-ss
On (20/07/20 08:43), Marco Elver wrote:
> On Sun, Jul 19, 2020 at 12:43PM +0900, Sergey Senozhatsky wrote:
>
> As I said, a number of debugging tools use them to format reports to be
> more readable (visually separate title and report body, and separate
> parts of the report). Also, such reports are often parsed by CI systems,
> and by changing the reports, these CI systems may break. But those are
> just the usecases I'm acutely aware of
Can you give example of such CI systems? // that's a real question //
-ss
On Mon, 20 Jul 2020 at 10:41, Sergey Senozhatsky
<[email protected]> wrote:
>
> On (20/07/20 08:43), Marco Elver wrote:
> > On Sun, Jul 19, 2020 at 12:43PM +0900, Sergey Senozhatsky wrote:
> >
> > As I said, a number of debugging tools use them to format reports to be
> > more readable (visually separate title and report body, and separate
> > parts of the report). Also, such reports are often parsed by CI systems,
> > and by changing the reports, these CI systems may break. But those are
> > just the usecases I'm acutely aware of
>
> Can you give example of such CI systems? // that's a real question //
None of ours should break; I agree the CI system is brittle if it
relies on newlines. Parsed and displayed reports are changing, however
-- what irks me is now all the reports sent to the LKML look ugly.
Some random KASAN reports (just compare formatting):
next (ugly): https://lore.kernel.org/lkml/[email protected]/
mainline (normal):
https://lore.kernel.org/lkml/[email protected]/
The same problem exists with lockdep reports, KCSAN reports, ... If
newline-printks to insert blank lines are now banned, what are we to
do? Send dozens of patches to switch everyone to printk(" \n")? Or
some better suggestion? I cannot yet see how that is an improvement.
(And if the behaviour is not reverted, please document the new
behaviour.)
That also doesn't yet address the ~400 other newline-printk users, and
somebody needs to do the due diligence to understand if it's just a
flush, or an intentional blank line.
Thanks,
-- Marco
On Mon, Jul 20, 2020 at 11:41 AM Marco Elver <[email protected]> wrote:
>
> On Mon, 20 Jul 2020 at 10:41, Sergey Senozhatsky
> <[email protected]> wrote:
> >
> > On (20/07/20 08:43), Marco Elver wrote:
> > > On Sun, Jul 19, 2020 at 12:43PM +0900, Sergey Senozhatsky wrote:
> > >
> > > As I said, a number of debugging tools use them to format reports to be
> > > more readable (visually separate title and report body, and separate
> > > parts of the report). Also, such reports are often parsed by CI systems,
> > > and by changing the reports, these CI systems may break. But those are
> > > just the usecases I'm acutely aware of
> >
> > Can you give example of such CI systems? // that's a real question //
>
> None of ours should break; I agree the CI system is brittle if it
> relies on newlines. Parsed and displayed reports are changing, however
> -- what irks me is now all the reports sent to the LKML look ugly.
>
> Some random KASAN reports (just compare formatting):
> next (ugly): https://lore.kernel.org/lkml/[email protected]/
> mainline (normal):
> https://lore.kernel.org/lkml/[email protected]/
>
> The same problem exists with lockdep reports, KCSAN reports, ... If
> newline-printks to insert blank lines are now banned, what are we to
> do? Send dozens of patches to switch everyone to printk(" \n")? Or
> some better suggestion? I cannot yet see how that is an improvement.
> (And if the behaviour is not reverted, please document the new
> behaviour.)
>
> That also doesn't yet address the ~400 other newline-printk users, and
> somebody needs to do the due diligence to understand if it's just a
> flush, or an intentional blank line.
Empty lines improve readability of long crash reports significantly.
New lines in sanitizer reports originated in Go race reports 7 years
ago and then spread to user-space ASAN/MSAN/TSAN b/c that was an
improvement and then were specifically added to kernel sanitizers.
This is even more important now that we have up to 5 stacks in KASAN
reports.
Please keep them.
Also having lots of printk("\n") sprinkled in kernel code and turning
them into no-op separately does not look like the right solution.
These printk("\n") are confusing and add clutter. A better solution
would be to remove these printk("\n") from the code. But this also
naturally allows selective removal. Say, keeping for sanitizers and
some other cases, but removing some that are not useful.
On 2020-07-18, Marco Elver <[email protected]> wrote:
> It seems this causes a regression observed at least with newline-only
> printks.
> [...]
> ------ >8 ------
>
> --- a/init/main.c
> +++ b/init/main.c
> @@ -1039,6 +1039,10 @@ asmlinkage __visible void __init start_kernel(void)
> sfi_init_late();
> kcsan_init();
>
> + pr_info("EXPECT BLANK LINE --vv\n");
> + pr_info("\n");
> + pr_info("EXPECT BLANK LINE --^^\n");
> +
> /* Do the rest non-__init'ed, we're now alive */
> arch_call_rest_init();
Thanks for the example. This is an unintentional regression in the
series. I will submit a patch to fix this.
Note that this regression does not exist when the followup series [0]
(reimplementing LOG_CONT) is applied. All the more reason that the 1st
series should be fixed before pushing the 2nd series to linux-next.
John Ogness
[0] https://lkml.kernel.org/r/[email protected]
On Mon, 20 Jul 2020 at 12:20, John Ogness <[email protected]> wrote:
>
> On 2020-07-18, Marco Elver <[email protected]> wrote:
> > It seems this causes a regression observed at least with newline-only
> > printks.
> > [...]
> > ------ >8 ------
> >
> > --- a/init/main.c
> > +++ b/init/main.c
> > @@ -1039,6 +1039,10 @@ asmlinkage __visible void __init start_kernel(void)
> > sfi_init_late();
> > kcsan_init();
> >
> > + pr_info("EXPECT BLANK LINE --vv\n");
> > + pr_info("\n");
> > + pr_info("EXPECT BLANK LINE --^^\n");
> > +
> > /* Do the rest non-__init'ed, we're now alive */
> > arch_call_rest_init();
>
> Thanks for the example. This is an unintentional regression in the
> series. I will submit a patch to fix this.
>
> Note that this regression does not exist when the followup series [0]
> (reimplementing LOG_CONT) is applied. All the more reason that the 1st
> series should be fixed before pushing the 2nd series to linux-next.
Great, thank you for clarifying! :-)
-- Marco
> John Ogness
>
> [0] https://lkml.kernel.org/r/[email protected]
From what I can tell, I think this patch ("printk: use the lockless
ringbuffer") breaks lx-dmesg in CONFIG_GDB_SCRIPTS.
(gdb) lx-dmesg
Python Exception <class 'gdb.error'> No symbol "log_first_idx" in specified context.:
Error occurred in Python: No symbol "log_first_idx" in specified context.
This command is used to dump the printk log buffer.
It looks like the only places left in the kernel that reference are:
- Documentation/admin-guide/kdump/gdbmacros.txt
- Documentation/admin-guide/kdump/vmcoreinfo.rst
- scripts/gdb/linux/dmesg.py
I believe this commit removed log_first_idx, so all of the above probably need
to be fixed up, too.
~ Nick
On 2020-08-11, Nick Desaulniers <[email protected]> wrote:
> From what I can tell, I think this patch ("printk: use the lockless
> ringbuffer") breaks lx-dmesg in CONFIG_GDB_SCRIPTS.
>
> (gdb) lx-dmesg
> Python Exception <class 'gdb.error'> No symbol "log_first_idx" in specified context.:
> Error occurred in Python: No symbol "log_first_idx" in specified context.
>
> This command is used to dump the printk log buffer.
>
> It looks like the only places left in the kernel that reference are:
>
> - Documentation/admin-guide/kdump/gdbmacros.txt
> - Documentation/admin-guide/kdump/vmcoreinfo.rst
> - scripts/gdb/linux/dmesg.py
>
> I believe this commit removed log_first_idx, so all of the above
> probably need to be fixed up, too.
Thanks for pointing this out! I will get to work on a patch for this.
John Ogness
Hello,
When doing some internal testing on a 5.10.4 kernel, we found that the
time taken for dmesg seemed to increase from the order of milliseconds to
the order of seconds when the dmesg size approached the ~1.2MB limit. After
doing some digging, we found that by reverting all of the patches in printk/
up to and including 896fbe20b4e2333fb55cc9b9b783ebcc49eee7c7 ("use the
lockless ringbuffer"), we were able to once more see normal dmesg times.
This kernel had no meaningful diffs in the printk/ dir when compared to
Linus' tree. This behavior was consistently reproducible using the
following steps:
1) In one shell, run "time dmesg > /dev/null"
2) In another, constantly write to /dev/kmsg
Within ~5 minutes, we saw that dmesg times increased to 1 second, only
increasing further from there. Is this a known issue?
Thank you,
Avila
On 2021-01-22, "J. Avila" <[email protected]> wrote:
> When doing some internal testing on a 5.10.4 kernel, we found that the
> time taken for dmesg seemed to increase from the order of milliseconds
> to the order of seconds when the dmesg size approached the ~1.2MB
> limit. After doing some digging, we found that by reverting all of the
> patches in printk/ up to and including
> 896fbe20b4e2333fb55cc9b9b783ebcc49eee7c7 ("use the lockless
> ringbuffer"), we were able to once more see normal dmesg times.
>
> This kernel had no meaningful diffs in the printk/ dir when compared
> to Linus' tree. This behavior was consistently reproducible using the
> following steps:
>
> 1) In one shell, run "time dmesg > /dev/null"
> 2) In another, constantly write to /dev/kmsg
>
> Within ~5 minutes, we saw that dmesg times increased to 1 second, only
> increasing further from there. Is this a known issue?
The last couple days I have tried to reproduce this issue with no
success.
Is your dmesg using /dev/kmsg or syslog() to read the buffer?
Are there any syslog daemons or systemd running? Perhaps you can run
your test within an initrd to see if this effect is still visible?
John Ogness
Hello,
This dmesg uses /dev/kmsg; we've verified that we don't see this long
dmesg time when reading from syslog (via dmesg -S).
We've also tried testing this with logging daemons disabled as well as
within initrd - both result in similar behavior.
If it's relevant, this was done on a toybox shell.
Thanks,
Avila
On Mon, Jan 25, 2021 at 5:32 AM John Ogness <[email protected]> wrote:
>
> On 2021-01-22, "J. Avila" <[email protected]> wrote:
> > When doing some internal testing on a 5.10.4 kernel, we found that the
> > time taken for dmesg seemed to increase from the order of milliseconds
> > to the order of seconds when the dmesg size approached the ~1.2MB
> > limit. After doing some digging, we found that by reverting all of the
> > patches in printk/ up to and including
> > 896fbe20b4e2333fb55cc9b9b783ebcc49eee7c7 ("use the lockless
> > ringbuffer"), we were able to once more see normal dmesg times.
> >
> > This kernel had no meaningful diffs in the printk/ dir when compared
> > to Linus' tree. This behavior was consistently reproducible using the
> > following steps:
> >
> > 1) In one shell, run "time dmesg > /dev/null"
> > 2) In another, constantly write to /dev/kmsg
> >
> > Within ~5 minutes, we saw that dmesg times increased to 1 second, only
> > increasing further from there. Is this a known issue?
>
> The last couple days I have tried to reproduce this issue with no
> success.
>
> Is your dmesg using /dev/kmsg or syslog() to read the buffer?
>
> Are there any syslog daemons or systemd running? Perhaps you can run
> your test within an initrd to see if this effect is still visible?
>
> John Ogness
Hello John,
I’ve done some additional digging on my end. I tested using a 5.10.11
kernel and observed the following:
1) With the default of CONFIG_LOG_BUF_SHIFT=17, I was not able to reproduce
the issue.
2) With CONFIG_LOG_BUF_SHIFT=20, I was able to reproduce the behavior
mentioned before.
3) With (2) + reverting up to and including 896fbe20b4e2 (printk: use the
lockless ringbuffer), I saw short dmesg times again.
It seems that this issue may only exist with a sufficiently big log buffer
size. Despite 1MB being a relatively uncommon size for linux kernel log
buffers, this still indicates a potential issue in the code; do you think
it's worth investigation?
Thanks,
Avila
On Mon, Jan 25, 2021 at 4:00 PM J. Avila <[email protected]> wrote:
>
> Hello,
>
> This dmesg uses /dev/kmsg; we've verified that we don't see this long
> dmesg time when reading from syslog (via dmesg -S).
>
> We've also tried testing this with logging daemons disabled as well as
> within initrd - both result in similar behavior.
>
> If it's relevant, this was done on a toybox shell.
>
> Thanks,
>
> Avila
>
> On Mon, Jan 25, 2021 at 5:32 AM John Ogness <[email protected]> wrote:
> >
> > On 2021-01-22, "J. Avila" <[email protected]> wrote:
> > > When doing some internal testing on a 5.10.4 kernel, we found that the
> > > time taken for dmesg seemed to increase from the order of milliseconds
> > > to the order of seconds when the dmesg size approached the ~1.2MB
> > > limit. After doing some digging, we found that by reverting all of the
> > > patches in printk/ up to and including
> > > 896fbe20b4e2333fb55cc9b9b783ebcc49eee7c7 ("use the lockless
> > > ringbuffer"), we were able to once more see normal dmesg times.
> > >
> > > This kernel had no meaningful diffs in the printk/ dir when compared
> > > to Linus' tree. This behavior was consistently reproducible using the
> > > following steps:
> > >
> > > 1) In one shell, run "time dmesg > /dev/null"
> > > 2) In another, constantly write to /dev/kmsg
> > >
> > > Within ~5 minutes, we saw that dmesg times increased to 1 second, only
> > > increasing further from there. Is this a known issue?
> >
> > The last couple days I have tried to reproduce this issue with no
> > success.
> >
> > Is your dmesg using /dev/kmsg or syslog() to read the buffer?
> >
> > Are there any syslog daemons or systemd running? Perhaps you can run
> > your test within an initrd to see if this effect is still visible?
> >
> > John Ogness