printing TSC in printk

[ron minnich]

Here's a simple proposal.

Define an option
PRINTK_TSC

What it does: each time printk would print a newline, it will instead
print this:
(16 hex digits of TSC)\n

Here's another simpler option:

Define a new format letter, T, such that %T as a format means "time".

first option allows comprehensive timing, but it will slow things down
a bit. Second option allows us to completely tailor the printing of
time, but you have to explicitly add %T when you want time printed.

Comments?

ron

[Carl-Daniel Hailfinger]

On 09.02.2008 21:50, ron minnich wrote:
> Here's a simple proposal.
>
> Define an option
> PRINTK_TSC
>
> What it does: each time printk would print a newline, it will instead
> print this:
> (16 hex digits of TSC)\n
>
> Here's another simpler option:
>
> Define a new format letter, T, such that %T as a format means "time".
>
> first option allows comprehensive timing, but it will slow things down
> a bit. Second option allows us to completely tailor the printing of
> time, but you have to explicitly add %T when you want time printed.

Try this:
Regards,
Carl-Daniel

Preliminary patch for the second option, does not compile yet, but you
get the idea.
Signed-off-by: Carl-Daniel Hailfinger

Index: LinuxBIOSv3-printktimestamp/include/console.h
===================================================================
--- LinuxBIOSv3-printktimestamp/include/console.h	(Revision 582)
+++ LinuxBIOSv3-printktimestamp/include/console.h	(Arbeitskopie)
@@ -37,6 +37,7 @@
 unsigned char console_rx_byte(void);
 int console_tst_byte(void);
 void die(const char *msg);
+u32 get_timestamp(void);

struct console_driver {
    void (*init)(void);
Index: LinuxBIOSv3-printktimestamp/lib/vtxprintf.c
===================================================================
--- LinuxBIOSv3-printktimestamp/lib/vtxprintf.c	(Revision 582)
+++ LinuxBIOSv3-printktimestamp/lib/vtxprintf.c	(Arbeitskopie)
@@ -12,6 +12,7 @@
 #include <stdarg.h>
 #include <string.h>
 #include <div64.h>
+#include <console.h>

#define isdigit(c)	((c) >= '0' && (c) <= '9')
 #define is_digit isdigit
@@ -118,6 +119,7 @@
    int qualifier;		/* 'h', 'l', or 'L' for integer fields */
    
