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

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

[Martin Peschke]

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);
+	return sprintf(s, "[%5lu.%06lu]", (unsigned long)t, nsec_rem/1000);
+}
+#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())) {

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

[Balbir Singh]

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

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

[Martin Peschke]

Balbir Singh wrote:
>> +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.

Sure. I tried to keep my changes as small as possible ;-)

>> +       return sprintf(s, "[%5lu.%06lu]", (unsigned long)t, 
>> nsec_rem/1000);
>> +}
> 
> Something symbolic for the 1000 would be better.  NSECS_PER_USEC probably?

Makes sense.

Thanks,
Martin

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

[Tim Bird]

Martin Peschke wrote:
> The original piece of code was a bit promiscuous, IMHO.
> Please accept the little cleanup that comes with my patch.

In general, I like the cleanup.  See comments below.

> 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).

I'm not following your change here.  I can't find the problem you
mention in the original code.  And your fix appears to mess up the
printed_len.

> +		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;
Here you subtract from the printed_len to account for skipping
the submitted log level.

> +			} else	{
> +				loglev_char = default_message_loglevel + '0';
> +			}
> +			emit_log_char('<');
> +			emit_log_char(loglev_char);
> +			emit_log_char('>');

But here you don't re-count the chars for the log-level
you are adding back in.  There's a discrepancy here.

Please look at this again.  NAK
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Electronics
=============================

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

[Martin Peschke]

Tim Bird wrote:
> Martin Peschke wrote:
>> 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).
> 
> I'm not following your change here.  I can't find the problem you
> mention in the original code.  And your fix appears to mess up the
> printed_len.

I am sorry for not responding sooner ... and I am sorry for introducing
a bug here. I think you are right.

>> +		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;
> Here you subtract from the printed_len to account for skipping
> the submitted log level.
> 
>> +			} else	{
>> +				loglev_char = default_message_loglevel + '0';
>> +			}
>> +			emit_log_char('<');
>> +			emit_log_char(loglev_char);
>> +			emit_log_char('>');
> 
> But here you don't re-count the chars for the log-level
> you are adding back in.  There's a discrepancy here.

Correct. My print_len loses 3 in the 'got log level'-case due to a surplus
substraction. It also loses 3 in the other case due to adding a log level
substring that is not entered in the books.

This is how I would fix it:

         printed_len = vscnprintf(printk_buf, sizeof(printk_buf), fmt, args);

         ...

         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;
                 } else  {
                         loglev_char = default_message_loglevel + '0';
                         print_len += 3;
                 }
                 emit_log_char('<');
                 emit_log_char(loglev_char);
                 emit_log_char('>');


Could you confirm, please. I will send a patch to Andrew then.


Or, Andrew, do you prefer a replacement patch for my
statistics-infrastructure-prerequisite-timestamp.patch
that introduces this miscalculation. I could put
statistics-infrastructure-make-printk_clock-a-generic-kernel-wide-nsec-resolution.patch
into that one as well, so that all the timestamp related printk-changes are in
one place.

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

[Andrew Morton]

On Thu, 01 Jun 2006 10:40:32 +0200
Martin Peschke <mp3@de.ibm.com> wrote:

> Or, Andrew, do you prefer a replacement patch for my
> statistics-infrastructure-prerequisite-timestamp.patch
> that introduces this miscalculation. I could put
> statistics-infrastructure-make-printk_clock-a-generic-kernel-wide-nsec-resolution.patch
> into that one as well, so that all the timestamp related printk-changes are in
> one place.

umm, finest-possible-granularity patches against rc5-mm2 would be preferred
if poss.  I have scripts and tricks to do the topolgical patchsort so that
things end up in a logical patch series.

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

[Thomas Gleixner]

On Wed, 2006-05-24 at 15:08 -0700, Andrew Morton wrote:
> do_div() is actually defined in terms of u64, not unsigned long long. 
> Although afaict this will all work OK and all the usual type promotions
> will dtrt.
> 
> Which begs the question: how _does_ the kernel represent nanoseconds?  The
> time-management code is a bit undecided (search for long long in
> posix-cpu-timers.c, and for u64 in hrtimers.c).  All a bit confused.

posix-cpu-timers.c needs some caring hand !

During the ktimers/hrtimers discussion we agreed on u64 resp. ktime_t to
hold the kernel internal values.

ktime_t is the preferred way as it is optimized for 32/64 bit archs and
all the conversion functions are available out of the box.

	tglx

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

[Andrew Morton]

Martin Peschke <mp3@de.ibm.com> wrote:
>
> +static inline int nsec_to_timestamp(char *s, unsigned long long t)
> +{
> +	unsigned long nsec_rem = do_div(t, NSEC_PER_SEC);
> +	return sprintf(s, "[%5lu.%06lu]", (unsigned long)t,
> +		       nsec_rem/NSEC_PER_USEC);
> +}

do_div() is actually defined in terms of u64, not unsigned long long. 
Although afaict this will all work OK and all the usual type promotions
will dtrt.

Which begs the question: how _does_ the kernel represent nanoseconds?  The
time-management code is a bit undecided (search for long long in
posix-cpu-timers.c, and for u64 in hrtimers.c).  All a bit confused.

Anwyay.  This function is too big and slow to be inlined..

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

[Martin Peschke]

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 |    8 +++++
 kernel/printk.c         |   74 +++++++++++++++++++-----------------------------
 2 files changed, 38 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,12 @@ 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, NSEC_PER_SEC);
+	return sprintf(s, "[%5lu.%06lu]", (unsigned long)t,
+		       nsec_rem/NSEC_PER_USEC);
+}
+#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())) {