Change in coreboot[master]: [WIP] console,boot_state: Reformat state times output

[Kyösti Mälkki (Code Review)]

Kyösti Mälkki has uploaded this change for review. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

[WIP] console,boot_state: Reformat state times output

Change-Id: I0c847da98901c56b356b4a933d9ae865dada98b6
Signed-off-by: Kyösti Mälkki 
---
M src/console/printk.c
M src/lib/hardwaremain.c
2 files changed, 14 insertions(+), 17 deletions(-)

git pull ssh://review.coreboot.org:29418/coreboot refs/changes/84/36584/1

diff --git a/src/console/printk.c b/src/console/printk.c
index 4f9f547..3fb69cb 100644
--- a/src/console/printk.c
+++ b/src/console/printk.c
@@ -52,7 +52,7 @@
    if (!TRACK_CONSOLE_TIME)
    	return;

-	printk(BIOS_DEBUG, "Accumulated console time in " ENV_STRING " %ld ms\n",
+	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (ms) run (unknown) (%ld)\n",
    	DIV_ROUND_CLOSEST(console_usecs, USECS_PER_MSEC));
 }

diff --git a/src/lib/hardwaremain.c b/src/lib/hardwaremain.c
index 3fcf882..c1ea1b3 100644
--- a/src/lib/hardwaremain.c
+++ b/src/lib/hardwaremain.c
@@ -252,26 +252,23 @@

static void bs_report_time(struct boot_state *state)
 {
-	long entry_time;
-	long run_time;
-	long exit_time;
    struct mono_time *samples = &state->times.samples[0];
+	const char *sample_id[] = { "entry", "run", "exit" };
+	long execution, console;
+	int i;

-	entry_time = mono_time_diff_microseconds(&samples[0], &samples[1]);
-	run_time = mono_time_diff_microseconds(&samples[1], &samples[2]);
-	exit_time = mono_time_diff_microseconds(&samples[2], &samples[3]);
+	for (i = 0; i < MAX_TIME_SAMPLES - 1; i++) {
+		execution = mono_time_diff_microseconds(&samples[i], &samples[i + 1]);
+		console = state->times.console_usecs[i + 1];

-	entry_time -= state->times.console_usecs[1];
-	run_time -= state->times.console_usecs[2];
-	exit_time -= state->times.console_usecs[3];
+		/* Report with millisecond precision to reduce log diffs. */
+		execution = DIV_ROUND_CLOSEST(execution, USECS_PER_MSEC);
+		console = DIV_ROUND_CLOSEST(console, USECS_PER_MSEC);

-	/* Report with millisecond precision to reduce log diffs. */
-	entry_time = DIV_ROUND_CLOSEST(entry_time, USECS_PER_MSEC);
-	run_time = DIV_ROUND_CLOSEST(run_time, USECS_PER_MSEC);
-	exit_time = DIV_ROUND_CLOSEST(exit_time, USECS_PER_MSEC);
-
-	printk(BIOS_DEBUG, "BS: %s times (ms): entry %ld run %ld exit %ld\n",
-	       state->name, entry_time, run_time, exit_time);
+		if (execution)
+			printk(BIOS_DEBUG, "BS: %s times (ms): %s %ld (%ld)\n",
+				state->name, sample_id[i], execution - console, console);
+	}
 }
 #else
 static inline void bs_sample_time(struct boot_state *state) {}

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 1:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/1/src/lib/hardwaremain.c 
File src/lib/hardwaremain.c:

https://review.coreboot.org/c/coreboot/+/36584/1/src/lib/hardwaremain.c@256 
PS1, Line 256: 	const char *sample_id[] = { "entry", "run", "exit" };
char * array declaration might be better as static const

[Kyösti Mälkki (Code Review)]

Hello build bot (Jenkins),

I'd like you to reexamine a change. Please visit

https://review.coreboot.org/c/coreboot/+/36584

