Tidy-up of TRACE Macros in Bootloader (and possibly elsewhere)?

[stellarpower]

Hi,

I'm trying to build the system to get more verbose output for the loader process as my installation isn't being found. I was about ot run Jam with the required macros defined, but it seems there's a variety of differnet tracing macros being used, each slightly different from the others. For example:

• ​fat/File.cpp
• ​partitions.cpp
• ​elf.cpp

to name some of those in question. There seems to be a variety of conventions, including

---

Macro takes variadic arguments	Call requires parentheses included
#define TRACE(...) dprintf(__VA_ARGS__)	#define TRACE x dprintf x

---

No-op default definition is commented	No-op definition included in the source
// #define TRACE_SOMETHING	#define TRACE_SOMETHING
#ifdef TRACE_SOMETHING	#ifdef TRACE_SOMETHING

I would have thought this would require editing the file during the build process in order to override, which if so, isn't great.

---

No-op definition is blank	No-op definition reduced to no instruction
#define TRACE(x)	#define TRACE(x) do{} while(0);
#define TRACE(x) ;	#define TRACE(x) do{} while(false);

---

Is there a reason for this variation, or is this just different conventions accumulating from years of code? Would I be okay to tidy these up and submit a patch? In a totally ideal world, it would be nice, I think, to have something similar ot how we can engage the bootmenu with spacebar, for a different key, that would enable printing of these messages to the serial console without needing to recompile. Or possibly, as for booting the kernel, a menu that allows enabling of different levels/areas of tracing. In fact I don't know if this could be incorporated into the menu itself, e.g. if the menu is shown, then unless this was user-requested it's probable no installation has been found/it's a non-bootable system for whatever reason, at which point I don't know if it would be possible to select to print the debug output and for the bootloader to load itself over again, this time outputting more information to serial. Although I don't know how simple this would be or if it would be worth it, but could certainly make things easier going forwards - especially if greater support for ARM, EFI, etc. is desired eventually.

Also don't know how much this applies to the rest of the code, just using github's search feature it's looking a bit more formulaic overall as:

//#define TRACE_SOMETHING
#ifdef TRACE_SOMETHING
#define TRACE(x) dprintf x
#else
#	define TRACE(x) ;
#endif

Any thoughts? Is this by design or would a look at this be worth some input - am happy to take this on, feels like a nice easy patch, at least for the first part if it just wants tidying.

Cheers :)

[pulkomandy]

Hi!

I think the main way used is the last one you quoted:

//#define TRACE_SOMETHING
#ifdef TRACE_SOMETHING
#define TRACE(x) dprintf x
#else
#	define TRACE(x) ;
#endif

It has its limitations, mainly that the TRACE macro needs to be called like this:

TRACE(("some string"));

Notice the double parentheses (one for the macro expansion, one for the dprintf call).

This way of doing things was (I think) imported from NewOS. The solution with __VA_ARGS__ was introduced later to avoid this, but not all the code was migrated.

For enabling the tracing, there are two ways:

• Edit the defines directly in the code of the file you're debugging,
• Enable them from build/jam/UserBuildConfig, which can be used to set defines from the compiler command line.

A typical things would be to use SetConfigVar DEBUG in UserBuildConfig, and when build in debug mode, some sourcefiles will also enable tracing. I guess we could have a SetConfigVar TRACE that would enable the tracing independently of the debug.

I would prefer the no-op definition to be a do{} while(0) (you have added a semicolon in the ticket description, that should not be there). The reason is that we allow if/else conditions without braces, and if the trace macro expands to nothing, and is used in such an if/else, it can create subtle and annoying bugs.

The reason for tracing requiring a recompile is that it makes little sense to enable tracing globally (as could be the case in the boot menu with a simple "verbose mode" option). You would get so many traces that it would be very hard to find what you look for. In fact, some logs would be lost because there are some cases where we store things in a buffer with a fixed size. In the bootloader case, it is also not easy to extract these logs (basically you have to take screenshots of them from the boot menu log viewer, page by page), so keeping logs to a minimum (but a wise minimum) is actually best. This is changing however: as Haiku becomes closer to R1, our userbase is also getting less technical and less willing to recompile a bootloader to help investigate a bug.

So, to sum it up:

• It's a good idea to unify the tracing, preferrably to a form that doesn't require double parentheses and does not expand to blank when tracing is disabled
• I think it's also a good idea to enable tracing easily from UserBuildConfig when building Haiku, as we do for enabling DEBUG
• Runtime enable/disable is probably more complicated and deserves more discussion, especially for the bootloader where currently there isn't a place where you could configure it.

[X512]

#define TRACE(x) dprintf x

Is it possible to reduce code duplication and move it in some common header? Keep only module name for tracing.

[stellarpower]

