Improve LOG_LEVEL capabilities

[sbranden]

We need the ability to enable printing of debug logs at run time rather than compile time. This can be easily accomplished by adding defines into debug.h that can be replaced on a per platform basis to GET_LOG_LEVEL and SET_LOG_LEVEL.

Also, no need to print out 9 characters to indicate NOTICE, ERROR, WARNING, or INFO. Simply printing N:, E:, W:, or I: is sufficient to save space on the screen and increase speed of log.

[sorenb-xlnx]

Shortening the prefix to one letter is probably OK if you're very familiar with the what is going on on your UART, but not in the general case, IMHO. I'd prefer to keep such "optimizations" out of the common/general code base. And compile time disable/enable is really something that would bloat the binary since 99% of users will probably never enable any of those prints.

[sbranden]

I don't think there are 100 different users of the ATF codebase, so 99% is an exaggeration.

The changes I am making do not affect others who do not need a single debug/production image. For those users who wish to recompile their code to debug it they can continue to do so with zero changes to their code.

In terms of shortening prints - I can add a platform specific override to shorten the strings if that is what is needed. Or, everyone can benefit from the shortened names if my change is accepted. Given that you think that 99% of the users never use the prints anyway then it shouldn't be that much of an impact to shorten them though.

[nmenon]

I must be among the 1% of users. Please make the shortening of type and dynamic print configurable. I don't want to deal with random customer support teams needing explanation as to what 'I' is. For people who need prints, yes, I agree it will improve boot performance since lesser characters need to be dumped over uart..

[ghost]

Shortening the prefix does not seem to buy us anything other than making the output more obscure and confusing to people.

[sbranden]

It may not buy anything for you - but it does buy a number of things for us. When you have a 16 or 32 byte UART FIFO having a 9 character prefix is quite substantially. The boot flow is stalled waiting for characters to be printed.

Beyond that - trying to fit ATF into limited memory and debug it is a challenge. Every 500 bytes saved is quite significant.

I'll make the default the same as they are today and add ability to override the prefix. Nobody else will be affected and they can continue to use a 9 character prefix.

[sorenb-xlnx]

IMHO, this is the usual trade off between debugability and performance. And I'd argue that if I'm debugging, I don't care much about performance. Also, due to the sensitive nature of the ATF, a production build should be sparse with prints to begin with. So, if you need performance, you can get best performance by completely disabling all prints (DEBUG=0 LOG_LEVEL=0). Then nothing stalls on a UART and you do not give away any sensitive information. When debugging, I assume you don't mind whether boot takes a few extra seconds or not and you can enable all the printing that you want. And where do you want to draw the line on these optimizations? Next could be a binary format instead of human-readable ascii (I know I'm exaggerating, but there will be always a reason to go more into either of these directions)?

And if you go with run-time switching on/off prints, isn't that completely bloating the binary size since you have to have all prints in the build at all times?

Having said that, I do see the merits of this feature for cases where you need to debug units in the field where you may not be able to swap out the firmware easily/at all. As long as the default stays as is, I don't mind configuration options.

[sbranden]

The prints are far more valuable to have in to debug when boards don't boot than a silent boot and guess what image has not been flash or signed properly or whatever other issue comes up. You can't rebuild BL1 or other components when they are in ROM. We can provision the device to have prints enabled or not.

[jwerner-chromium]

Beyond that - trying to fit ATF into limited memory and debug it is a challenge. Every 500 bytes saved is quite significant.

If you're worried about binary size, wouldn't it make much more sense to just change the code to not repeat the prefix in every error string? Right now NOTICE() and friends are macros that concatenate to the argument string at compile time. Just change them to functions which first print the prefix and then print the actual message, and you'll have to store the prefixes only once.

[sbranden]

Everything else is implemented in the platform layer. Nobody else is the wiser of functionality added now.

[soby-mathew]

Sorry, I don't agree with the patch. As far as I can see, there are 2 concerns with current logs :

• Code size For this I agree with @jwerner-chromium that current macros concatenates the strings which is not memory efficient. A patch to this effect will reduce the code size used for the string RO data and this will be of benefit.

• Console print time There are only few lines of log by default during boot (atleast on FVP) and I am not sure how much we can gain by reducing couple of characters. There can be many other blocking points during boot (like IO) which will drown out any gains made by reducing couple of characters per printed line.

  Or perhaps another way is to have a dummy console driver which prints to memory and have the memory dumped out to console when watchdog fires ? That way, no time is spent for UART console print on a successful boot.

Also another issue with the current patch is that it introduces 5 new platform macros without any perceivable benefit. We have to continue to maintain these platform macros and take care of compatibility in case we change something in the future.

[nmenon]

@soby-mathew console prints are serialized - depending on baud rate and FIFO, they can be pretty painful to watch sometimes.. even in release build mode, there are prints we can see, slowing things down in an environment such as FPGA pre-silicon environment - it is not really characters that matter, but how long those characters get thrown out before the next instruction gets through.. at least in lauterbach profiling I did, I feel @sbranden 's pain. Just saying - kicking prints completely out is an option.. I can even post a DCC support in (cheaper than a semihosting in v8 at least), but in many cases, having some basic prints appear on screen is beneficial (at least people dont scratch heads on "where the heck did it hang")

[soby-mathew]

Then perhaps dynamic log level control will be useful here? IMO, if code size is not of concern, then that is something that will solve the problem atleast for pre-silicon environments.

[nmenon]

@soby-mathew there are markets that are super sensitive to boot delays.. while needing to balance that with debug capability..

Just brain storming...alternatively, changing console framework from the current basic: console_core_init, console_core_putc console_core_getc to a) print buffer b) console_core_init, console_core_tx_ready, console_core_putc, console_core_rx_ready, console_core_getc and associated setup may help alliviate it at the risk of complicating the framework..

