summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorKyösti Mälkki <kyosti.malkki@gmail.com>2019-11-02 18:14:31 +0200
committerNico Huber <nico.h@gmx.de>2019-12-31 17:38:04 +0000
commit94694a810e752760ba18d1cf545c63ff3287092b (patch)
tree5fcb39ef4ce9ee77d8938847511b7b341b0a82d9
parent99b075aa94e238fc459378ce9749214ac562621b (diff)
downloadcoreboot-94694a810e752760ba18d1cf545c63ff3287092b.tar.xz
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 <kyosti.malkki@gmail.com> Reviewed-on: https://review.coreboot.org/c/coreboot/+/36584 Tested-by: build bot (Jenkins) <no-reply@coreboot.org> Reviewed-by: Nico Huber <nico.h@gmx.de>
-rw-r--r--src/console/printk.c2
-rw-r--r--src/lib/hardwaremain.c91
2 files changed, 36 insertions, 57 deletions
diff --git a/src/console/printk.c b/src/console/printk.c
index b32fadb8b1..3ef28f32be 100644
--- a/src/console/printk.c
+++ b/src/console/printk.c
@@ -49,7 +49,7 @@ void console_time_report(void)
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 3fcf8829f3..eba5f12625 100644
--- a/src/lib/hardwaremain.c
+++ b/src/lib/hardwaremain.c
@@ -52,20 +52,6 @@ static boot_state_t bs_write_tables(void *arg);
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_state {
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,46 +221,43 @@ static boot_state_t bs_payload_boot(void *arg)
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;
-
- long console_usecs = console_time_get_and_reset();
- state->times.console_usecs[state->times.num_samples] = console_usecs;
-
- mt = &state->times.samples[state->times.num_samples];
- timer_monotonic_get(mt);
- state->times.num_samples++;
-}
-
-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);
+ static const char *const sample_id[] = { "entry", "run", "exit" };
+ static struct mono_time previous_sample;
+ struct mono_time this_sample;
+ long console;
+
+ if (!CONFIG(HAVE_MONOTONIC_TIMER))
+ return;
+
+ 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);
}
-#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 @@ static void bs_walk_state_machine(void)
bs_sample_time(state);
- bs_report_time(state);
-
state->complete = 1;
}
}