This series rearranges the log code in such a way that the LOG_CONT
and LOG_PREFIX log record flags can be eliminated entirely. The
result should be considerably easier to understand than before. It
builds on another recently-posted series of patches:
https://lkml.org/lkml/2014/7/17/363
The first patch exploits the fact that LOG_CONT and LOG_NEWLINE
are inverses, and uses LOG_NEWLINE (or its negation) anywhere
LOG_CONT is used. As a result, LOG_CONT is no longer needed, so
it's eliminated.
The next three patches together eliminate LOG_PREFIX. The effect
of LOG_PREFIX is to complete the previous log entry before recording
a new one. Patch 2 arranges to do this directly, marking the previous
log record with LOG_NEWLINE whenever a new record is presented with
LOG_PREFIX set. Patch 3 stops saving LOG_PREFIX in any log records,
and patch 4 finally gets rid of LOG_PREFIX.
The last patch is just some cleanup of the code now that it's gone
through this transformation.
-Alex
This series is available here:
http://git.linaro.org/landing-teams/working/broadcom/kernel.git
Branch review/more-printk-flags
It is based on branch review/printk-flags-v2 in that same repository.
Alex Elder (5):
printk: kill LOG_CONT
printk: update previous message for LOG_PREFIX
printk: stop actually recording LOG_PREFIX
printk: kill LOG_PREFIX
printk: rename LOG_NEWLINE and tidy up
kernel/printk/printk.c | 135 +++++++++++++++++++++++++++++--------------------
1 file changed, 81 insertions(+), 54 deletions(-)
--
1.9.1
Whenever log_store() sees a LOG_PREFIX flag it marks the previous
log entry (if there is one) with LOG_NEWLINE, which (also) produces
the desired effect.
There's therefore no need to record LOG_PREFIX in log records.
If no log entries contain LOG_PREFIX, devkmsg_read() and
msg_print_text() don't need to check for it.
Signed-off-by: Alex Elder <[email protected]>
---
kernel/printk/printk.c | 11 +++++++----
1 file changed, 7 insertions(+), 4 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6b72a77..df38b5e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -432,8 +432,11 @@ static int log_store(int facility, int level,
* If we're forcing a new log record, update the flags for
* the previous one to mark it complete.
*/
- if (flags & LOG_PREFIX && log_last_msg)
- log_last_msg->flags |= LOG_NEWLINE;
+ if (flags & LOG_PREFIX) {
+ if (log_last_msg)
+ log_last_msg->flags |= LOG_NEWLINE;
+ flags &= ~LOG_PREFIX;
+ }
msg = (struct printk_log *)(log_buf + log_next_idx);
memcpy(log_text(msg), text, text_len);
@@ -633,7 +636,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
* a record that should be merged with one or more earlier records.
* And a '-' indicates a "normal" self-contained single record.
*/
- if (!(user->prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
+ if (!(user->prev & LOG_NEWLINE))
cont = '+';
else if (!(msg->flags & LOG_NEWLINE))
cont = 'c';
@@ -1020,7 +1023,7 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
bool newline = true;
size_t len = 0;
- if (!(prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
+ if (!(prev & LOG_NEWLINE))
prefix = false;
if (!(msg->flags & LOG_NEWLINE))
--
1.9.1
Rename LOG_NEWLINE to be LOG_COMPLETE, so it makes more sense in the
context of a log record (or a string of them) rather than how a
record gets formatted.
Add a block of commentary explaining how the log flags indicate that
consecutive log records should be treated as a single logical log
entry.
Do some other tidying of the code now that a lot of the former flags
complexity has been eliminated.
Signed-off-by: Alex Elder <[email protected]>
---
kernel/printk/printk.c | 73 +++++++++++++++++++++++++++++---------------------
1 file changed, 42 insertions(+), 31 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index bfc2581..69bfd39 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -150,7 +150,7 @@ static int console_may_schedule;
* are stored..
*
* If the heads indicate available messages, the length in the header
- * tells the start next message. A length == 0 for the next message
+ * tells the start of the next message. A length == 0 for the next message
* indicates a wrap-around to the beginning of the buffer.
*
* Every record carries the monotonic timestamp in microseconds, as well as
@@ -159,6 +159,17 @@ static int console_may_schedule;
* a matching syslog facility, by default LOG_USER. The origin of every
* message can be reliably determined that way.
*
+ * If a printk() call doesn't end in a newline, the content of the message
+ * is buffered temporarily so that a subsequent printk() call can be
+ * appended to it. Occasionally a buffered/partial message needs to be
+ * flushed to the log before the logically next printk() call is seen.
+ * This is distinguished in log records by the presence (or absence) of a
+ * LOG_COMPLETE flag. In this case the last log record comprising a
+ * the original message has LOG_COMPLETE set; the rest do not. When
+ * formatted, a log record will include a prefix (including a time stamp
+ * and possibly a syslog value) whenever its predecessor in the log was
+ * marked LOG_COMPLETE.
+ *
* 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.
@@ -209,7 +220,7 @@ static int console_may_schedule;
enum log_flags {
LOG_NOCONS = 1, /* already flushed, do not print to console */
- LOG_NEWLINE = 2, /* text ended with a newline */
+ LOG_COMPLETE = 2, /* this record ends a log entry */
};
struct printk_log {
@@ -432,7 +443,7 @@ static int log_store(int facility, int level, bool force_new,
* the previous one to mark it complete.
*/
if (force_new && log_last_msg)
- log_last_msg->flags |= LOG_NEWLINE;
+ log_last_msg->flags |= LOG_COMPLETE;
msg = (struct printk_log *)(log_buf + log_next_idx);
memcpy(log_text(msg), text, text_len);
@@ -632,9 +643,9 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
* a record that should be merged with one or more earlier records.
* And a '-' indicates a "normal" self-contained single record.
*/
- if (!(user->prev & LOG_NEWLINE))
+ if (!(user->prev & LOG_COMPLETE))
cont = '+';
- else if (!(msg->flags & LOG_NEWLINE))
+ else if (!(msg->flags & LOG_COMPLETE))
cont = 'c';
else
cont = '-';
@@ -1015,15 +1026,9 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
{
const char *text = log_text(msg);
size_t text_size = msg->text_len;
- bool prefix = true;
- bool newline = true;
size_t len = 0;
-
- if (!(prev & LOG_NEWLINE))
- prefix = false;
-
- if (!(msg->flags & LOG_NEWLINE))
- newline = false;
+ bool prefix = !!(prev & LOG_COMPLETE);
+ bool newline = !!(msg->flags & LOG_COMPLETE);
do {
const char *next = memchr(text, '\n', text_size);
@@ -1556,7 +1561,8 @@ static size_t cont_print_text(char *text, size_t size)
size_t textlen = 0;
size_t len;
- if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
+ /* If we're starting a new one, format a time stamp */
+ if (cont.cons == 0 && console_prev & LOG_COMPLETE) {
textlen += print_time(cont.ts_nsec, text);
size -= textlen;
}
@@ -1571,7 +1577,7 @@ static size_t cont_print_text(char *text, size_t size)
}
if (cont.flushed) {
- if (cont.flags & LOG_NEWLINE)
+ if (cont.flags & LOG_COMPLETE)
text[textlen++] = '\n';
/* got everything, release buffer */
cont.len = 0;
@@ -1637,7 +1643,7 @@ asmlinkage int vprintk_emit(int facility, int level,
recursion_bug = 0;
text_len = strlen(recursion_msg);
/* emit KERN_CRIT message */
- printed_len += log_store(0, 2, true, LOG_NEWLINE, 0,
+ printed_len += log_store(0, 2, true, LOG_COMPLETE, 0,
NULL, 0, recursion_msg, text_len);
}
@@ -1659,7 +1665,7 @@ asmlinkage int vprintk_emit(int facility, int level,
*/
if (text_len && text[text_len-1] == '\n') {
text_len--;
- lflags = LOG_NEWLINE;
+ lflags = LOG_COMPLETE;
}
/* strip kernel syslog prefix and extract log level or control flags */
@@ -1690,17 +1696,23 @@ asmlinkage int vprintk_emit(int facility, int level,
if (dict) {
force_new = true;
- lflags = LOG_NEWLINE;
+ lflags = LOG_COMPLETE;
}
- if (!(lflags & LOG_NEWLINE)) {
+ /*
+ * If there's a partial record buffered by someone else
+ * we'll want to force a new entry to be started.
+ */
+ if (cont.len)
+ force_new |= cont.owner != current;
+ if (!(lflags & LOG_COMPLETE)) {
/*
* We're recording an incomplete record. We'll add it to the
- * "cont" buffer if possible, but if it contains data written
- * by somebody else we need to flush that to the log first.
+ * "cont" buffer if possible, but if we're forcing a new
+ * entry we need to flush the buffer to the log first.
*/
- if (cont.len && (force_new || cont.owner != current))
- cont_flush(LOG_NEWLINE);
+ if (cont.len && force_new)
+ cont_flush(LOG_COMPLETE);
/* If we're unable to buffer it, store it immediately */
if (cont_add(facility, level, text, text_len))
@@ -1713,18 +1725,17 @@ asmlinkage int vprintk_emit(int facility, int level,
bool stored = false;
/*
- * This record is complete (it should be formatted with a
- * newline), so we'll be writing it to the log. If there
- * are any incomplete records buffered we will need to
- * flush those to the log first. If possible, we'll add
- * this record to the buffer first. If there's nothing
- * buffered, just write this record to the log.
+ * This record is complete, so we'll be writing it to the log.
+ * If there are any incomplete records buffered we'll try to
+ * add this record to the buffer before flushing it to the log.
+ * Otherwise if there's nothing buffered, just write this
+ * record to the log directly.
*/
if (cont.len) {
- if (cont.owner == current && !force_new)
+ if (!force_new)
stored = cont_add(facility, level, text,
text_len);
- cont_flush(LOG_NEWLINE);
+ cont_flush(LOG_COMPLETE);
}
if (stored)
--
1.9.1
The LOG_CONT and LOG_NEWLINE flags are mutually exclusive, i.e.,
the presence of LOG_NEWLINE implies the absense of LOG_CONT, and
vice-versa. As a result, wherever LOG_CONT is used, we can
equivalently substitute !LOG_NEWLINE; and we can use LOG_NEWLINE
wherever !LOG_CONT is used.
Switch to using LOG_NEWLINE only, and get rid of LOG_CONT. Make
some refinements on a nearby block of comments.
Signed-off-by: Alex Elder <[email protected]>
---
kernel/printk/printk.c | 29 ++++++++++++++---------------
1 file changed, 14 insertions(+), 15 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index eff68a4..e35d91a 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -211,7 +211,6 @@ enum log_flags {
LOG_NOCONS = 1, /* already flushed, do not print to console */
LOG_NEWLINE = 2, /* text ended with a newline */
LOG_PREFIX = 4, /* text started with a prefix */
- LOG_CONT = 8, /* text is a fragment of a continuation line */
};
struct printk_log {
@@ -613,16 +612,18 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
do_div(ts_usec, 1000);
/*
- * If we couldn't merge continuation line fragments during the print,
- * export the stored flags to allow an optional external merge of the
- * records. Merging the records isn't always necessarily correct, like
- * when we hit a race during printing. In most cases though, it produces
- * better readable output. 'c' in the record flags mark the first
- * fragment of a line, '+' the following.
+ * Sometimes it's necessary to flush an incomplete record to the log.
+ * When this happens, consecutive records should be merged to produce
+ * a logically complete message.
+ *
+ * Indicate this to user space with a flag character. A 'c' indicates
+ * the first of a series of incomplete log records. A '+' indicates
+ * a record that should be merged with one or more earlier records.
+ * And a '-' indicates a "normal" self-contained single record.
*/
- if ((user->prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
+ if (!(user->prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
cont = '+';
- else if (msg->flags & LOG_CONT)
+ else if (!(msg->flags & LOG_NEWLINE))
cont = 'c';
else
cont = '-';
@@ -1007,10 +1008,10 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
bool newline = true;
size_t len = 0;
- if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
+ if (!(prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
prefix = false;
- if (msg->flags & LOG_CONT)
+ if (!(msg->flags & LOG_NEWLINE))
newline = false;
do {
@@ -1516,7 +1517,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
if (cont.len + len > sizeof(cont.buf)) {
/* the line gets too long, split it up in separate records */
- cont_flush(LOG_CONT);
+ cont_flush(0);
return false;
}
@@ -1534,7 +1535,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
cont.len += len;
if (cont.len > (sizeof(cont.buf) * 80) / 100)
- cont_flush(LOG_CONT);
+ cont_flush(0);
return true;
}
@@ -1647,8 +1648,6 @@ asmlinkage int vprintk_emit(int facility, int level,
if (text_len && text[text_len-1] == '\n') {
text_len--;
lflags = LOG_NEWLINE;
- } else {
- lflags = LOG_CONT;
}
/* strip kernel syslog prefix and extract log level or control flags */
--
1.9.1
The only place that uses LOG_PREFIX is log_store(), and that
now strips it from the flags field before recording it in a log
buffer.
Switch to passing a Boolean flag to log_store() to indicate whether
this record should force a new record--that is, complete the
previous one--and eliminate the LOG_PREFIX flag altogether. Update
a few comments as well.
Signed-off-by: Alex Elder <[email protected]>
---
kernel/printk/printk.c | 60 ++++++++++++++++++++++++++------------------------
1 file changed, 31 insertions(+), 29 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index df38b5e..bfc2581 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -210,7 +210,6 @@ static int console_may_schedule;
enum log_flags {
LOG_NOCONS = 1, /* already flushed, do not print to console */
LOG_NEWLINE = 2, /* text ended with a newline */
- LOG_PREFIX = 4, /* text started with a prefix */
};
struct printk_log {
@@ -397,7 +396,7 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
}
/* insert record into the buffer, discard old ones, update heads */
-static int log_store(int facility, int level,
+static int log_store(int facility, int level, bool force_new,
enum log_flags flags, u64 ts_nsec,
const char *dict, u16 dict_len,
const char *text, u16 text_len)
@@ -432,11 +431,8 @@ static int log_store(int facility, int level,
* If we're forcing a new log record, update the flags for
* the previous one to mark it complete.
*/
- if (flags & LOG_PREFIX) {
- if (log_last_msg)
- log_last_msg->flags |= LOG_NEWLINE;
- flags &= ~LOG_PREFIX;
- }
+ if (force_new && log_last_msg)
+ log_last_msg->flags |= LOG_NEWLINE;
msg = (struct printk_log *)(log_buf + log_next_idx);
memcpy(log_text(msg), text, text_len);
@@ -1493,7 +1489,7 @@ static struct cont {
u64 ts_nsec; /* time of first print */
u8 level; /* log level of first message */
u8 facility; /* log level of first message */
- enum log_flags flags; /* prefix, newline flags */
+ enum log_flags flags; /* nocons, newline flags */
bool flushed:1; /* buffer sealed and committed */
} cont;
@@ -1510,7 +1506,7 @@ static void cont_flush(enum log_flags flags)
* console; wait for the console to pick up the rest of the
* line. LOG_NOCONS suppresses a duplicated output.
*/
- log_store(cont.facility, cont.level, flags | LOG_NOCONS,
+ log_store(cont.facility, cont.level, false, flags | LOG_NOCONS,
cont.ts_nsec, NULL, 0, cont.buf, cont.len);
cont.flags = flags;
cont.flushed = true;
@@ -1519,7 +1515,7 @@ static void cont_flush(enum log_flags flags)
* If no fragment of this line ever reached the console,
* just submit it to the store and free the buffer.
*/
- log_store(cont.facility, cont.level, flags, 0,
+ log_store(cont.facility, cont.level, false, flags, 0,
NULL, 0, cont.buf, cont.len);
cont.len = 0;
}
@@ -1596,6 +1592,7 @@ asmlinkage int vprintk_emit(int facility, int level,
int this_cpu;
int printed_len = 0;
bool in_sched = false;
+ bool force_new = false;
/* cpu currently holding logbuf_lock in this function */
static volatile unsigned int logbuf_cpu = UINT_MAX;
@@ -1640,7 +1637,7 @@ asmlinkage int vprintk_emit(int facility, int level,
recursion_bug = 0;
text_len = strlen(recursion_msg);
/* emit KERN_CRIT message */
- printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
+ printed_len += log_store(0, 2, true, LOG_NEWLINE, 0,
NULL, 0, recursion_msg, text_len);
}
@@ -1676,7 +1673,7 @@ asmlinkage int vprintk_emit(int facility, int level,
if (level == -1)
level = kern_level - '0';
case 'd': /* KERN_DEFAULT */
- lflags |= LOG_PREFIX;
+ force_new = true;
}
/*
* No need to check length here because vscnprintf
@@ -1691,36 +1688,40 @@ asmlinkage int vprintk_emit(int facility, int level,
if (level == -1)
level = default_message_loglevel;
- if (dict)
- lflags = LOG_PREFIX|LOG_NEWLINE;
+ if (dict) {
+ force_new = true;
+ lflags = LOG_NEWLINE;
+ }
if (!(lflags & LOG_NEWLINE)) {
/*
- * Flush the conflicting buffer. An earlier newline was missing,
- * or another task also prints continuation lines.
+ * We're recording an incomplete record. We'll add it to the
+ * "cont" buffer if possible, but if it contains data written
+ * by somebody else we need to flush that to the log first.
*/
- if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
+ if (cont.len && (force_new || cont.owner != current))
cont_flush(LOG_NEWLINE);
- /* buffer line if possible, otherwise store it right away */
+ /* If we're unable to buffer it, store it immediately */
if (cont_add(facility, level, text, text_len))
printed_len += text_len;
else
- printed_len += log_store(facility, level, lflags, 0,
- NULL, 0, text, text_len);
+ printed_len += log_store(facility, level, force_new,
+ lflags, 0, NULL, 0,
+ text, text_len);
} else {
bool stored = false;
/*
- * If an earlier newline was missing and it was the same task,
- * either merge it with the current buffer and flush, or if
- * there was a race with interrupts (prefix == true) then just
- * flush it out and store this line separately.
- * If the preceding printk was from a different task and missed
- * a newline, flush and append the newline.
+ * This record is complete (it should be formatted with a
+ * newline), so we'll be writing it to the log. If there
+ * are any incomplete records buffered we will need to
+ * flush those to the log first. If possible, we'll add
+ * this record to the buffer first. If there's nothing
+ * buffered, just write this record to the log.
*/
if (cont.len) {
- if (cont.owner == current && !(lflags & LOG_PREFIX))
+ if (cont.owner == current && !force_new)
stored = cont_add(facility, level, text,
text_len);
cont_flush(LOG_NEWLINE);
@@ -1729,8 +1730,9 @@ asmlinkage int vprintk_emit(int facility, int level,
if (stored)
printed_len += text_len;
else
- printed_len += log_store(facility, level, lflags, 0,
- dict, dictlen, text, text_len);
+ printed_len += log_store(facility, level, force_new,
+ lflags, 0, dict, dictlen,
+ text, text_len);
}
logbuf_cpu = UINT_MAX;
--
1.9.1
If log_store() gets flags containing LOG_PREFIX, it indicates the
record getting stored should implicitly complete the previous log
record and start a new one.
We can also ensure the previous record is completed by keeping
track of the previously-logged record, and adding the LOG_NEWLINE
flag to it when log_store() sees a LOG_PREFIX flag.
Signed-off-by: Alex Elder <[email protected]>
---
kernel/printk/printk.c | 14 +++++++++++++-
1 file changed, 13 insertions(+), 1 deletion(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e35d91a..6b72a77 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -242,6 +242,9 @@ static size_t syslog_partial;
static u64 log_first_seq;
static u32 log_first_idx;
+/* Pointer to the last record written into the log */
+static struct printk_log *log_last_msg;
+
/* index and sequence number of the next record to store in the buffer */
static u64 log_next_seq;
static u32 log_next_idx;
@@ -425,7 +428,13 @@ static int log_store(int facility, int level,
log_next_idx = 0;
}
- /* fill message */
+ /*
+ * If we're forcing a new log record, update the flags for
+ * the previous one to mark it complete.
+ */
+ if (flags & LOG_PREFIX && log_last_msg)
+ log_last_msg->flags |= LOG_NEWLINE;
+
msg = (struct printk_log *)(log_buf + log_next_idx);
memcpy(log_text(msg), text, text_len);
msg->text_len = text_len;
@@ -449,6 +458,9 @@ static int log_store(int facility, int level,
log_next_idx += msg->len;
log_next_seq++;
+ /* Save our previous record address for next time. */
+ log_last_msg = msg;
+
return msg->text_len;
}
--
1.9.1
On Thu, Jul 17, 2014 at 7:59 PM, Alex Elder <[email protected]> wrote:
> This series rearranges the log code in such a way that the LOG_CONT
> and LOG_PREFIX log record flags can be eliminated entirely. The
> result should be considerably easier to understand than before. It
> builds on another recently-posted series of patches:
> https://lkml.org/lkml/2014/7/17/363
>
> The first patch exploits the fact that LOG_CONT and LOG_NEWLINE
> are inverses, and uses LOG_NEWLINE (or its negation) anywhere
> LOG_CONT is used. As a result, LOG_CONT is no longer needed, so
> it's eliminated.
>
> The next three patches together eliminate LOG_PREFIX. The effect
> of LOG_PREFIX is to complete the previous log entry before recording
> a new one. Patch 2 arranges to do this directly, marking the previous
> log record with LOG_NEWLINE whenever a new record is presented with
> LOG_PREFIX set. Patch 3 stops saving LOG_PREFIX in any log records,
> and patch 4 finally gets rid of LOG_PREFIX.
>
> The last patch is just some cleanup of the code now that it's gone
> through this transformation.
Continuation lines are racy and unreliable by definition, they create
a problem that cannot be solved properly, so we need to try to make
the best out of it. The idea of the record buffer flags was to record
what actually happened when things race against each other. A line
without a newline is recorded as a line without a newline.
Your simplifying patches changes the code to store how things will
*look* like when exported, not what actually *happened*; like it
pretends the earlier line had a newline, while that might not have
been the case.
Maybe your simplified logic is "good enough" for the common use cases,
I haven't thought it through, but it sounds a bit strange to pretend
things in the flags of a record which actually did not happen for this
record that way, just to save a bit in a flag field.
Thanks,
Kay
On 07/17/2014 08:37 PM, Kay Sievers wrote:
> On Thu, Jul 17, 2014 at 7:59 PM, Alex Elder <[email protected]> wrote:
>> This series rearranges the log code in such a way that the LOG_CONT
>> and LOG_PREFIX log record flags can be eliminated entirely. The
>> result should be considerably easier to understand than before. It
>> builds on another recently-posted series of patches:
>> https://lkml.org/lkml/2014/7/17/363
>>
>> The first patch exploits the fact that LOG_CONT and LOG_NEWLINE
>> are inverses, and uses LOG_NEWLINE (or its negation) anywhere
>> LOG_CONT is used. As a result, LOG_CONT is no longer needed, so
>> it's eliminated.
>>
>> The next three patches together eliminate LOG_PREFIX. The effect
>> of LOG_PREFIX is to complete the previous log entry before recording
>> a new one. Patch 2 arranges to do this directly, marking the previous
>> log record with LOG_NEWLINE whenever a new record is presented with
>> LOG_PREFIX set. Patch 3 stops saving LOG_PREFIX in any log records,
>> and patch 4 finally gets rid of LOG_PREFIX.
>>
>> The last patch is just some cleanup of the code now that it's gone
>> through this transformation.
>
> Continuation lines are racy and unreliable by definition, they create
> a problem that cannot be solved properly, so we need to try to make
> the best out of it. The idea of the record buffer flags was to record
> what actually happened when things race against each other. A line
> without a newline is recorded as a line without a newline.
Understood.
> Your simplifying patches changes the code to store how things will
> *look* like when exported, not what actually *happened*; like it
> pretends the earlier line had a newline, while that might not have
> been the case.
What do you mean by "exported?" Does the result in syslog
or /proc/kmsg (or the console for that matter) actually
differ? I'll have to look again, but I think they do not.
I believe with the changes I made, all log records are saved in
exactly the same order, and buffered records are merged in exactly
the same way as before. It's just that !LOG_NEWLINE is now treated
as the same as LOG_CONT, and the effect of LOG_PREFIX is done by
"completing" the previous record.
I do see your point though, that the fact that a newline
was added by a successor entry loses the piece of information
that the previous one didn't have one originally. Is that
significant information? I don't believe it's visible outside
the in-core log records.
> Maybe your simplified logic is "good enough" for the common use cases,
> I haven't thought it through, but it sounds a bit strange to pretend
> things in the flags of a record which actually did not happen for this
> record that way, just to save a bit in a flag field.
It is not about saving bits, it's about making the
code more understandable. As it was, only after
looking very hard at this to see things could be
refactored that I saw that the one case (where PREFIX
did not override a previous CONT flag) had a bug.
My sincere intention was to preserve exactly the same
behavior, but do so with fewer flags. The net result
is the same, but you're right, I realize now there was
some information loss--I just didn't recognize that
information as important.
I really appreciate your looking this stuff over Kay.
-Alex
> Thanks,
> Kay
>
On Thu 2014-07-17 12:59:10, Alex Elder wrote:
> If log_store() gets flags containing LOG_PREFIX, it indicates the
> record getting stored should implicitly complete the previous log
> record and start a new one.
>
> We can also ensure the previous record is completed by keeping
> track of the previously-logged record, and adding the LOG_NEWLINE
> flag to it when log_store() sees a LOG_PREFIX flag.
>
> Signed-off-by: Alex Elder <[email protected]>
> ---
> kernel/printk/printk.c | 14 +++++++++++++-
> 1 file changed, 13 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e35d91a..6b72a77 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -242,6 +242,9 @@ static size_t syslog_partial;
> static u64 log_first_seq;
> static u32 log_first_idx;
>
> +/* Pointer to the last record written into the log */
> +static struct printk_log *log_last_msg;
> +
> /* index and sequence number of the next record to store in the buffer */
> static u64 log_next_seq;
> static u32 log_next_idx;
> @@ -425,7 +428,13 @@ static int log_store(int facility, int level,
> log_next_idx = 0;
> }
>
> - /* fill message */
> + /*
> + * If we're forcing a new log record, update the flags for
> + * the previous one to mark it complete.
> + */
> + if (flags & LOG_PREFIX && log_last_msg)
> + log_last_msg->flags |= LOG_NEWLINE;
You are not allowed to do this. The previous message might already be
proceed by readers (console, syslog, kmsg).
IMHO, you will not be able to make this safe without adding extra
complexity into the readers. So, I am afraid that there is no win
in vanishing the LOG_PREFIX flag.
Best Regards,
Petr
> msg = (struct printk_log *)(log_buf + log_next_idx);
> memcpy(log_text(msg), text, text_len);
> msg->text_len = text_len;
> @@ -449,6 +458,9 @@ static int log_store(int facility, int level,
> log_next_idx += msg->len;
> log_next_seq++;
>
> + /* Save our previous record address for next time. */
> + log_last_msg = msg;
> +
> return msg->text_len;
> }
>
> --
> 1.9.1
>
On Thu 2014-07-17 20:54:35, Alex Elder wrote:
> On 07/17/2014 08:37 PM, Kay Sievers wrote:
> > On Thu, Jul 17, 2014 at 7:59 PM, Alex Elder <[email protected]> wrote:
> >> This series rearranges the log code in such a way that the LOG_CONT
> >> and LOG_PREFIX log record flags can be eliminated entirely. The
> >> result should be considerably easier to understand than before. It
> >> builds on another recently-posted series of patches:
> >> https://lkml.org/lkml/2014/7/17/363
> >>
> >> The first patch exploits the fact that LOG_CONT and LOG_NEWLINE
> >> are inverses, and uses LOG_NEWLINE (or its negation) anywhere
> >> LOG_CONT is used. As a result, LOG_CONT is no longer needed, so
> >> it's eliminated.
I think that only this part is usable. It would make sense to move it
to the other patch set.
> >> The next three patches together eliminate LOG_PREFIX. The effect
> >> of LOG_PREFIX is to complete the previous log entry before recording
> >> a new one. Patch 2 arranges to do this directly, marking the previous
> >> log record with LOG_NEWLINE whenever a new record is presented with
> >> LOG_PREFIX set. Patch 3 stops saving LOG_PREFIX in any log records,
> >> and patch 4 finally gets rid of LOG_PREFIX.
>>>
> >> The last patch is just some cleanup of the code now that it's gone
> >> through this transformation.
The other patches would break readers. You could not modify older
records because the might already have been proceed.
You would need to add another hacks to the readers. I think that using
LOG_PREFIX is more clear and less hacky.
> > Continuation lines are racy and unreliable by definition, they create
> > a problem that cannot be solved properly, so we need to try to make
> > the best out of it. The idea of the record buffer flags was to record
> > what actually happened when things race against each other. A line
> > without a newline is recorded as a line without a newline.
>
> Understood.
>
> > Your simplifying patches changes the code to store how things will
> > *look* like when exported, not what actually *happened*; like it
> > pretends the earlier line had a newline, while that might not have
> > been the case.
>
> What do you mean by "exported?" Does the result in syslog
> or /proc/kmsg (or the console for that matter) actually
> differ? I'll have to look again, but I think they do not.
Yes, they are asynchronous. Each of them has its own speed and
behavior.
Console is like a dog. It tries to process all new messages until
the very last one.
Syslog and kmsg are interfaces that are used by userspace tools,
e.g. syslogd, dmesg. They are asked to read selected part of
the ring buffer, usually the last messages. They might be asked to
seek, read everything again, ...
Syslog and kmsg have to release the logbuf_lock every time they copy
some line to the userspace. This is the time when the ring buffer
might get rotated and they might miss the end of continuous line.
Best Regards,
Petr
On 07/18/2014 04:02 AM, Petr Ml?dek wrote:
> On Thu 2014-07-17 12:59:10, Alex Elder wrote:
>> If log_store() gets flags containing LOG_PREFIX, it indicates the
>> record getting stored should implicitly complete the previous log
>> record and start a new one.
>>
>> We can also ensure the previous record is completed by keeping
>> track of the previously-logged record, and adding the LOG_NEWLINE
>> flag to it when log_store() sees a LOG_PREFIX flag.
>>
>> Signed-off-by: Alex Elder <[email protected]>
>> ---
>> kernel/printk/printk.c | 14 +++++++++++++-
>> 1 file changed, 13 insertions(+), 1 deletion(-)
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index e35d91a..6b72a77 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -242,6 +242,9 @@ static size_t syslog_partial;
>> static u64 log_first_seq;
>> static u32 log_first_idx;
>>
>> +/* Pointer to the last record written into the log */
>> +static struct printk_log *log_last_msg;
>> +
>> /* index and sequence number of the next record to store in the buffer */
>> static u64 log_next_seq;
>> static u32 log_next_idx;
>> @@ -425,7 +428,13 @@ static int log_store(int facility, int level,
>> log_next_idx = 0;
>> }
>>
>> - /* fill message */
>> + /*
>> + * If we're forcing a new log record, update the flags for
>> + * the previous one to mark it complete.
>> + */
>> + if (flags & LOG_PREFIX && log_last_msg)
>> + log_last_msg->flags |= LOG_NEWLINE;
>
> You are not allowed to do this. The previous message might already be
> proceed by readers (console, syslog, kmsg).
>
> IMHO, you will not be able to make this safe without adding extra
> complexity into the readers. So, I am afraid that there is no win
> in vanishing the LOG_PREFIX flag.
You're right. I had not been thinking about this.
We can't change the flag state of a log entry that's
already been read, and we have no (good) way of knowing
when that has occurred.
I'll retract this and related patches, and will rework
it accordingly. I'm still going to try to do what I
can with this (and the previous) series to be simplified.
I'm going to look at the rest of your reviews first.
Thank you.
-Alex
> Best Regards,
> Petr
>
>> msg = (struct printk_log *)(log_buf + log_next_idx);
>> memcpy(log_text(msg), text, text_len);
>> msg->text_len = text_len;
>> @@ -449,6 +458,9 @@ static int log_store(int facility, int level,
>> log_next_idx += msg->len;
>> log_next_seq++;
>>
>> + /* Save our previous record address for next time. */
>> + log_last_msg = msg;
>> +
>> return msg->text_len;
>> }
>>
>> --
>> 1.9.1
>>