to look at the new patch set (#2).

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

[WIP] console,boot_state: Reformat state times output

Change-Id: I0c847da98901c56b356b4a933d9ae865dada98b6
Signed-off-by: Kyösti Mälkki 
---
M src/console/printk.c
M src/lib/hardwaremain.c
2 files changed, 14 insertions(+), 17 deletions(-)

git pull ssh://review.coreboot.org:29418/coreboot refs/changes/84/36584/2

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 2:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/2/src/lib/hardwaremain.c 
File src/lib/hardwaremain.c:

https://review.coreboot.org/c/coreboot/+/36584/2/src/lib/hardwaremain.c@256 
PS2, Line 256: 	static const char *sample_id[] = { "entry", "run", "exit" };
static const char * array should probably be static const char * const

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 3:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/3/src/lib/hardwaremain.c 
File src/lib/hardwaremain.c:

https://review.coreboot.org/c/coreboot/+/36584/3/src/lib/hardwaremain.c@256 
PS3, Line 256: 	static const char *sample_id[] = { "entry", "run", "exit" };
static const char * array should probably be static const char * const

[Kyösti Mälkki (Code Review)]

Hello build bot (Jenkins),

I'd like you to reexamine a change. Please visit

https://review.coreboot.org/c/coreboot/+/36584

to look at the new patch set (#4).

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

[WIP] console,boot_state: Reformat state times output

Change-Id: I0c847da98901c56b356b4a933d9ae865dada98b6
Signed-off-by: Kyösti Mälkki 
---
M src/console/printk.c
M src/lib/hardwaremain.c
2 files changed, 14 insertions(+), 17 deletions(-)

git pull ssh://review.coreboot.org:29418/coreboot refs/changes/84/36584/4

[Nico Huber (Code Review)]

Nico Huber has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 4: Code-Review+1

(3 comments)

https://review.coreboot.org/c/coreboot/+/36584/4//COMMIT_MSG 
Commit Message:

https://review.coreboot.org/c/coreboot/+/36584/4//COMMIT_MSG@7 
PS4, Line 7: [WIP] console,boot_state: Reformat state times output
Update?

https://review.coreboot.org/c/coreboot/+/36584/4/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/4/src/console/printk.c@55 
PS4, Line 55: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (ms) run (unknown) (%ld)\n",
this looks like it wants an update, e.g.

"BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n"

https://review.coreboot.org/c/coreboot/+/36584/4/src/lib/hardwaremain.c 
File src/lib/hardwaremain.c:

https://review.coreboot.org/c/coreboot/+/36584/4/src/lib/hardwaremain.c@256 
PS4, Line 256:  
Having _no_ space between the asterisk and `const` seems more common
(can't say that the space is uncommon, though, counts: 924 / *const>/
170 / * const>/).

[Kyösti Mälkki (Code Review)]

Hello build bot (Jenkins), Nico Huber,

I'd like you to reexamine a change. Please visit

https://review.coreboot.org/c/coreboot/+/36584

to look at the new patch set (#5).

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

[WIP] console,boot_state: Reformat state times output

Change-Id: I0c847da98901c56b356b4a933d9ae865dada98b6
Signed-off-by: Kyösti Mälkki 
---
M src/console/printk.c
M src/lib/hardwaremain.c
2 files changed, 14 insertions(+), 17 deletions(-)

git pull ssh://review.coreboot.org:29418/coreboot refs/changes/84/36584/5

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 5:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/5/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/5/src/console/printk.c@55 
PS5, Line 55: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
line over 96 characters

[Kyösti Mälkki (Code Review)]

Kyösti Mälkki has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 5:

(2 comments)

https://review.coreboot.org/c/coreboot/+/36584/4//COMMIT_MSG 
Commit Message:

https://review.coreboot.org/c/coreboot/+/36584/4//COMMIT_MSG@7 
PS4, Line 7: [WIP] console,boot_state: Reformat state times output
> Update?

Still WIP. If we split entry/run/exit "phases" on separate lines, we should also interleave them with the respective console output.

That in turn means we would not need the array of monotimes at all?

https://review.coreboot.org/c/coreboot/+/36584/4/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/4/src/console/printk.c@55 
PS4, Line 55: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (ms) run (unknown) (%ld)\n",
> this looks like it wants an update, e.g. […]

Done

[Nico Huber (Code Review)]

Nico Huber has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 5:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/4//COMMIT_MSG 
Commit Message:

https://review.coreboot.org/c/coreboot/+/36584/4//COMMIT_MSG@7 
PS4, Line 7: [WIP] console,boot_state: Reformat state times output
> Still WIP. […]

Good question. Given that we only show the times at BIOS_DEBUG (we could
discuss that too), there would be really something to interleave. No strong
feelings on my side. Right now, I like the idea.

[Kyösti Mälkki (Code Review)]

Kyösti Mälkki has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 5:

Aaron, do you wish to maintain logging bootstate "phases" (entry,run,exit) on one line in the logs? I did not receive feedback on the mailing list if someone is currently actively parsing these on their test rigs.

[Aaron Durbin (Code Review)]

Aaron Durbin has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 5:
> Patch Set 5:
>
> Aaron, do you wish to maintain logging bootstate "phases" (entry,run,exit) on one line in the logs? I did not receive feedback on the mailing list if someone is currently actively parsing these on their test rigs.

I don't think it matters if it's on one line or not. We're not actively parsing the unstructured logs. I do think, though, that we should maintain for each of those phases.

[Aaron Durbin (Code Review)]

Aaron Durbin has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 5: Code-Review+1

[Kyösti Mälkki (Code Review)]

Hello Aaron Durbin, build bot (Jenkins), Nico Huber,

I'd like you to reexamine a change. Please visit

https://review.coreboot.org/c/coreboot/+/36584

to look at the new patch set (#6).

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

[WIP] console,boot_state: Reformat state times output

Change-Id: I0c847da98901c56b356b4a933d9ae865dada98b6
Signed-off-by: Kyösti Mälkki 
---
M src/console/printk.c
M src/lib/hardwaremain.c
2 files changed, 34 insertions(+), 55 deletions(-)

git pull ssh://review.coreboot.org:29418/coreboot refs/changes/84/36584/6

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: [WIP] console,boot_state: Reformat state times output
......................................................................

Patch Set 6:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/6/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/6/src/console/printk.c@52 
PS6, Line 52: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
line over 96 characters

Change in coreboot[master]: console,boot_state: Reformat state times output

[Kyösti Mälkki (Code Review)]

Hello Aaron Durbin, build bot (Jenkins), Nico Huber,

I'd like you to reexamine a change. Please visit

https://review.coreboot.org/c/coreboot/+/36584

to look at the new patch set (#7).

Change subject: console,boot_state: Reformat state times output
......................................................................

console,boot_state: Reformat state times output

For each boot_state, report the times spent interleaved
with other console output and remove the samples arrays.

Change-Id: I0c847da98901c56b356b4a933d9ae865dada98b6
Signed-off-by: Kyösti Mälkki 
---
M src/console/printk.c
M src/lib/hardwaremain.c
2 files changed, 34 insertions(+), 55 deletions(-)

git pull ssh://review.coreboot.org:29418/coreboot refs/changes/84/36584/7

Change in coreboot[master]: console,boot_state: Reformat state times output

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 7:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/7/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/7/src/console/printk.c@52 
PS7, Line 52: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
line over 96 characters

Change in coreboot[master]: console,boot_state: Reformat state times output

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 8:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/8/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/8/src/console/printk.c@52 
PS8, Line 52: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
line over 96 characters

Change in coreboot[master]: console,boot_state: Reformat state times output

[Kyösti Mälkki (Code Review)]

Kyösti Mälkki has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 8:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/4//COMMIT_MSG 
Commit Message:

https://review.coreboot.org/c/coreboot/+/36584/4//COMMIT_MSG@7 
PS4, Line 7: [WIP] console,boot_state: Reformat state times output
> Good question. Given that we only show the times at BIOS_DEBUG (we could […]

Done

Change in coreboot[master]: console,boot_state: Reformat state times output

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 9:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/9/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/9/src/console/printk.c@52 
PS9, Line 52: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
line over 96 characters

Change in coreboot[master]: console,boot_state: Reformat state times output

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 10:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/10/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/10/src/console/printk.c@52 
PS10, Line 52: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
line over 96 characters

Change in coreboot[master]: console,boot_state: Reformat state times output

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 11:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/11/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/11/src/console/printk.c@52 
PS11, Line 52: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
line over 96 characters

Change in coreboot[master]: console,boot_state: Reformat state times output

[Nico Huber (Code Review)]

Nico Huber has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 11: Code-Review+2

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/11//COMMIT_MSG 
Commit Message:

https://review.coreboot.org/c/coreboot/+/36584/11//COMMIT_MSG@10 
PS11, Line 10: with other console output and remove the samples arrays.
Maybe mention that the time spent to output samples is
not accounted for.

Change in coreboot[master]: console,boot_state: Reformat state times output

[Kyösti Mälkki (Code Review)]

Hello Aaron Durbin, build bot (Jenkins), Nico Huber,

I'd like you to reexamine a change. Please visit

https://review.coreboot.org/c/coreboot/+/36584

to look at the new patch set (#12).

Change subject: console,boot_state: Reformat state times output
......................................................................

console,boot_state: Reformat state times output

For each boot_state, report the times spent interleaved
with other console output and remove the samples arrays.

The time spent to report the times to console is not
accounted for.

Change-Id: I0c847da98901c56b356b4a933d9ae865dada98b6
Signed-off-by: Kyösti Mälkki 
---
M src/console/printk.c
M src/lib/hardwaremain.c
2 files changed, 34 insertions(+), 55 deletions(-)

git pull ssh://review.coreboot.org:29418/coreboot refs/changes/84/36584/12

Change in coreboot[master]: console,boot_state: Reformat state times output

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 12:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/12/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/12/src/console/printk.c@52 
PS12, Line 52: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
line over 96 characters

Change in coreboot[master]: console,boot_state: Reformat state times output

[Nico Huber (Code Review)]

Nico Huber has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 12: Code-Review+2

Change in coreboot[master]: console,boot_state: Reformat state times output

[build bot (Jenkins) (Code Review)]

build bot (Jenkins) has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

Patch Set 13:

(1 comment)

https://review.coreboot.org/c/coreboot/+/36584/13/src/console/printk.c 
File src/console/printk.c:

https://review.coreboot.org/c/coreboot/+/36584/13/src/console/printk.c@52 
PS13, Line 52: 	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
line over 96 characters

Change in coreboot[master]: console,boot_state: Reformat state times output

[Nico Huber (Code Review)]

Nico Huber has submitted this change. ( https://review.coreboot.org/c/coreboot/+/36584 )

Change subject: console,boot_state: Reformat state times output
......................................................................

console,boot_state: Reformat state times output

For each boot_state, report the times spent interleaved
with other console output and remove the samples arrays.

The time spent to report the times to console is not
accounted for.

Change-Id: I0c847da98901c56b356b4a933d9ae865dada98b6
Signed-off-by: Kyösti Mälkki 
Reviewed-on: https://review.coreboot.org/c/coreboot/+/36584
Tested-by: build bot (Jenkins) 
Reviewed-by: Nico Huber 
---
M src/console/printk.c
M src/lib/hardwaremain.c
2 files changed, 34 insertions(+), 55 deletions(-)

Approvals:
  build bot (Jenkins): Verified
  Nico Huber: Looks good to me, approved

diff --git a/src/console/printk.c b/src/console/printk.c
index b32fadb..3ef28f3 100644
--- a/src/console/printk.c
+++ b/src/console/printk.c
@@ -49,7 +49,7 @@
    if (!TRACK_CONSOLE_TIME)
    	return;

-	printk(BIOS_DEBUG, "Accumulated console time in " ENV_STRING " %ld ms\n",
+	printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n",
    	DIV_ROUND_CLOSEST(console_usecs, USECS_PER_MSEC));
 }

diff --git a/src/lib/hardwaremain.c b/src/lib/hardwaremain.c
index 3fcf882..eba5f12 100644
--- a/src/lib/hardwaremain.c
+++ b/src/lib/hardwaremain.c
@@ -52,20 +52,6 @@
 static boot_state_t bs_payload_load(void *arg);
 static boot_state_t bs_payload_boot(void *arg);

-/*
- * Typically a state will take 4 time samples:
- *   1. Before state entry callbacks
- *   2. After state entry callbacks / Before state function.
- *   3. After state function / Before state exit callbacks.
- *   4. After state exit callbacks.
- */
-#define MAX_TIME_SAMPLES 4
-struct boot_state_times {
-	int num_samples;
-	struct mono_time samples[MAX_TIME_SAMPLES];
-	long console_usecs[MAX_TIME_SAMPLES];
-};
-
 /* The prologue (BS_ON_ENTRY) and epilogue (BS_ON_EXIT) of a state can be
  * blocked from transitioning to the next (state,seq) pair. When the blockers
  * field is 0 a transition may occur. */
@@ -81,10 +67,8 @@
    struct boot_phase phases[2];
    boot_state_t (*run_state)(void *arg);
    void *arg;
+	int num_samples;
    int complete : 1;
-#if CONFIG(HAVE_MONOTONIC_TIMER)
-	struct boot_state_times times;
-#endif
 };

#define BS_INIT(state_, run_func_)				\
@@ -237,47 +221,44 @@
    return BS_PAYLOAD_BOOT;
 }

-#if CONFIG(HAVE_MONOTONIC_TIMER)
+/*
+ * Typically a state will take 4 time samples:
+ *   1. Before state entry callbacks
+ *   2. After state entry callbacks / Before state function.
+ *   3. After state function / Before state exit callbacks.
+ *   4. After state exit callbacks.
+ */
 static void bs_sample_time(struct boot_state *state)
 {
-	struct mono_time *mt;
+	static const char *const sample_id[] = { "entry", "run", "exit" };
+	static struct mono_time previous_sample;
+	struct mono_time this_sample;
+	long console;

-	long console_usecs = console_time_get_and_reset();
-	state->times.console_usecs[state->times.num_samples] = console_usecs;
+	if (!CONFIG(HAVE_MONOTONIC_TIMER))
+		return;

-	mt = &state->times.samples[state->times.num_samples];
-	timer_monotonic_get(mt);
-	state->times.num_samples++;
+	console = console_time_get_and_reset();
+	timer_monotonic_get(&this_sample);
+	state->num_samples++;
+
+	int i = state->num_samples - 2;
+	if ((i >= 0) && (i < ARRAY_SIZE(sample_id))) {
+		long execution = mono_time_diff_microseconds(&previous_sample, &this_sample);
+
+		/* Report with millisecond precision to reduce log diffs. */
+		execution = DIV_ROUND_CLOSEST(execution, USECS_PER_MSEC);
+		console = DIV_ROUND_CLOSEST(console, USECS_PER_MSEC);
+		if (execution) {
+			printk(BIOS_DEBUG, "BS: %s %s times (exec / console): %ld / %ld ms\n",
+				state->name, sample_id[i], execution - console, console);
+			/* Reset again to ignore printk() time above. */
+			console_time_get_and_reset();
+		}
+	}
+	timer_monotonic_get(&previous_sample);
 }

-static void bs_report_time(struct boot_state *state)
-{
-	long entry_time;
-	long run_time;
-	long exit_time;
-	struct mono_time *samples = &state->times.samples[0];
-
-	entry_time = mono_time_diff_microseconds(&samples[0], &samples[1]);
-	run_time = mono_time_diff_microseconds(&samples[1], &samples[2]);
-	exit_time = mono_time_diff_microseconds(&samples[2], &samples[3]);
-
-	entry_time -= state->times.console_usecs[1];
-	run_time -= state->times.console_usecs[2];
-	exit_time -= state->times.console_usecs[3];
-
-	/* Report with millisecond precision to reduce log diffs. */
-	entry_time = DIV_ROUND_CLOSEST(entry_time, USECS_PER_MSEC);
-	run_time = DIV_ROUND_CLOSEST(run_time, USECS_PER_MSEC);
-	exit_time = DIV_ROUND_CLOSEST(exit_time, USECS_PER_MSEC);
-
-	printk(BIOS_DEBUG, "BS: %s times (ms): entry %ld run %ld exit %ld\n",
-	       state->name, entry_time, run_time, exit_time);
-}
-#else
-static inline void bs_sample_time(struct boot_state *state) {}
-static inline void bs_report_time(struct boot_state *state) {}
-#endif
-
 #if CONFIG(TIMER_QUEUE)
 static void bs_run_timers(int drain)
 {
@@ -388,8 +369,6 @@

bs_sample_time(state);

-		bs_report_time(state);
-
    	state->complete = 1;
    }
 }