Turn CBMEM console into a ring buffer that can persist across reboots

This patch allows the CBMEM console to persist across reboots, which
should greatly help post factum debugging of issues involving multiple
reboots. In order to prevent the console from filling up, it will
instead operate as a ring buffer that continues to evict the oldest
lines once full. (This means that if even a single boot doesn't fit into
the buffer, we will now drop the oldest lines whereas previous code
would've dropped the newest lines instead.)

The console control structure is modified in a sorta
backwards-compatible way, so that new readers can continue to work with
old console buffers and vice versa. When an old reader reads a new
buffer that has already once overflowed (i.e. is operating in true ring
buffer mode) it will print lines out of order, but it will at least
still print out the whole console content and not do any illegal memory
accesses (assuming it correctly implemented cursor overflow as it was
already possible before this patch).

BUG=chromium:651966
TEST=Rebooted and confirmed output repeatedly on a Kevin and a Falco.
Also confirmed correct behavior across suspend/resume for the latter.

Change-Id: Ifcbf59d58e1ad20995b98d111c4647281fbb45ff
Signed-off-by: Julius Werner <jwerner@chromium.org>
Reviewed-on: https://review.coreboot.org/18301
Tested-by: build bot (Jenkins)
Reviewed-by: Aaron Durbin <adurbin@chromium.org>
This commit is contained in:
Julius Werner 2017-02-02 17:32:00 -08:00
parent 2d35809530
commit d67c6876b5
4 changed files with 163 additions and 182 deletions

View File

@ -35,6 +35,9 @@ struct cbmem_console {
u8 body[0]; u8 body[0];
} __attribute__ ((__packed__)); } __attribute__ ((__packed__));
#define CURSOR_MASK ((1 << 28) - 1)
#define OVERFLOW (1 << 31)
static u32 char_width(char c, u32 cursor, u32 screen_width) static u32 char_width(char c, u32 cursor, u32 screen_width)
{ {
@ -114,23 +117,28 @@ static int bootlog_module_init(void)
} }
/* Extract console information */ /* Extract console information */
char *buffer = (char *)(&(console->body)); char *buffer = (char *)(&(console->body));
u32 buffer_size = console->size; u32 size = console->size;
u32 cursor = console->cursor; u32 cursor = console->cursor & CURSOR_MASK;
/* The cursor may be bigger than buffer size when the buffer is full */ /* The cursor may be bigger than buffer size with older console code */
if (cursor >= buffer_size) { if (cursor >= size) {
cursor = buffer_size - 1; cursor = size - 1;
} }
/* Calculate how much characters will be displayed on screen */ /* Calculate how much characters will be displayed on screen */
u32 chars_count = calculate_chars_count(buffer, cursor + 1, SCREEN_X, LINES_SHOWN); u32 chars_count = calculate_chars_count(buffer, cursor, SCREEN_X, LINES_SHOWN);
u32 overflow_chars_count = 0;
if (console->cursor & OVERFLOW) {
overflow_chars_count = calculate_chars_count(buffer + cursor,
size - cursor, SCREEN_X, LINES_SHOWN);
}
/* Sanity check, chars_count must be padded to full line */ /* Sanity check, chars_count must be padded to full line */
if (chars_count % SCREEN_X != 0) { if (chars_count % SCREEN_X || overflow_chars_count % SCREEN_X) {
return -2; return -2;
} }
g_lines_count = chars_count / SCREEN_X; g_lines_count = (chars_count + overflow_chars_count) / SCREEN_X;
g_max_cursor_line = MAX(g_lines_count - 1 - LINES_SHOWN, 0); g_max_cursor_line = MAX(g_lines_count - 1 - LINES_SHOWN, 0);
g_buf = malloc(chars_count); g_buf = malloc(chars_count);
@ -138,17 +146,26 @@ static int bootlog_module_init(void)
return -3; return -3;
} }
if (sanitize_buffer_for_display(buffer, cursor + 1, if (console->cursor & OVERFLOW) {
g_buf, chars_count, if (sanitize_buffer_for_display(buffer + cursor, size - cursor,
SCREEN_X) < 0) { g_buf, overflow_chars_count, SCREEN_X) < 0) {
free(g_buf); goto err_free;
g_buf = NULL; }
return -4; }
if (sanitize_buffer_for_display(buffer, cursor,
g_buf + overflow_chars_count,
chars_count, SCREEN_X) < 0) {
goto err_free;
} }
/* TODO: Maybe a _cleanup hook where we call free()? */ /* TODO: Maybe a _cleanup hook where we call free()? */
return 0; return 0;
err_free:
free(g_buf);
g_buf = NULL;
return -4;
} }
static int bootlog_module_redraw(WINDOW *win) static int bootlog_module_redraw(WINDOW *win)

