Make console-log time more readable: seconds rather than timebase

I've tried to align it with what the kernel prints today

The existing logs show:

[20287269125,5] PSI[0x000]: Found PSI bridge [working=1, active=0]
[890425679,5] BT: Interface initialized, IO 0x00e4
[1249199642,4] SLW: HB-provided idle states property found
[1249344409,5] NVRAM: Size is 576 KB
[1484422964,3] NVRAM: Layout appears sane

The mftb() output is not very meaningful, the changed output shows:

[   38.315784591,5] CENTAUR:   FSI host: 0x0 cMFSI0 port 2
[   38.315922971,5] PSI[0x000]: Found PSI bridge [working=1, active=0]
[    1.448765255,5] BT: Interface initialized, IO 0x00e4
[    2.398136129,5] NVRAM: Size is 576 KB
[    3.145017865,3] NVRAM: Layout appears sane

For the output sample, I've taken bits where one can see the time move back
w.r.t. previous log, but that was always the case. I don't think that is
worth fixing here

Adds an additional divide and modulo for every log printed. I've also
fixed the test cases that run as a part of make check

Signed-off-by: Balbir Singh <bsingharora@gmail.com>
[stewart@linux.vnet.ibm.com: fix up tb in console tests]
Signed-off-by: Stewart Smith <stewart@linux.vnet.ibm.com>

3 files changed, 16 insertions, 10 deletions

diff --git a/core/test/run-console-log-buf-overrun.c b/core/test/run-console-log-buf-overrun.c
index a09742e..847a22c 100644
--- a/core/test/run-console-log-buf-overrun.c
+++ b/core/test/run-console-log-buf-overrun.c
@@ -21,6 +21,8 @@
 #include <stdarg.h>
 #include <compiler.h>
 
+unsigned long tb_hz = 512000000;
+
 #define __TEST__
 
 #define CHECK_BUF_ASSERT(buf, str)			\
@@ -71,7 +73,7 @@ int main(void)
 	huge_tb = 1;
 
 	prlog(PR_EMERG, "Hello World");
-	CHECK_ASSERT("[1223372515963611388,0] Hello World");
+	CHECK_ASSERT("[2389399445.123611388,0] Hello World");
 
 	memset(console_buffer, 0, sizeof(console_buffer));
 
@@ -79,10 +81,10 @@ int main(void)
 	huge_tb = 0;
 
 	prlog(PR_EMERG, "Hello World %lu", value);
-	CHECK_ASSERT("[42,0] Hello World 18446744073709551615");
+	CHECK_ASSERT("[    0.000042,0] Hello World 18446744073709551615");
 
 	printf("Hello World %lu", value);
-	CHECK_ASSERT("[42,5] Hello World 18446744073709551615");
+	CHECK_ASSERT("[    0.000042,5] Hello World 18446744073709551615");
 
 	/*
 	 * Test string of size > 320
@@ -103,7 +105,7 @@ int main(void)
 	 */
 	memset(console_buffer, 0, sizeof(console_buffer));
 
-	prlog(PR_EMERG, "%313s", "Hello World");
+	prlog(PR_EMERG, "%303s", "Hello World");
 	assert(console_buffer[319] == 0);
 
 	/* compare truncated string */
diff --git a/core/test/run-console-log-pr_fmt.c b/core/test/run-console-log-pr_fmt.c
index 33b2e37..92c600d 100644
--- a/core/test/run-console-log-pr_fmt.c
+++ b/core/test/run-console-log-pr_fmt.c
@@ -22,6 +22,8 @@
 
 #define __TEST__
 
+unsigned long tb_hz = 512000000;
+
 static inline unsigned long mftb(void)
 {
 	return 42;
@@ -50,7 +52,7 @@ int main(void)
 	debug_descriptor.console_log_levels = 0x75;
 
 	prlog(PR_EMERG, "Hello World");
-	assert(memcmp(console_buffer, "[42,0] PREFIX: Hello World", strlen("[42,0] PREFIX: Hello World")) == 0);
+	assert(memcmp(console_buffer, "[    0.000042,0] PREFIX: Hello World", strlen("[    0.000042,0] PREFIX: Hello World")) == 0);
 	assert(flushed_to_drivers==true);
 
 	memset(console_buffer, 0, sizeof(console_buffer));
@@ -61,11 +63,11 @@ int main(void)
 
 	// Should not be flushed to console
 	prlog(PR_DEBUG, "Hello World");
-	assert(memcmp(console_buffer, "[42,7] PREFIX: Hello World", strlen("[42,7] PREFIX: Hello World")) == 0);
+	assert(memcmp(console_buffer, "[    0.000042,7] PREFIX: Hello World", strlen("[    0.000042,7] PREFIX: Hello World")) == 0);
 	assert(flushed_to_drivers==false);
 
 	printf("Hello World");
-	assert(memcmp(console_buffer, "[42,5] PREFIX: Hello World", strlen("[42,5] PREFIX: Hello World")) == 0);
+	assert(memcmp(console_buffer, "[    0.000042,5] PREFIX: Hello World", strlen("[    0.000042,5] PREFIX: Hello World")) == 0);
 	assert(flushed_to_drivers==true);
 
 	return 0;
diff --git a/core/test/run-console-log.c b/core/test/run-console-log.c
index 5c9b73a..f9e7b56 100644
--- a/core/test/run-console-log.c
+++ b/core/test/run-console-log.c
@@ -24,6 +24,8 @@
 
 #define _printf printf
 
+unsigned long tb_hz = 512000000;
+
 static inline unsigned long mftb(void)
 {
 	return 42;
@@ -50,7 +52,7 @@ int main(void)
 	debug_descriptor.console_log_levels = 0x75;
 
 	prlog(PR_EMERG, "Hello World");
-	assert(memcmp(console_buffer, "[42,0] Hello World", strlen("[42,0] Hello World")) == 0);
+	assert(memcmp(console_buffer, "[    0.000042,0] Hello World", strlen("[    0.000042,0] Hello World")) == 0);
 	assert(flushed_to_drivers==true);
 
 	memset(console_buffer, 0, sizeof(console_buffer));
@@ -61,11 +63,11 @@ int main(void)
 
 	// Should not be flushed to console
 	prlog(PR_DEBUG, "Hello World");
-	assert(memcmp(console_buffer, "[42,7] Hello World", strlen("[42,7] Hello World")) == 0);
+	assert(memcmp(console_buffer, "[    0.000042,7] Hello World", strlen("[    0.000042,7] Hello World")) == 0);
 	assert(flushed_to_drivers==false);
 
 	printf("Hello World");
-	assert(memcmp(console_buffer, "[42,5] Hello World", strlen("[42,5] Hello World")) == 0);
+	assert(memcmp(console_buffer, "[    0.000042,5] Hello World", strlen("[    0.000042,5] Hello World")) == 0);
 	assert(flushed_to_drivers==true);
 
 	return 0;