    int count;
+	u32 tstamp;

for (count=0; *fmt ; ++fmt) {
    	if (*fmt != '%') {
@@ -218,6 +220,16 @@
    			field_width, precision, flags);
    		continue;

+		/* Timestamp in 32bit hex */
+		case 'T':
+			if (field_width == -1) {
+				field_width = 2 * sizeof(unsigned long);
+				flags |= ZEROPAD;
+			}
+			tstamp = get_timestamp();
+			count += number(tx_byte, arg, tstamp, 16,
+				field_width, precision, flags);
+			continue;

case 'n':
    		if (qualifier == 'L') {
Index: LinuxBIOSv3-printktimestamp/arch/x86/geodelx/cpu.c
===================================================================
--- LinuxBIOSv3-printktimestamp/arch/x86/geodelx/cpu.c	(Revision 582)
+++ LinuxBIOSv3-printktimestamp/arch/x86/geodelx/cpu.c	(Arbeitskopie)
@@ -37,6 +37,25 @@
 /* TODO: Better comment on vsm_end_post_smi, and define 0x05a2 down below. */

/**
+ * Retrieve a 32-bit time stamp. The generic get_timestamp() offers no guarantee
+ * whatsoever about monotony, granularity, absence of wraparounds or linear
+ * relationship between the time stamp and real time.
+ * This implementation has wraparounds after 2^32 cycles of the TSC register
+ * and will usually have a linear dependency on real time.
+ * Qemu and Geode LX support the rdtsc instruction.
+ * If v3 ever is used on x86 architectures which don't support rdtsc, we have
+ * to provide an alternative.
+ *
+ * @return 32-bit truncated number of TSC cycles since poweron.
+ */
+u32 get_timestamp(void)
+{
+	u32 tstamp;
+	__asm__ __volatile__ ("rdtsc" : "=a" (tstamp) : : "edx");
+	return tstamp;
+}
+
+/**
  * This is a call to the VSM.
  *
  * TODO: We need to know what it does.

[Carl-Daniel Hailfinger]

Any reviews/opinions?

Regards,
Carl-Daniel

On 10.02.2008 00:49, Carl-Daniel Hailfinger wrote:
> On 09.02.2008 21:50, ron minnich wrote:
> > Define a new format letter, T, such that %T as a format means "time".
> >
> > [...] allows us to completely tailor the printing of
> > time, but you have to explicitly add %T when you want time printed.
>
> Preliminary patch[...] does not compile yet, but you get the idea.

Needs an additional declaration in some header to fix compilation, code 
itself should be sound.
> Signed-off-by: Carl-Daniel Hailfinger
> Index: LinuxBIOSv3-printktimestamp/include/console.h
>
> --- LinuxBIOSv3-printktimestamp/include/console.h	(Revision 582)
> +++ LinuxBIOSv3-printktimestamp/include/console.h	(Arbeitskopie)
> @@ -37,6 +37,7 @@
>  unsigned char console_rx_byte(void);
>  int console_tst_byte(void);
>  void die(const char *msg);
> +u32 get_timestamp(void);
>
> struct console_driver {
>    void (*init)(void);
> Index: LinuxBIOSv3-printktimestamp/lib/vtxprintf.c
> ===================================================================
> --- LinuxBIOSv3-printktimestamp/lib/vtxprintf.c	(Revision 582)
> +++ LinuxBIOSv3-printktimestamp/lib/vtxprintf.c	(Arbeitskopie)
> @@ -12,6 +12,7 @@
>  #include <stdarg.h>
>  #include <string.h>
>  #include <div64.h>
> +#include <console.h>
>
> #define isdigit(c)	((c) >= '0' && (c) <= '9')
>  #define is_digit isdigit
> @@ -118,6 +119,7 @@
>    int qualifier;		/* 'h', 'l', or 'L' for integer fields */
>
> int count;
>
> u32 tstamp;
>
> for (count=0; *fmt ; ++fmt) {
> if (*fmt != '%') {
>
> @@ -218,6 +220,16 @@
>    			field_width, precision, flags);
>    		continue;
> /* Timestamp in 32bit hex */
> case 'T':
> 	if (field_width == -1) {
> 		field_width = 2 * sizeof(unsigned long);
> 		flags |= ZEROPAD;
> 	}
> 	tstamp = get_timestamp();
> 	count += number(tx_byte, arg, tstamp, 16,
> 		field_width, precision, flags);
> 	continue;
>
> case 'n':
> 	if (qualifier == 'L') {
> Index: LinuxBIOSv3-printktimestamp/arch/x86/geodelx/cpu.c
>
> --- LinuxBIOSv3-printktimestamp/arch/x86/geodelx/cpu.c	(Revision 582)
> +++ LinuxBIOSv3-printktimestamp/arch/x86/geodelx/cpu.c	(Arbeitskopie)
> @@ -37,6 +37,25 @@
>  /* TODO: Better comment on vsm_end_post_smi, and define 0x05a2 down below. */
>
> /**
> Retrieve a 32-bit time stamp. The generic get_timestamp() offers no guarantee
> whatsoever about monotony, granularity, absence of wraparounds or linear
> relationship between the time stamp and real time.
> This implementation has wraparounds after 2^32 cycles of the TSC register
> and will usually have a linear dependency on real time.
> Qemu and Geode LX support the rdtsc instruction.
> If v3 ever is used on x86 architectures which don't support rdtsc, we have
> to provide an alternative.
> @return 32-bit truncated number of TSC cycles since poweron.
> */
>
> +u32 get_timestamp(void)
> +{
> u32 tstamp;
> __asm__ __volatile__ ("rdtsc" : "=a" (tstamp) : : "edx");
> return tstamp;
>
> +}
>
> +/**
> This is a call to the VSM.
> TODO: We need to know what it does.

[ron minnich]

Have not had time to test, can you test in qemu? It looks like what I want.

ron

[Peter Stuge]

On Sat, Feb 09, 2008 at 12:50:28PM -0800, ron minnich wrote:
> Define an option
> PRINTK_TSC

This is good. Linux has the same option.
> What it does: each time printk would print a newline, it will
> instead print this:
> (16 hex digits of TSC)\n

Pro: Every line has time
Con: Time is last on the line
> Define a new format letter, T, such that %T as a format means
> "time".

Pro: Time can be first on line
Con: We need to add it manually.

Doing it like Linux would need a static variable near printk() to
keep \n state. :\
> first option allows comprehensive timing, but it will slow things
> down a bit.

This must be optional though.
> Second option allows us to completely tailor the printing of
> time, but you have to explicitly add %T when you want time
> printed.
>
> Comments?

I think it is important that the time always is printed at the same
position in a line, but manually having to add %T to every printk is
impossible.

Maybe the answer is a macro wrapper around printk() (why is it called
print_k_ by the way, we are not the kernel) which is defined
differently depending on the config option.

If the option is set, the macro always prepends "%T " to the format
string.

//Peter

[Carl-Daniel Hailfinger]

On 10.02.2008 15:03, Peter Stuge wrote:
> On Sat, Feb 09, 2008 at 12:50:28PM -0800, ron minnich wrote:
> > Define an option
> > PRINTK_TSC
>
> This is good. Linux has the same option.

<AOL>me too</AOL>
> > What it does: each time printk would print a newline, it will
> > instead print this:
> > (16 hex digits of TSC)\n
>
> Pro: Every line has time
> Con: Time is last on the line

Insertion at start for every printk will work as well unless you use
multiple prinks to fill one line. That would be the Linux concept.
> > Define a new format letter, T, such that %T as a format means
> > "time".
>
> Pro: Time can be first on line
> Con: We need to add it manually.
>
> Doing it like Linux would need a static variable near printk() to
> keep \n state. :\

I have a patch which gives us as many static variable as we want.
> > first option allows comprehensive timing, but it will slow things
> > down a bit.
>
> This must be optional though.

Indeed.
> > Second option allows us to completely tailor the printing of
> > time, but you have to explicitly add %T when you want time
> > printed.
> >
> > Comments?
>
> I think it is important that the time always is printed at the same
> position in a line, but manually having to add %T to every printk is
> impossible.
>
> Maybe the answer is a macro wrapper around printk() (why is it called

Please no macros.
> print_k_ by the way, we are not the kernel) which is defined

_k_oreboot? ;-)
> differently depending on the config option.
>
> If the option is set, the macro always prepends "%T " to the format
> string.

Now I see what you're trying to do. Nice idea. The "%T" support patch
(see my other mail in this thread) could be used as a basis for this idea.

Regards,
Carl-Daniel