View File

@ -36,6 +36,9 @@ struct cbmem_console {
uint8_t body[0]; uint8_t body[0];
} __attribute__ ((__packed__)); } __attribute__ ((__packed__));
#define CURSOR_MASK ((1 << 28) - 1)
#define OVERFLOW (1 << 31)
static struct cbmem_console *cbmem_console_p; static struct cbmem_console *cbmem_console_p;
static struct console_output_driver cbmem_console_driver = static struct console_output_driver cbmem_console_driver =
@ -43,18 +46,32 @@ static struct console_output_driver cbmem_console_driver =
.write = &cbmem_console_write, .write = &cbmem_console_write,
}; };
static void do_write(const void *buffer, size_t count)
{
memcpy(cbmem_console_p->body + (cbmem_console_p->cursor & CURSOR_MASK),
buffer, count);
cbmem_console_p->cursor += count;
}
void cbmem_console_init(void) void cbmem_console_init(void)
{ {
cbmem_console_p = lib_sysinfo.cbmem_cons; cbmem_console_p = lib_sysinfo.cbmem_cons;
if (cbmem_console_p) if (cbmem_console_p && cbmem_console_p->size)
console_add_output_driver(&cbmem_console_driver); console_add_output_driver(&cbmem_console_driver);
} }
void cbmem_console_write(const void *buffer, size_t count) void cbmem_console_write(const void *buffer, size_t count)
{ {
if (cbmem_console_p->cursor + count >= cbmem_console_p->size) while ((cbmem_console_p->cursor & CURSOR_MASK) + count >=
return; cbmem_console_p->size) {
size_t still_fits = cbmem_console_p->size -
(cbmem_console_p->cursor & CURSOR_MASK);
do_write(buffer, still_fits);
cbmem_console_p->cursor &= ~CURSOR_MASK;
cbmem_console_p->cursor |= OVERFLOW;
buffer += still_fits;
count -= still_fits;
}
memcpy(cbmem_console_p->body + cbmem_console_p->cursor, buffer, count); do_write(buffer, count);
cbmem_console_p->cursor += count;
} }

View File

