Hey coreboot community!
It’s been just under a month of working on coreboot. I’ve not been keeping up with my blog posts. So here is the first of three particularly long posts detailing what I’ve been up to, what decisions I’ve been making, and what problems I’ve faced. This post is a background on logging, the problems it has as of now, and how not to fix them.
Tomorrow I will be posting a blog post giving some background on a change I made to solve these problems in a fair way. I will also be posting a blog post about what’s up next for me.
So how does logging work?
For most programs, logging works simply through slinging text at some interface. A developer wanting to leak some information uses a function to print some information. You can then look at stdout/stderr, or an output file, or syslog, or whatever, and get that leaked run-time information.
Where coreboot differs from most programs is that coreboot is pre-OS. The abstractions that our operating systems provide aren’t available for coreboot, and not just the higher abstractions like syslog. Coreboot is self contained. Where a Hello World using stdio might be something like:
fprintf(stdout, "Hello World\n")
coreboot doesn’t have that privilege. In theory, we could provide all the same familiar functions, but why? We really don’t need them. This information ultimately ends up going out on some UART, so why bother with needless abstractions? We’re constrained to fitting coreboot and a payload and a video option rom and a TXE and so on into 8MB or less… It’s important that we are prudent in what we make available.
So what does the coreboot project do? We have printk(), which you might associate with the linux kernel (‘print kernel’). In fact, this is exactly the case. If you go into src/console/printk.c, you’ll see a humorous message in the copyright notice:
/*
* blatantly copied from linux/kernel/printk.c
*
* Copyright (C) 1991, 1992 Linus Torvalds
*
*/
Why? Recall that coreboot used to be linuxbios, and linuxbios was largely an effort to bootstrap linux. For a really awesome background on coreboot and its origins, and particularly for an interesting look at just how much coreboot has changed over time, you might be interested in watching the first few minutes of this video
But just because we’re inspired by linux doesn’t mean we’re inside linux. In spite of the copyright, coreboot’s printk() does not resemble linux at all anymore besides in name. We’re fully responsible for this function, so how does it work?
Let’s follow a debugging print statement, for example, one at src/lib/cbfs.c:102
DEBUG("Checking offset %zx\n", offset);
Already we have something interesting. What’s 'DEBUG()'? I thought it was printk()?
Go to the top of the file and you’ll see some preprocessor
#if IS_ENABLED(CONFIG_DEBUG_CBFS)
#define DEBUG(x...) printk(BIOS_SPEW, "CBFS: " x)
#else
#define DEBUG(x...)
#endif
Oh, okay. So depending on DEBUG_CBFS, the above DEBUG() call either means an empty statement, or
printk(BIOS_SPEW, "CBFS: " "Checking offset %zx\n", offset);
Firstly, what’s a 'BIOS_SPEW'? Just a constant, as defined in src/include/console/loglevels.h. You’ll notice again that these loglevels mirror the linux loglevels exactly, replacing 'KERNEL_' with 'BIOS_'.
What’s the point of it? If you want to control the verbosity of your logs, you set CONFIG_DEFAULT_CONSOLE_LOGLEVEL to the loglevel you want and you’ll get more or less verbosity as a result. If your configured log level is greater than the loglevel the printk statement is tagged with, it prints.
Why is this file doing this alias of printk? Is it done elsewhere? Why is there a separate CONFIG_DEBUG_CBFS variable? I’ll get to that in a second. This is actually some of the problem I’m setting out to fix. For now, let’s continue by assuming that our configuration is set such that it expands out to printk. Where, then, is printk defined?
Go into src/include/console/console.h and you’ll see what printk() is about:
static inline void printk(int LEVEL, const char *fmt, ...) {}
or
#define printk(LEVEL, fmt, args...) \
do { do_printk(LEVEL, fmt, ##args); } while(0)
Hmm, why the wrapper with preprocessor? If we are producing a final version of coreboot to go into a production setting, there’s an advantage to muting the logging information at compile time, because at aggregate, debugging statements do have a meaningful performance penalty, and we can increase the speed of our boot by making them empty statements.
So it’s really do_printk. It comes from src/console/printk.c. I won’t post the full contents, but I’ll explain briefly what it does:
- checks
LEVELwith the configured log level, muting statements if they’re more verbose than what is requested - when configured as such, in pre-ram settings, mute statements not originating from the bootstrap processor.
- Temporarily stop function tracing (a configuration option to watch functions and their callsites)
- temporarily lock the console resources to the a single thread, ensuring writes do not overlap.
- deal with varargs loading into its type via
va_start().
(notice the'args...'in the signature? That allowsprintkto take
a flexible amount of variables. It places n arguments onto the stack
and so that they can be popped off later. Functions interact with
variable arguments viava_arg().) - calls
vtxprintfwithwrap_putchar, the format string, the variable argument list, andNULL. This interpolates the varargs into the format string and pushes it to the outputs. - clean up variable arguments with
va_end() - flush the tx (not all output methods require it, but it’s harmless in those cases)
- Unlock the console resources
- re-enable tracing
- return the number of bytes of the output.
One cool thing to take away from this is how we abstract the factor of where console output is going from do_printk. wrap_putchar is another (aptly named) wrapper for do_putchar. do_putchar calls src/console/console.c‘s console_tx_byte(), which contains a bunch of functions like '__uart_tx_byte()' or '__usb_tx_byte()' or '__cbmemc_tx_byte()' which might be defined or left empty via preprocessor.
This allows us to not have to consider their differences or implementation in do_printk(), just in configuration and in their own implementations of init(), tx_byte(), and tx_flush()
The entirety of that is interesting, which is why I wanted to talk about it, but it’s not what I’m touching. Now we know how logging works, we know where we can influence it in do_printk(), and we’ve seen that it’s influenced elsewhere in preprocessor, too.
Let’s go back to the proprocessor 'DEBUG()' in src/lib/cbfs.c
#if IS_ENABLED(CONFIG_DEBUG_CBFS)
#define DEBUG(x...) printk(BIOS_SPEW, "CBFS: " x)
#else
#define DEBUG(x...)
#endif
If loglevels control verbosity, why are there additional CONFIG_DEBUG_CBFS variables? The gist of it is that mapping all statements to a level of 1-8 really isn’t granular enough for coreboot anymore. Sometimes you want to see most everything, but you’re not working on changes for CBFS and don’t need to see it dump its tables. Other times you’re working on a bug in CBFS and need all the information you can get, so you set the variable and get more output.
CONFIG_DEBUG_CBFS is not the only variable like this, nor should it be. There’s many different parts of coreboot, some are relevant all the time in your console output, some are rarely relevant, some are relevant when you need them to be, and if we can get more granularity without it being at the expense of performance or of making a complex mess, we should do it.
But there’s more than just CBFS and SMM and the things already defined with CONFIG_DEBUG_* variables. What that means is this will require quite a bit of grokking the source of coreboot, and classifying things. (Can we do this in a programmatic way?)
The first way I tackled this problem was to think about loglevels. What did they mean? The descriptions we had in the header were the same as those in the linux kernel:
#define KERN_EMERG "<0>" /* system is unusable*/
#define KERN_ALERT "<1>" /* action must be taken immediately*/
#define KERN_CRIT "<2>" /* critical conditions*/
#define KERN_ERR "<3>" /* error conditions*/
#define KERN_WARNING "<4>" /* warning conditions*/
#define KERN_NOTICE "<5>" /* normal but significant condition*/
#define KERN_INFO "<6>" /* informational*/
#define KERN_DEBUG "<7>" /* debug-level messages*/
I think this is poorly defined, particularly for coreboot. What’s the difference between a “normal but significant condition” and an “informational” message? What’s critical, what’s an error? In the context of the linux kernel these are clearly distinct but coreboot is do-or-die in a lot of cases. It stands to reason that a kernel can take many more steps than coreboot to recover.
I made a contribution to the header to try to define these in a more clear way. I didn’t get a whole lot of feedback, but it made it in. If you’re reading this and you didn’t see it, please look it over. If you think anything is wrong here, let’s fix it. I felt pretty confident that this mapped well to their current usage within coreboot.
http://review.coreboot.org/#/c/10444/
But that’s really none of the battle. Shockingly, the granularity problem still exists even though I put some comments in a file!
My first thought was, “Well let’s just make a bunch of subsystems, each with their own loglevel 1-8. We can have a CBFS subsystem and an SMM subsystem and a POST code subsystem and so on.”
Let’s explore this idea now. I didn’t. I jumped in and implemented it and before thinking and realized some problems with this idea, quickly putting me back to square one.
When would a POST code qualify as BIOS_SPEW and when would it be BIOS_CRIT? It’s a laughable question. Some of these things are more fitting for toggle rather than a varying level of verbosity, and the current system for doing so is genuinely the best way to make decisions about printing such information… (Though, that doesn’t mean it’s implemented in the best way.)
Meanwhile CBFS probably does have enough of a variation that we can give it its own loglevels. But does it need to be mapped over 8 values? Maybe 4 would be more fitting.
So we want POST mapped to two values. We want CBFS mapped to 4. We want X mapped to N. How can we make a framework for this without creating a mess of Kconfig? How can we make sure that developers know what values they can use?
How are we going to do this in such a way that we don’t mess with preexisting systems? People can set their debug level in CMOS, how is this going to play into that system, where space is limited? We can’t afford to put unlimited configuration values into there. How are we going to do this in a way that extends printk, rather than re-implements it, without breaking everything that exists now? Remember above when I wondered about if other places do preprocessor definitions of printk like 'DEBUG()'? The answer is yes. Nearly everywhere.
It’s a problem of comparing of compile-time configuration against runtime configuration, of weighing preprocessor against implementing things in code, and of weighing simplicity against ease.
So in summation:
- We need more granularity in logging. Right now we’re using putting the preprocessor to work to accomplish that, and while I first thought this was a bad practice, I came to feel feel that it actually isn’t so bad.
- Outside of the additional variables to accomplish extra verbosity, there is little organization of printk statements besides by their log
level. If log messages were properly tagged, logs would be much cleaner and easier to parse. This needs to be accomplished as well. - Logging works through a interface called do_printk(), which is separated out from the lower levels of printing, giving us a lot of freedom to work.
- We must stay conscious of problems that we can introduce through creating too much new configuration.
Check in tomorrow for how I chose to solve this.