lkml.org 
[lkml]   [2012]   [May]   [13]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    SubjectRe: [PATCH RESEND 1/3] printk: convert byte-buffer to variable-length record buffer
    From
    Date
    On Fri, 2012-05-11 at 12:35 +0200, Sasha Levin wrote:
    > On Thu, May 10, 2012 at 4:30 AM, Kay Sievers <kay@vrfy.org> wrote:
    > > On Wed, 2012-05-09 at 16:06 -0700, Greg Kroah-Hartmann wrote:
    > >> On Wed, May 09, 2012 at 04:02:40PM -0700, Yinghai Lu wrote:
    > >> > On Wed, May 9, 2012 at 7:37 AM, Kay Sievers <kay@vrfy.org> wrote:
    > >> > >
    > >> > >> Changing printk semantics and trying to stabilize
    > >> > >> printk message content are bad ideas though.
    > >> > >
    > >> > > Again, nobody talks about content of here.
    > >> >
    > >> > printk_time=1 does not work anymore with this patch on serial console.
    > >>
    > >> Known issue, I think Kay is working on the solution for this right
    > >> now...
    > >
    > > Sure, and this seems to work for me.
    > >
    > > Thanks,
    > > Kay
    > >
    > >
    > > From: Kay Sievers <kay@vrfy.org>
    > > Subject: printk() - restore timestamp printing at console output
    > >
    > > The output of the timestamps got lost with the conversion of the
    > > kmsg buffer to records; restore the old behavior.
    > >
    > > Document, that CONFIG_PRINTK_TIME now only controls the output of
    > > the timestamps in the syslog() system call and on the console, and
    > > not the recording of the timestamps.
    > >
    > > Signed-off-by: Kay Sievers <kay@vrfy.org>
    > > ---
    >
    > This has a small issue with the way timing is printed compared to how
    > it worked previously.
    >
    > Consider the following case:
    >
    > printk("\n foo \n bar \n zoot")
    >
    > Previously, you would see timing on each line of the print, but now
    > you see it only on the first.

    Does this fix it for you? It should fully restore the current behavior
    for multi-line printing.

    Thanks,
    Kay



    From: Kay Sievers <kay@vrfy.org>
    Subject: printk() - restore prefix/timestamp printing for multi-newline strings

    Calls like:
    printk("\n *** DEADLOCK ***\n\n");
    will print 3 properly indented, separated, syslog + timestamp prefixed lines in
    the log output.


    Reported-By: Sasha Levin <levinsasha928@gmail.com>
    Signed-off-by: Kay Sievers <kay@vrfy.org>
    ---

    printk.c | 127 +++++++++++++++++++++++++++++++++++++--------------------------
    1 file changed, 76 insertions(+), 51 deletions(-)

    diff --git a/kernel/printk.c b/kernel/printk.c
    index c42faf9..ee312c7 100644
    --- a/kernel/printk.c
    +++ b/kernel/printk.c
    @@ -448,7 +448,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,

    /* escape non-printable characters */
    for (i = 0; i < msg->text_len; i++) {
    - char c = log_text(msg)[i];
    + unsigned char c = log_text(msg)[i];

    if (c < ' ' || c >= 128)
    len += sprintf(user->buf + len, "\\x%02x", c);
    @@ -461,7 +461,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
    bool line = true;

    for (i = 0; i < msg->dict_len; i++) {
    - char c = log_dict(msg)[i];
    + unsigned char c = log_dict(msg)[i];

    if (line) {
    user->buf[len++] = ' ';
    @@ -785,56 +791,81 @@ static bool printk_time;
    #endif
    module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);

    -static size_t prepend_timestamp(unsigned long long t, char *buf)
    +static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
    {
    - unsigned long rem_ns;
    + size_t len = 0;

    - if (!printk_time)
    - return 0;
    + if (syslog) {
    + if (buf) {
    + len += sprintf(buf, "<%u>", msg->level);
    + } else {
    + len += 3;
    + if (msg->level > 9)
    + len++;
    + if (msg->level > 99)
    + len++;
    + }
    + }

    - if (!buf)
    - return 15;
    + if (printk_time) {
    + if (buf) {
    + unsigned long long ts = msg->ts_nsec;
    + unsigned long rem_nsec = do_div(ts, 1000000000);

    - rem_ns = do_div(t, 1000000000);
    + len += sprintf(buf + len, "[%5lu.%06lu] ",
    + (unsigned long) ts, rem_nsec / 1000);
    + } else {
    + len += 15;
    + }
    + }

    - return sprintf(buf, "[%5lu.%06lu] ",
    - (unsigned long) t, rem_ns / 1000);
    + return len;
    }

    -static int syslog_print_line(u32 idx, char *text, size_t size)
    +static size_t msg_print_text(const struct log *msg, bool syslog,
    + char *buf, size_t size)
    {
    - struct log *msg;
    - size_t len;
    + const char *text = log_text(msg);
    + size_t text_size = msg->text_len;
    + size_t len = 0;

    - msg = log_from_idx(idx);
    - if (!text) {
    - /* calculate length only */
    - len = 3;
    + do {
    + const char *next = memchr(text, '\n', text_size);
    + size_t text_len;

    - if (msg->level > 9)
    - len++;
    - if (msg->level > 99)
    - len++;
    - len += prepend_timestamp(0, NULL);
    + if (next) {
    + text_len = next - text;
    + next++;
    + text_size -= next - text;
    + } else {
    + text_len = text_size;
    + }

    - len += msg->text_len;
    - len++;
    - return len;
    - }
    + if (buf) {
    + if (print_prefix(msg, syslog, NULL) +
    + text_len + 1>= size - len)
    + break;
    +
    + len += print_prefix(msg, syslog, buf + len);
    + memcpy(buf + len, text, text_len);
    + len += text_len;
    + buf[len++] = '\n';
    + } else {
    + /* SYSLOG_ACTION_* buffer size only calculation */
    + len += print_prefix(msg, syslog, NULL);
    + len += text_len + 1;
    + }
    +
    + text = next;
    + } while (text);

    - len = sprintf(text, "<%u>", msg->level);
    - len += prepend_timestamp(msg->ts_nsec, text + len);
    - if (len + msg->text_len > size)
    - return -EINVAL;
    - memcpy(text + len, log_text(msg), msg->text_len);
    - len += msg->text_len;
    - text[len++] = '\n';
    return len;
    }

    static int syslog_print(char __user *buf, int size)
    {
    char *text;
    + struct log *msg;
    int len;

    text = kmalloc(LOG_LINE_MAX, GFP_KERNEL);
    @@ -847,7 +878,8 @@ static int syslog_print(char __user *buf, int size)
    syslog_seq = log_first_seq;
    syslog_idx = log_first_idx;
    }
    - len = syslog_print_line(syslog_idx, text, LOG_LINE_MAX);
    + msg = log_from_idx(syslog_idx);
    + len = msg_print_text(msg, true, text, LOG_LINE_MAX);
    syslog_idx = log_next(syslog_idx);
    syslog_seq++;
    raw_spin_unlock_irq(&logbuf_lock);
    @@ -887,14 +919,18 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
    seq = clear_seq;
    idx = clear_idx;
    while (seq < log_next_seq) {
    - len += syslog_print_line(idx, NULL, 0);
    + struct log *msg = log_from_idx(idx);
    +
    + len += msg_print_text(msg, true, NULL, 0);
    idx = log_next(idx);
    seq++;
    }
    seq = clear_seq;
    idx = clear_idx;
    while (len > size && seq < log_next_seq) {
    - len -= syslog_print_line(idx, NULL, 0);
    + struct log *msg = log_from_idx(idx);
    +
    + len -= msg_print_text(msg, true, NULL, 0);
    idx = log_next(idx);
    seq++;
    }
    @@ -904,9 +940,10 @@ static int syslog_print_all(char __user *buf, int size, bool clear)

    len = 0;
    while (len >= 0 && seq < next_seq) {
    + struct log *msg = log_from_idx(idx);
    int textlen;

    - textlen = syslog_print_line(idx, text, LOG_LINE_MAX);
    + textlen = msg_print_text(msg, true, text, LOG_LINE_MAX);
    if (textlen < 0) {
    len = textlen;
    break;
    @@ -1044,7 +1081,9 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
    seq = syslog_seq;
    idx = syslog_idx;
    while (seq < log_next_seq) {
    - error += syslog_print_line(idx, NULL, 0);
    + struct log *msg = log_from_idx(idx);
    +
    + error += msg_print_text(msg, true, NULL, 0);
    idx = log_next(idx);
    seq++;
    }
    @@ -1439,10 +1478,8 @@ static struct log *log_from_idx(u32 idx) { return NULL; }
    static u32 log_next(u32 idx) { return 0; }
    static char *log_text(const struct log *msg) { return NULL; }
    static void call_console_drivers(int level, const char *text, size_t len) {}
    -static size_t prepend_timestamp(unsigned long long t, char *buf)
    -{
    - return 0;
    -}
    +static size_t msg_print_text(const struct log *msg, bool syslog,
    + char *buf, size_t size) { return 0; }

    #endif /* CONFIG_PRINTK */

    @@ -1750,7 +1787,7 @@ again:
    for (;;) {
    struct log *msg;
    static char text[LOG_LINE_MAX];
    - size_t len, l;
    + size_t len;
    int level;

    raw_spin_lock_irqsave(&logbuf_lock, flags);
    @@ -1771,13 +1808,7 @@ again:
    msg = log_from_idx(console_idx);
    level = msg->level & 7;

    - len = prepend_timestamp(msg->ts_nsec, text);
    - l = msg->text_len;
    - if (len + l + 1 >= sizeof(text))
    - l = sizeof(text) - len - 1;
    - memcpy(text + len, log_text(msg), l);
    - len += l;
    - text[len++] = '\n';
    + len = msg_print_text(msg, false, text, sizeof(text));

    console_idx = log_next(console_idx);
    console_seq++;



    \
     
     \ /
      Last update: 2012-05-13 23:41    [W:0.041 / U:4.340 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site