@ -23,9 +23,11 @@
/* /*
* Structure describing console buffer. It is overlaid on a flat memory area, * Structure describing console buffer. It is overlaid on a flat memory area,
* with body covering the extent of the memory. Once the buffer is * with body covering the extent of the memory. Once the buffer is full,
* full, the cursor keeps going but the data is dropped on the floor. This * output will wrap back around to the start of the buffer. The high bit of the
* allows to tell how much data was lost in the process. * cursor field gets set to indicate that this happened. If the underlying
* storage allows this, the buffer will persist across multiple boots and append
* to the previous log.
*/ */
struct cbmem_console { struct cbmem_console {
u32 size; u32 size;
@ -33,10 +35,13 @@ struct cbmem_console {
u8 body[0]; u8 body[0];
} __attribute__ ((__packed__)); } __attribute__ ((__packed__));
static struct cbmem_console *cbmem_console_p CAR_GLOBAL; #define MAX_SIZE (1 << 28) /* can't be changed without breaking readers! */
#define CURSOR_MASK (MAX_SIZE - 1) /* bits 31-28 are reserved for flags */
#define OVERFLOW (1 << 31) /* set if in ring-buffer mode */
_Static_assert(CONFIG_CONSOLE_CBMEM_BUFFER_SIZE <= MAX_SIZE,
"cbmem_console format cannot support buffers larger than 256MB!");
static void copy_console_buffer(struct cbmem_console *old_cons_p, static struct cbmem_console *cbmem_console_p CAR_GLOBAL;
struct cbmem_console *new_cons_p);
#ifdef __PRE_RAM__ #ifdef __PRE_RAM__
/* /*
@ -62,38 +67,36 @@ static void copy_console_buffer(struct cbmem_console *old_cons_p,
static u8 static_console[STATIC_CONSOLE_SIZE]; static u8 static_console[STATIC_CONSOLE_SIZE];
#endif #endif
/* flags for init */ static struct cbmem_console *current_console(void)
#define CBMEMC_RESET (1<<0)
#define CBMEMC_APPEND (1<<1)
static inline struct cbmem_console *current_console(void)
{ {
return car_sync_var(cbmem_console_p); return car_sync_var(cbmem_console_p);
} }
static inline void current_console_set(struct cbmem_console *new_console_p) static void current_console_set(struct cbmem_console *new_console_p)
{ {
car_set_var(cbmem_console_p, new_console_p); car_set_var(cbmem_console_p, new_console_p);
} }
static inline void init_console_ptr(void *storage, u32 total_space, int flags) static int buffer_valid(struct cbmem_console *cbm_cons_p, u32 total_space)
{
return (cbm_cons_p->cursor & CURSOR_MASK) < cbm_cons_p->size &&
cbm_cons_p->size <= MAX_SIZE &&
cbm_cons_p->size == total_space - sizeof(struct cbmem_console);
}
static void init_console_ptr(void *storage, u32 total_space)
{ {
struct cbmem_console *cbm_cons_p = storage; struct cbmem_console *cbm_cons_p = storage;
if (!cbm_cons_p || total_space == 0) { if (!cbm_cons_p || total_space <= sizeof(struct cbmem_console)) {
current_console_set(NULL); current_console_set(NULL);
return; return;
} }
if (flags & CBMEMC_RESET) { if (!buffer_valid(cbm_cons_p, total_space)) {
cbm_cons_p->size = total_space - sizeof(struct cbmem_console); cbm_cons_p->size = total_space - sizeof(struct cbmem_console);
cbm_cons_p->cursor = 0; cbm_cons_p->cursor = 0;
} }
if (flags & CBMEMC_APPEND) {
struct cbmem_console *tmp_cons_p = current_console();
if (tmp_cons_p)
copy_console_buffer(tmp_cons_p, cbm_cons_p);
}
current_console_set(cbm_cons_p); current_console_set(cbm_cons_p);
} }
@ -101,149 +104,74 @@ static inline void init_console_ptr(void *storage, u32 total_space, int flags)
void cbmemc_init(void) void cbmemc_init(void)
{ {
#ifdef __PRE_RAM__ #ifdef __PRE_RAM__
int flags = 0; /* Pre-RAM environments use special buffer placed by linker script. */
init_console_ptr(_preram_cbmem_console, _preram_cbmem_console_size);
/* If in bootblock always initialize the console first. */
if (ENV_BOOTBLOCK)
flags = CBMEMC_RESET;
else if (ENV_ROMSTAGE) {
/* Initialize console for the first time in romstage when
* there's no prior stage that initialized it first. */
if (!IS_ENABLED(CONFIG_VBOOT_STARTS_IN_BOOTBLOCK) &&
!IS_ENABLED(CONFIG_BOOTBLOCK_CONSOLE))
flags = CBMEMC_RESET;
} else if (ENV_VERSTAGE) {
/*
* Initialize console for the first time in verstage when
* there is no console in bootblock. Otherwise honor the
* bootblock console when verstage comes right after
* bootblock.
*/
if (IS_ENABLED(CONFIG_VBOOT_STARTS_IN_BOOTBLOCK) &&
!IS_ENABLED(CONFIG_BOOTBLOCK_CONSOLE))
flags = CBMEMC_RESET;
}
init_console_ptr(_preram_cbmem_console,
_preram_cbmem_console_size, flags);
#else #else
/* /* Post-RAM uses static (BSS) buffer before CBMEM is reinitialized. */
* Initializing before CBMEM is available, use static buffer to store init_console_ptr(static_console, sizeof(static_console));
* the log.
*/
init_console_ptr(static_console, sizeof(static_console), CBMEMC_RESET);
#endif #endif
} }
void cbmemc_tx_byte(unsigned char data) void cbmemc_tx_byte(unsigned char data)
{ {
struct cbmem_console *cbm_cons_p = current_console(); struct cbmem_console *cbm_cons_p = current_console();
u32 cursor;
if (!cbm_cons_p) if (!cbm_cons_p || !cbm_cons_p->size)
return; return;
cursor = cbm_cons_p->cursor++; u32 flags = cbm_cons_p->cursor & ~CURSOR_MASK;
if (cursor < cbm_cons_p->size) u32 cursor = cbm_cons_p->cursor & CURSOR_MASK;
cbm_cons_p->body[cursor] = data;
cbm_cons_p->body[cursor++] = data;
if (cursor >= cbm_cons_p->size) {
cursor = 0;
flags |= OVERFLOW;
}
cbm_cons_p->cursor = flags | cursor;
} }
/* /*
* Copy the current console buffer (either from the cache as RAM area, or from * Copy the current console buffer (either from the cache as RAM area or from
* the static buffer, pointed at by cbmem_console_p) into the CBMEM console * the static buffer, pointed at by src_cons_p) into the newly initialized CBMEM
* buffer space (pointed at by new_cons_p), concatenating the copied data with * console. The use of cbmemc_tx_byte() ensures that all special cases for the
* the CBMEM console buffer contents. * target console (e.g. overflow) will be handled. If there had been an
* * overflow in the source console, log a message to that effect.
* If there is overflow - add to the destination area a string, reporting the
* overflow and the number of dropped characters.
*/ */
static void copy_console_buffer(struct cbmem_console *old_cons_p, static void copy_console_buffer(struct cbmem_console *src_cons_p)
struct cbmem_console *new_cons_p)
{ {
u32 copy_size, dropped_chars; u32 c;
u32 cursor = new_cons_p->cursor;
if (old_cons_p->cursor < old_cons_p->size) if (!src_cons_p)
copy_size = old_cons_p->cursor; return;
else
copy_size = old_cons_p->size;
if (cursor > new_cons_p->size) if (src_cons_p->cursor & OVERFLOW) {
copy_size = 0; const char overflow_warning[] = "\n*** Pre-CBMEM console "
else if (cursor + copy_size > new_cons_p->size) "overflowed, log truncated ***\n";
copy_size = new_cons_p->size - cursor; for (c = 0; c < sizeof(overflow_warning) - 1; c++)
cbmemc_tx_byte(overflow_warning[c]);
dropped_chars = old_cons_p->cursor - copy_size; for (c = src_cons_p->cursor & CURSOR_MASK;
if (dropped_chars) { c < src_cons_p->size; c++)
/* Reserve 80 chars to report overflow, if possible. */ cbmemc_tx_byte(src_cons_p->body[c]);
if (copy_size < 80)
return;
copy_size -= 80;
dropped_chars += 80;
} }
memcpy(new_cons_p->body + cursor, old_cons_p->body, for (c = 0; c < (src_cons_p->cursor & CURSOR_MASK); c++)
copy_size); cbmemc_tx_byte(src_cons_p->body[c]);
cursor += copy_size; /* Invalidate the source console, so it will be reinitialized on the
next reboot. Otherwise, we might copy the same bytes again. */
if (dropped_chars) { src_cons_p->size = 0;
const char loss_str1[] = "\n\n*** Log truncated, ";
const char loss_str2[] = " characters dropped. ***\n\n";
/*
* When running from ROM sprintf is not available, a simple
* itoa implementation is used instead.
*/
int got_first_digit = 0;
/* Way more than possible number of dropped characters. */
u32 mult = 100000;
strcpy((char *)new_cons_p->body + cursor, loss_str1);
cursor += sizeof(loss_str1) - 1;
while (mult) {
int digit = dropped_chars / mult;
if (got_first_digit || digit) {
new_cons_p->body[cursor++] = digit + '0';
dropped_chars %= mult;
/* Excessive, but keeps it simple */
got_first_digit = 1;
}
mult /= 10;
}
strcpy((char *)new_cons_p->body + cursor, loss_str2);
cursor += sizeof(loss_str2) - 1;
}
new_cons_p->cursor = cursor;
} }
static void cbmemc_reinit(int is_recovery) static void cbmemc_reinit(int is_recovery)
{ {
struct cbmem_console *cbm_cons_p;
const size_t size = CONFIG_CONSOLE_CBMEM_BUFFER_SIZE; const size_t size = CONFIG_CONSOLE_CBMEM_BUFFER_SIZE;
int flags = CBMEMC_APPEND; /* If CBMEM entry already existed, old contents are not altered. */
struct cbmem_console *cbmem_cons_p = cbmem_add(CBMEM_ID_CONSOLE, size);
struct cbmem_console *previous_cons_p = current_console();
/* No appending when no preram console available and adding for init_console_ptr(cbmem_cons_p, size);
* the first time. */ copy_console_buffer(previous_cons_p);
if (!ENV_RAMSTAGE && !ENV_POSTCAR && _preram_cbmem_console_size == 0)
flags = CBMEMC_RESET;
/* Need to reset the newly added cbmem console in romstage. */
if (ENV_ROMSTAGE)
flags |= CBMEMC_RESET;
/* Need to reset the newly added cbmem console in ramstage
* when there was no console in preram environment. */
if (ENV_RAMSTAGE && IS_ENABLED(CONFIG_LATE_CBMEM_INIT))
flags |= CBMEMC_RESET;
/* If CBMEM entry already existed, old contents is not altered. */
cbm_cons_p = cbmem_add(CBMEM_ID_CONSOLE, size);
init_console_ptr(cbm_cons_p, size, flags);
} }
ROMSTAGE_CBMEM_INIT_HOOK(cbmemc_reinit) ROMSTAGE_CBMEM_INIT_HOOK(cbmemc_reinit)
RAMSTAGE_CBMEM_INIT_HOOK(cbmemc_reinit) RAMSTAGE_CBMEM_INIT_HOOK(cbmemc_reinit)
@ -253,14 +181,18 @@ POSTCAR_CBMEM_INIT_HOOK(cbmemc_reinit)
void cbmem_dump_console(void) void cbmem_dump_console(void)
{ {
struct cbmem_console *cbm_cons_p; struct cbmem_console *cbm_cons_p;
int cursor; u32 cursor;
cbm_cons_p = current_console(); cbm_cons_p = current_console();
if (!cbm_cons_p) if (!cbm_cons_p)
return; return;
uart_init(0); uart_init(0);
for (cursor = 0; cursor < cbm_cons_p->cursor; cursor++) if (cbm_cons_p->cursor & OVERFLOW)
for (cursor = cbm_cons_p->cursor & CURSOR_MASK;
cursor < cbm_cons_p->size; cursor++)
uart_tx_byte(0, cbm_cons_p->body[cursor]);
for (cursor = 0; cursor < (cbm_cons_p->cursor & CURSOR_MASK); cursor++)
uart_tx_byte(0, cbm_cons_p->body[cursor]); uart_tx_byte(0, cbm_cons_p->body[cursor]);
} }
#endif #endif

View File

@ -601,52 +601,67 @@ static void dump_timestamps(int mach_readable)
unmap_memory(); unmap_memory();
} }
struct cbmem_console {
u32 size;
u32 cursor;
u8 body[0];
} __attribute__ ((__packed__));
#define CBMC_CURSOR_MASK ((1 << 28) - 1)
#define CBMC_OVERFLOW (1 << 31)
/* dump the cbmem console */ /* dump the cbmem console */
static void dump_console(void) static void dump_console(void)
{ {
void *console_p; struct cbmem_console *console_p;
char *console_c; char *console_c;
uint32_t size; size_t size, cursor;
uint32_t cursor;
if (console.tag != LB_TAG_CBMEM_CONSOLE) { if (console.tag != LB_TAG_CBMEM_CONSOLE) {
fprintf(stderr, "No console found in coreboot table.\n"); fprintf(stderr, "No console found in coreboot table.\n");
return; return;
} }
console_p = map_memory_size((unsigned long)console.cbmem_addr, size = sizeof(*console_p);
2 * sizeof(uint32_t), 1); console_p = map_memory_size((unsigned long)console.cbmem_addr, size, 1);
/* The in-memory format of the console area is: cursor = console_p->cursor & CBMC_CURSOR_MASK;
* u32 size if (!(console_p->cursor & CBMC_OVERFLOW) && cursor < console_p->size)
* u32 cursor
* char console[size]
* Hence we have to add 8 to get to the actual console string.
*/
size = ((uint32_t *)console_p)[0];
cursor = ((uint32_t *)console_p)[1];
/* Cursor continues to go on even after no more data fits in
* the buffer but the data is dropped in this case.
*/
if (size > cursor)
size = cursor; size = cursor;
console_c = calloc(1, size + 1); else
size = console_p->size;
unmap_memory(); unmap_memory();
console_c = malloc(size + 1);
if (!console_c) { if (!console_c) {
fprintf(stderr, "Not enough memory for console.\n"); fprintf(stderr, "Not enough memory for console.\n");
exit(1); exit(1);
} }
console_c[size] = '\0';
console_p = map_memory_size((unsigned long)console.cbmem_addr, console_p = map_memory_size((unsigned long)console.cbmem_addr,
size + sizeof(size) + sizeof(cursor), 1); size + sizeof(*console_p), 1);
aligned_memcpy(console_c, console_p + 8, size); if (console_p->cursor & CBMC_OVERFLOW) {
if (cursor >= size) {
printf("cbmem: ERROR: CBMEM console struct is illegal, "
"output may be corrupt or out of order!\n\n");
cursor = 0;
}
aligned_memcpy(console_c, console_p->body + cursor,
size - cursor);
aligned_memcpy(console_c + size - cursor,
console_p->body, cursor);
} else {
aligned_memcpy(console_c, console_p->body, size);
}
/* Slight memory corruption may occur between reboots and give us a few
unprintable characters like '\0'. Replace them with '?' on output. */
for (cursor = 0; cursor < size; cursor++)
if (!isprint(console_c[cursor]) && !isspace(console_c[cursor]))
console_c[cursor] = '?';
printf("%s\n", console_c); printf("%s\n", console_c);
if (size < cursor)
printf("%d %s lost\n", cursor - size,
(cursor - size) == 1 ? "byte":"bytes");
free(console_c); free(console_c);
unmap_memory(); unmap_memory();
} }