if by dynamic, you mean runtime... dynamic log level will need control - cost being an additional var check of somesort.. for an non-interactive bootloader, I am not personally seeing too much of a value.

I think we already have log levels..

[soby-mathew]

OK. Just to clarify, the dynamic log level would only be used during board bring up and in pre-silicon env. It wouldn't be used in a production system.

The input for the control of dynamic log level would be platform specific like some like jumper settings or DT node entry etc. It would be set once for every boot and cannot be changed at run-time.

But allowing each platform using ARM TF to have its own custom log format doesn't seem like a good idea to me.

[sbranden]

As shown by this discussion: different users have different requirements at different stages of development and production for logging. By allowing my simple patch users can implement what they need in the platform level. The default functionality remains in place today (which is sufficient for some/most). For others, we are free to do what is necessary - and it is necessary for us - to replace the log macros with whatever is needed.

[nmenon]

@soby-mathew

But allowing each platform using ARM TF to have its own custom log format doesn't seem like a good idea to me.

Could you elaborate why? I mean on linux, you can do

define pr_fmt(fmt) "%s: " fmt, func

before the includes and change the format to what ever people want. do we have a concern that some platforms may choose to do "ERROR" for debug prints and so on? I mean, nothing stops anyone from doing that today either..

just trying to understand rationale (I get the additional configurable platform macros problem ofcourse, which we probably would like to avoid)..

[soby-mathew]

@nmenon, I was referring to the prints in Generic code which is good to be standard across all platforms IMO. The PR as it stands allows overriding the entire print infrastructure by platforms thus preventing the generic code from adding any functionality without worrying about compatibility which I disagree with.

If I look at the beginning of the discussion, original issue was with the length of the prefix {ERROR, VERBOSE ...} being prefixed to the logs and the associated delay and code size due to that. The current patch is an overkill for the original problem.

I think the solution should be :

1. The log framework should be modified to not to repeat the prefix for every log. Define a default const array that will have the standard prefix {"ERROR", "INFO", "NOTICE"...} which will be referred to by the ERROR(), NOTICE() and other macros for the prefix.

2. Optionally the platforms can override this default array. Thus if a platform chooses to have shorter prefix, it is free to do so.

This ensures that the platforms can only override the log prefix and solves the problem with code size/prefix length.

[sbranden]

@soby-mathew, simply shortening print screens is not sufficient. This code may be in ROM and we need the ability to select whether specific prints are enabled or not at run time. This is controlled in a platform specific way. On our current platform it is controlled via SOTP setting for BL1 - entirely platform specific. And, at later stages (BL2, BL31) it can be changed as needed.

It still puzzles me why you are opposed to changes made by real users of ATF code. This improvement does not affect your current functionality and adds the necessary features that I do require. If you worked at various silicon companies you will see that they do have other features in their boot rom beyond the BL1 ATF implementation. We build, debug, AND test the same version of code we go to production with. We don't recompile the code to debug it. We run the same code in simulation at very reduced speeds, on ATE during chip screens, and at full speed on the real SoC.

In order to use BL1 in real products we need to enhance what the boot rom does.

Also, this does not introduce any sort of incompatibility with the rest of the ATF software. There is nothing in the specification disallowing run time selection of whether debug prints are produced or not.

[soby-mathew]

@sbranden, Apologies if I am not seeing the full picture. This fix may solve your problem , but I need to ensure that this fix covers all the possible scenarios and the fix is the best possible solution to the problem. This fix allows platform to override the tf_printf() and other console layers using LOG macros but fails to consider prints from other parts of generic code (like print during assert, panic, asm_assert etc). This is not desirable for us , if you see what I mean.

If you read my previous comments, dynamic logging is something we would like consider in generic code.

Probably the platform requirements are very diverse that this turns out to the right solution, but I need to understand before adding 5 new platform interfaces.

[danh-arm]

There are a number of issues/requirements in this thread. One issue that's not been mentioned is the leakage of information that's potentially useful to an attacker. In general I'd expect a minimum amount of console output to be emitted in release builds. Currently we only emit log messages at LOG_LEVEL_NOTICE and below by default. At one point we considered removing log messages in release builds altogether but decided that was over the top. It's a reasonable requirement for platforms to emit additional logging at runtime via some configurable mechanism, but that mechanism should not be on by default and should not be accessible by an attacker.

Anyway, getting back to specific issue here, it's reasonable to allow platforms to override the behaviour of the logging macros, but I think it would be better to do this with one new platform interface rather than 5. Also, I think it would better to use a C API than a macro, to provide a clearer API definition with which to maintain compatibility. So for example in platform.h:

void plat_log_printf(int log_level, const char *fmt, ...);

The logging macros would call this and there would be a default weak implementation in plat/common with the current behaviour. That would also localise the prefix strings into one place, which will reduce the code size a bit.

I expect at some point we'll need more generic support for dynamic configuration of log levels (which Soby refers to). We can update the plat/common definition with this functionality later.

[danh-arm]

Actually, forget that idea. My suggestion would introduce a runtime switch on the log_level, which would impact performance. For that reason it probably is better to use a macro, but maybe the log_level can be passed through the API statically so that only 1 new platform API is needed? In any case. the API contract needs to be described in the porting guide.

[sbranden]

@danh-arm. I'l push a new version which only adds one plat define and describes usage in porting guide.

[sbranden]

New pull request here: https://github.com/ARM-software/arm-trusted-firmware/pull/883

[danh-arm]

As mentioned here, we intend to implement this within ARM in order to take care of the API future proofing issues. We'll report back here when there's something to share.