Re: [Patch 3/6] statistics infrastructure - prerequisite: timestamp

Balbir Singh
2006-05-23T13:06:22Z

On 5/19/06, Martin Peschke <mp3@de.ibm.com> wrote:
> This patch separates the timestamp code out from printk. Thus, other
> components, like the statistics infrastructure, can also make use of it
> and provide similar timestamps. It just makes sense to have one timestamp
> format throughout the kernel.
>
> The original piece of code was a bit promiscuous, IMHO.
> Please accept the little cleanup that comes with my patch.
>
> And I think that I have fixed a printed_len related miscalculation.
> printed_len needs to be increased if no valid log level has been found
> and a log level prefix has been added by printk(). Otherwise, printed_len
> must not be increased. The old code did it the other way around (in the
> timestamp case).
>
> Signed-off-by: Martin Peschke <mp3@de.ibm.com>
> ---
>
> include/linux/jiffies.h | 7 ++++
> kernel/printk.c | 74 +++++++++++++++++++-----------------------------
> 2 files changed, 37 insertions(+), 44 deletions(-)
>
> diff -Nurp a/include/linux/jiffies.h b/include/linux/jiffies.h
> --- a/include/linux/jiffies.h 2006-05-19 15:44:27.000000000 +0200
> +++ b/include/linux/jiffies.h 2006-05-19 16:01:58.000000000 +0200
> @@ -447,4 +447,11 @@ static inline u64 nsec_to_clock_t(u64 x)
> return x;
> }
>
> +static inline int nsec_to_timestamp(char *s, unsigned long long t)
> +{
> + unsigned long nsec_rem = do_div(t, 1000000000);

Could we please use NSEC_PER_SEC. I cannot count the number of zeros
after the 1.

> + return sprintf(s, "[%5lu.%06lu]", (unsigned long)t, nsec_rem/1000);
> +}

Something symbolic for the 1000 would be better. NSECS_PER_USEC probably?

> +#define TIMESTAMP_SIZE 30
> +
> #endif
> diff -Nurp a/kernel/printk.c b/kernel/printk.c
> --- a/kernel/printk.c 2006-05-19 15:44:27.000000000 +0200
> +++ b/kernel/printk.c 2006-05-19 16:01:58.000000000 +0200
> @@ -493,7 +493,7 @@ asmlinkage int vprintk(const char *fmt,
> int printed_len;
> char *p;
> static char printk_buf[1024];
> - static int log_level_unknown = 1;
> + static int new_line = 1;
>
> preempt_disable();
> if (unlikely(oops_in_progress) && printk_cpu == smp_processor_id())
> @@ -510,59 +510,45 @@ asmlinkage int vprintk(const char *fmt,
>
> /*
> * Copy the output into log_buf. If the caller didn't provide
> - * appropriate log level tags, we insert them here
> + * appropriate log level tags, we insert them here.
> */
> for (p = printk_buf; *p; p++) {
> - if (log_level_unknown) {
> - /* log_level_unknown signals the start of a new line */
> + if (new_line) {
> + /* The log level token is first. */
> + int loglev_char;
> + if (p[0] == '<' && p[1] >='0' &&
> + p[1] <= '7' && p[2] == '>') {
> + loglev_char = p[1];
> + p += 3;
> + printed_len -= 3;
> + } else {
> + loglev_char = default_message_loglevel + '0';
> + }
> + emit_log_char('<');
> + emit_log_char(loglev_char);
> + emit_log_char('>');
> + /* A timestamp, if requested, goes next. */
> if (printk_time) {
> - int loglev_char;
> - char tbuf[50], *tp;
> - unsigned tlen;
> - unsigned long long t;
> - unsigned long nanosec_rem;
> -
> - /*
> - * force the log level token to be
> - * before the time output.
> - */
> - if (p[0] == '<' && p[1] >='0' &&
> - p[1] <= '7' && p[2] == '>') {
> - loglev_char = p[1];
> - p += 3;
> - printed_len -= 3;
> - } else {
> - loglev_char = default_message_loglevel
> - + '0';
> - }
> - t = printk_clock();
> - nanosec_rem = do_div(t, 1000000000);
> - tlen = sprintf(tbuf,
> - "<%c>[%5lu.%06lu] ",
> - loglev_char,
> - (unsigned long)t,
> - nanosec_rem/1000);
> -
> - for (tp = tbuf; tp < tbuf + tlen; tp++)
> + char tbuf[TIMESTAMP_SIZE], *tp;
> + printed_len += nsec_to_timestamp(tbuf,
> + printk_clock());
> + for (tp = tbuf; *tp; tp++)
> emit_log_char(*tp);
> - printed_len += tlen;
> - } else {
> - if (p[0] != '<' || p[1] < '0' ||
> - p[1] > '7' || p[2] != '>') {
> - emit_log_char('<');
> - emit_log_char(default_message_loglevel
> - + '0');
> - emit_log_char('>');
> - printed_len += 3;
> - }
> + emit_log_char(' ');
> + printed_len++;
> }
> - log_level_unknown = 0;
> + new_line = 0;
> if (!*p)
> break;
> }
> + /*
> + * Once we are done with special strings at the head of
> + * each line, we just keep copying characters until
> + * we come across another line and need to start over.
> + */
> emit_log_char(*p);
> if (*p == '\n')
> - log_level_unknown = 1;
> + new_line = 1;
> }
>
> if (!cpu_online(smp_processor_id())) {
>
>
> -

Regards,

Balbir
Linux Technology Center,
India Software Labs,
Bangalore