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.

Cc: Joe Perches <joe@perches.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Sasha Levin <levinsasha928@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Reported-by: Yinghai Lu <yinghai@kernel.org>
Signed-off-by: Kay Sievers <kay@vrfy.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
This commit is contained in:
Kay Sievers 2012-05-10 04:30:45 +02:00 committed by Greg Kroah-Hartman
parent 5c5d5ca51a
commit 649e6ee33f
2 changed files with 36 additions and 23 deletions

View file

@ -786,6 +786,22 @@ 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)
{
unsigned long rem_ns;
if (!printk_time)
return 0;
if (!buf)
return 15;
rem_ns = do_div(t, 1000000000);
return sprintf(buf, "[%5lu.%06lu] ",
(unsigned long) t, rem_ns / 1000);
}
static int syslog_print_line(u32 idx, char *text, size_t size)
{
struct log *msg;
@ -800,9 +816,7 @@ static int syslog_print_line(u32 idx, char *text, size_t size)
len++;
if (msg->level > 99)
len++;
if (printk_time)
len += 15;
len += prepend_timestamp(0, NULL);
len += msg->text_len;
len++;
@ -810,15 +824,7 @@ static int syslog_print_line(u32 idx, char *text, size_t size)
}
len = sprintf(text, "<%u>", msg->level);
if (printk_time) {
unsigned long long t = msg->ts_nsec;
unsigned long rem_ns = do_div(t, 1000000000);
len += sprintf(text + len, "[%5lu.%06lu] ",
(unsigned long) t, rem_ns / 1000);
}
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);
@ -1741,7 +1747,7 @@ void console_unlock(void)
for (;;) {
struct log *msg;
static char text[LOG_LINE_MAX];
size_t len;
size_t len, l;
int level;
raw_spin_lock_irqsave(&logbuf_lock, flags);
@ -1761,10 +1767,13 @@ void console_unlock(void)
msg = log_from_idx(console_idx);
level = msg->level & 7;
len = msg->text_len;
if (len+1 >= sizeof(text))
len = sizeof(text)-1;
memcpy(text, log_text(msg), len);
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';
console_idx = log_next(console_idx);

View file

@ -3,12 +3,16 @@ config PRINTK_TIME
bool "Show timing information on printks"
depends on PRINTK
help
Selecting this option causes timing information to be
included in printk output. This allows you to measure
the interval between kernel operations, including bootup
operations. This is useful for identifying long delays
in kernel startup. Or add printk.time=1 at boot-time.
See Documentation/kernel-parameters.txt
Selecting this option causes time stamps of the printk()
messages to be added to the output of the syslog() system
call and at the console.
The timestamp is always recorded internally, and exported
to /dev/kmsg. This flag just specifies if the timestamp should
be included, not that the timestamp is recorded.
The behavior is also controlled by the kernel command line
parameter printk.time=1. See Documentation/kernel-parameters.txt
config DEFAULT_MESSAGE_LOGLEVEL
int "Default message log level (1-7)"