erebion/coreboot
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Haswell NRI: Measure per-task execution time

Browse source 
Add some simple execution time measurement code. It only logs execution
times if `DEBUG_RAM_SETUP` is selected. Note that this will fill things
like pre-RAM CBMEM console, but NRI's debug output is already extremely
verbose, and will become even more verbose as additional training steps
get added.

Future plans include measuring the time spent waiting for REUT hardware
to finish testing, as that is what takes most time for complex training
algorithms (which are yet to be published).

Tested on Asrock B85M Pro4, still boots to Arch Linux. Output example:

    +------------------+------------+
    | Task             |      msecs |
    +------------------+------------+
    | PROCSPD          |        503 |
    | INITMPLL         |         33 |
    | CONVTIM          |         43 |
    | CONFMC           |          1 |
    | MEMMAP           |         39 |
    | JEDECINIT        |          1 |
    | PRETRAIN         |         23 |
    | SOT              |        394 |
    | RCVET            |       1448 |
    | RDMPRT           |       1088 |
    | JWRL             |       1975 |
    | OPTCOMP          |          0 |
    | POSTTRAIN        |          0 |
    | ACTIVATE         |          0 |
    | SAVE_TRAIN       |          0 |
    | SAVE_NONT        |          0 |
    | RAMINITEND       |          4 |
    +------------------+------------+
    | Total            |       5558 |
    +------------------+------------+

Note: the board had 4x dual-rank DIMMs installed, which gives the worst
possible boot time (more ranks to train, and that means more log output
to push through 115200 baud serial). Without debug logging, training is
substantially faster.

Change-Id: Ie4b6f6246e54f23d03babdb6fa0271538f69984e
Signed-off-by: Angel Pons <th3fanbus@gmail.com>
Reviewed-on: https://review.coreboot.org/c/coreboot/+/87830
Reviewed-by: Maximilian Brune <maximilian.brune@9elements.com>
Tested-by: build bot (Jenkins) <no-reply@coreboot.org>
This commit is contained in:
Angel Pons 2025-05-25 13:03:04 +02:00 • committed by Matt DeVillier
commit ab29f52ee2
1 changed files with 34 additions and 1 deletions
Download patch file Download diff file Expand all files Collapse all files

35
src/northbridge/intel/haswell/native_raminit/raminit_main.c
View file

@ -10,6 +10,7 @@
#include <northbridge/intel/haswell/raminit.h>
#include <static.h>
#include <string.h>
#include <timer.h>
#include <types.h>
#include "raminit_native.h"
@ -85,6 +86,9 @@ static const struct task_entry fast_boot[] = {
{ raminit_done, true, "RAMINITEND", },
};
_Static_assert(ARRAY_SIZE(cold_boot) >= ARRAY_SIZE(fast_boot),
"Code assumes cold boot task list is the longest one");
/* Return a generic stepping value to make stepping checks simpler */
static enum generic_stepping get_stepping(const uint32_t cpuid)
{
@ -120,6 +124,9 @@ static void initialize_ctrl(struct sysinfo *ctrl)
ctrl->bootmode = bootmode;
}
/** TODO: Adjust unit scale dynamically? **/
#define T_SCALE 1000 /* 1 = usecs, 1000 = msecs */
static enum raminit_status try_raminit(
struct sysinfo *ctrl,
const struct task_entry *const schedule,
@ -127,7 +134,11 @@ static enum raminit_status try_raminit(
{
enum raminit_status status = RAMINIT_STATUS_UNSPECIFIED_ERROR;
for (size_t i = 0; i < length; i++) {
long spent_time[ARRAY_SIZE(cold_boot)] = { 0 };
long total = 0;
size_t i;
for (i = 0; i < length; i++) {
const struct task_entry *const entry = &schedule[i];
assert(entry);
assert(entry->name);
@ -136,14 +147,36 @@ static enum raminit_status try_raminit(
assert(entry->task);
printk(RAM_DEBUG, "\nExecuting raminit task %s\n", entry->name);
struct mono_time prev, curr;
timer_monotonic_get(&prev);
status = entry->task(ctrl);
timer_monotonic_get(&curr);
spent_time[i] = mono_time_diff_microseconds(&prev, &curr);
printk(RAM_DEBUG, "\n");
if (status) {
i++;
printk(BIOS_ERR, "raminit failed on step %s\n", entry->name);
break;
}
}
if (CONFIG(DEBUG_RAM_SETUP)) {
const char unit_multiplier = T_SCALE == 1 ? 'u' : 'm';
printk(RAM_DEBUG, "+------------------+------------+\n");
printk(RAM_DEBUG, "| Task | %csecs |\n", unit_multiplier);
printk(RAM_DEBUG, "+------------------+------------+\n");
assert(i <= length);
for (size_t j = 0; j < i; j++) {
char buf[] = " ";
strncpy(buf, schedule[j].name, strlen(schedule[j].name));
printk(RAM_DEBUG, "| %s | % 10ld |\n", buf, spent_time[j] / T_SCALE);
total += spent_time[j];
}
printk(RAM_DEBUG, "+------------------+------------+\n");
printk(RAM_DEBUG, "| Total | % 10ld |\n", total / T_SCALE);
printk(RAM_DEBUG, "+------------------+------------+\n");
}
return status;
}