Yes, I'm not too keen on those double-brackets, I can easily understand for older compilers where maybe variadic arguments weren't handled properly or support was minimal, and the preprocessor can be funny so it makes sense, what you see is what you get, but, they don't scan too well by eye and would make me a bit wary so I think if they could be made to fit a more normal invocation that would be more sensible. If we've got a well-defined target of GCC2 (am I right in thinking it's exactly the modified 2.95.3 version only that needs to be taken into account?) then can ensure that anything matches the proper preprocessor support included with that version and beyond.

Is there anywhere where an empty semicolon for the default definition wouldn't work? I was trying to think of some corner cases, but ended up going down the route that ultimately, if TRACE is always called as a statement and not an expression, then any invocation should be ended with a semicolon, and as such, an empty statement should work in any use site. For that matter actually is another thing about the double-parens, whether or not a semicolon is included in a macro's use site or not. I probably fall in the camp that it should be included in the macro body and the call should be left bare, again, when it's implicit that the macro is a statement or self-contained, because they stand out differently to function calls and my view is that I'd want the user to be as aware as possible tjhat it's a macro and thus to be mindful it's not a perfect system that may have some odd behaviour compared to things in the compiler-realm. Also, whilst less flexible, it keeps more in our realm of control. So for me,

TRACE("Hello, World!")
// more often than not, but not always, looks better than 
TRACE("Hello, World!");

I'm sure there are valid arguments against this though.

I'm also wondering, if an argument for the empty loop-based default was that it can be included in conditionals, loops, etc. without braces (and a good point to keep in mind, these are indeed very annoying bugs to find), would it make more sense to refactor the condition into the macro? I've given an example of this below.

One would hope the compiler could optimise away the entire segment of code if the body results in a no-op in assembly, but whilst I'd be confident GCC8 would optimise this away, something as old as GCC2, I'd wanna look into that before guessing, and also one couldn't exclude the possibility that in general, a conditional expression could have side-effects, so in a worst-case, this can't be optimised out unless the compiler is sure nothing would be modified before deciding whether or not to run the non-existent loop. I wouldn't expect this to be likely, it'd certainly be a bit messy in code, but am wondering if it would be simpler to make something like TRACE_IF to make it a little more explicit, removing the check on the condition at runtime completely, and making it kinda clear that the whole statement is onyl there for verbosity/debugging purposes - if tracing is enabled, then output if this condition is true. For any other use where something would be going on inside the condition of the if statement, and the trace is the only statement we need, so no braces, then fall back to normal and it should be implicit that this needs to happen regardless of the call to TRACE that follows:

TRACE_IF(rect->contains(point), "I haz your mouse, this won't mutate anything" 
  "important so we can compile it out if we don't want the trace"
  "The condition is only relevant to the trace")

if(partition->getNext()->type == FS::BEFS)
  TRACE("We found a possible partition, and we do wanna keep this in")

if (transaction.commit() != B_OK){
  TRACE("We have an error we aren't meant to have");
  // ... evidently more complex error handling so braces ...
  throw Something();
}

Then we might also say (and this could be overkill but an option)

TRACE_FOR(uint i = partitions.begin(); i != partitions.end(); i++, "name: %s \tsize: %d", i->name(), i->size())

Regarding separation into a separate header, I wonder if the below would be a good way of doing this, in line with the sample provided above, and using the same concept of a per-file macro globally enabling or disabling.

// Foo.cpp
#define _TRACE_ON_ TRACE_FOO 
#include <.../trace.h>
// The existing definition this file is getting is basically forwarded for enabling or disabling the global within this file
// Underscores or similar on _TRACE_ON_ to mark as implementation/internal, for neatness
...

// trace.h
#ifdef _TRACE_ON_
  #define TRACE(...) dprintf(__VA_ARGS__);
  #define TRACE_IF(cond, ...) if(cond) TRACE(__VA_ARGS__)
  // And possibly TRACE_FOR, TRACE_WHILE, DO_TRACE_WHILE for completeness ???
#else
  #define TRACE(...) ;
  #define TRACE_IF(...) ;
#endif

// Other stuff
...

(There may be problems with the expansion order in this, I haven't run it through but you get the idea)

---

Enable them from build/jam/UserBuildConfig, which can be used to set defines from the compiler command line.

This feels the right way to me. Certainly my take would be that manually editing the source file to uncomment things is undesireable for rebuilding with a different verbosity level, and doing stuff like this through Jam seems appropriate. I was trying to play with this last night actually, but I have some disk-intensive stuff going on in the background and building Haiku within Haiku on KVM is quite a slow process so I've not really toyed with Jam yet, but will try building in Ubuntu and see if this works faster. Then can flesh a few ideas out for sure. Given we have TRACE_ELF, TRACE_PARTITION, for example, what about something like the below?

SetTraceVar LOADER, PARTITION
# or perhaps
SetConfigVar TRACE LOADER, PARTITION

As mentioned, not sure on the Jam syntax yet as to what would work but what I'd seen so far seemed to describe writing functions of sorts. Some of these may want stratifying into e.g. BOOT_LOADER_PARTITION or similar, and again, probably a task for another day but if a different approach to gathering debug info like this involving larger changes were to be taken then might be a moot point.

---

You would get so many traces that it would be very hard to find what you look for.

Understood, I'm coming at this from a VM angle, where the console output can just be teed into a file or sth. The increased speed of debugging would definitely outweigh the inconvenience factor in this environment, but I get that any ability to enable or disable these at runtime, i.e. boot, would require a high level of granularity so only what's relevant were captured. Am seeing something like a tree in my head, allowing enabling tracing of various branches, but yeah, bit of a larger redesign.

This is also beyond the scope, but as an aside, I've quite liked seeing error unique identifiers before - nominally numbers (e.g. CXX1234) but could be a path or anything similar (/system/kernel/scheduler/foo/bar). I've largely seen these on Windows, although Illumos has a few too, especially in ZFS, but as a concept if ever there were the impetus to make any larger refactors, IMHO having an unambiguous reference to a single line in the source where the code diverged can be really useful for debugging, speeding up locating the source and also helping with getting relevant results searching online, diagnosing something with an end users/in the community, plus it helps with things like translation (less relevant in the bootloader, I know, but doesn't hurt as an extra) as a bonus. Just a thought. I regularly find when searching for something spat out under linux, my results include a lot of irrelevant pages with a similar message or on the same component. I kinda like the mapping that one error message/code corresponds to one specific fault and so should help in diagnosing the specific issue at hand, even if that involves working up a tree/stack. File not Found is a great example of something that could happen anywhere along this chain so it'd be good to pin it down at some point I reckon.

Sorry this is a bit of a wordy braindump, just hoped to get all my thoughts down on paper. Will look at the actual sources in a bit more detail shortly if I can get this built faster on metal and then see what's going on.

Have a great rest of the weekend!

[stellarpower]

Another thing I'm running into, I'm guessing the buildscript must be compiling the loader for both 32 and 64 bits, because I'm getting errors with the format strings as the datatype lengths change, which I realised does just seem to be going round in circles each time I change it - the arguments are say uint64, but whether this is %lu or %llu is varying each time. I can think of several ways of making this a bit more robust (and I'm guessing this could be helpful with ports to more architectures like ARM down the line), but the more compatible ways for GCC2 won't be as pretty as if we can use features in newer standards, so I will just mull that over for the time being.

[waddlesplash]

We already have the B_PRI macros for that very purpose.

[stellarpower]

Thanks, I planned to look into the platform headers tomorrow and see what we have, but these are obviously perfect. So, are there any objections if I just knock something up using these and a basic tidy to start off with, and push this to gerrit as a starting point?

[stellarpower]

Oh right, you meant

I'd been checked out on beta 2 when I closed off for the night, as I was wanting to get a stable release built to use as my build env, didn't realise there would be changes to this in the master already.

[pulkomandy]

Replying to X512:

#define TRACE(x) dprintf x

Is it possible to reduce code duplication and move it in some common header? Keep only module name for tracing.

Yes, that would be a good idea. There are some attempts for some components already: headers/private/media/MediaDebug.h, headers/private/bluetooth/btDebug.h, headers/os/support/Debug.h

They should be investigated to see if we can have more code in common between them.

[pulkomandy]

Replying to stellarpower:

I probably fall in the camp that it should be included in the macro body and the call should be left bare, again, when it's implicit that the macro is a statement or self-contained, because they stand out differently to function calls and my view is that I'd want the user to be as aware as possible tjhat it's a macro and thus to be mindful it's not a perfect system that may have some odd behaviour compared to things in the compiler-realm. Also, whilst less flexible, it keeps more in our realm of control.

I prefer that we write the macro in a way that it behaves like a function. The logic is to put the quirks and unusual things inside the macro, which is written only once, and then we can use it "normally" (exactly like a function call). It makes a lot more of the code easier to follow.

[stellarpower]

I see a couple of things with that, and I think consistency would be good from the outset if a refactor is in order:

1. functions will evaluate to an expression via the return value, except for void, so if the macro is to look like a function invocation, that could potentially conflict for macros that expand to a statement
2. If the semicolon is meant to be included at the call site, to mimic a function call, then the no-op definition wouldn't be required, as an empty semicolon would be okay for e.g. single-statement conditional bodies. I guess it does no harm but it seems clearer to me how it's meant to be used if it expands to nothing - void(0) seems somewhat obvious too, or I'd vote for defining a NO_OP macro to be explicit and then anything would work really.

Perhaps long-term, a move away from macros and more of the code towards a logger framework, for the parts of the OS that will be up and able to handle something like this at the time it's used, would be worth considering. In past projects, I've used a logger with log levels and colour-coding, and the macros as minimally as possible to get the file, function and line, in the main logger. Any further ones on top would be specific to the task at hand to reduce manual typing. Maybe even a logging and debugging kit, or as part of the support kit, that user applications could use as well as the system.

I was tidying up my VCS yesterday so will have a more detailed look at those files above and elsewhere in the OS and knock together a first draft to see how it sounds before pushing to Gerrit. Ideally push everything into the one file, such that it supports all the existing usage in one way or another, and then edit all the various sources to use this file for their debugging. Then can review the specifics of the one file in Gerrit or via commits later. os/support/debug.h looks a good start, so it seems to make most sense to refactor the rest into that. Might as well include some modularity for outputting the function, file/line, other preambles, etc. too. I like how brief the bluetooth one is as one option.