[Skiboot] [PATCH] [TRIVIAL] Make console-log time more readable
Balbir Singh
bsingharora at gmail.com
Thu May 5 17:10:19 AEST 2016
Changelog v2:
Fix test cases - ensure make check does not
fail for the console test cases
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 at gmail.com>
---
core/console-log.c | 5 +++--
core/test/run-console-log-buf-overrun.c | 8 ++++----
core/test/run-console-log-pr_fmt.c | 6 +++---
core/test/run-console-log.c | 6 +++---
include/timebase.h | 5 +++++
5 files changed, 18 insertions(+), 12 deletions(-)
diff --git a/core/console-log.c b/core/console-log.c
index 3b9475e..c70229f 100644
--- a/core/console-log.c
+++ b/core/console-log.c
@@ -32,6 +32,7 @@ static int vprlog(int log_level, const char *fmt, va_list ap)
int count;
char buffer[320];
bool flush_to_drivers = true;
+ unsigned long tb = mftb();
/* It's safe to return 0 when we "did" something here
* as only printf cares about how much we wrote, and
@@ -43,8 +44,8 @@ static int vprlog(int log_level, const char *fmt, va_list ap)
if (log_level > (debug_descriptor.console_log_levels >> 4))
return 0;
- count = snprintf(buffer, sizeof(buffer), "[%lu,%d] ",
- mftb(), log_level);
+ count = snprintf(buffer, sizeof(buffer), "[%5lu.%06lu,%d] ",
+ tb_to_secs(tb), tb_remaining_nsecs(tb), log_level);
count+= vsnprintf(buffer+count, sizeof(buffer)-count, fmt, ap);
if (log_level > (debug_descriptor.console_log_levels & 0x0f))
diff --git a/core/test/run-console-log-buf-overrun.c b/core/test/run-console-log-buf-overrun.c
index a09742e..3ea7cd3 100644
--- a/core/test/run-console-log-buf-overrun.c
+++ b/core/test/run-console-log-buf-overrun.c
@@ -71,7 +71,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 +79,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 +103,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..ef7c352 100644
--- a/core/test/run-console-log-pr_fmt.c
+++ b/core/test/run-console-log-pr_fmt.c
@@ -50,7 +50,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 +61,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..6cc5b5d 100644
--- a/core/test/run-console-log.c
+++ b/core/test/run-console-log.c
@@ -50,7 +50,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 +61,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;
diff --git a/include/timebase.h b/include/timebase.h
index 7f5afe1..c50f601 100644
--- a/include/timebase.h
+++ b/include/timebase.h
@@ -64,6 +64,11 @@ static inline unsigned long tb_to_secs(unsigned long tb)
return tb / tb_hz;
}
+static inline unsigned long tb_remaining_nsecs(unsigned long tb)
+{
+ return tb % tb_hz;
+}
+
static inline unsigned long msecs_to_tb(unsigned long msecs)
{
return msecs * (tb_hz / 1000);
--
2.5.5
More information about the Skiboot
mailing list