A better UE_LOG, part 3

←Part 2

Update: UE_LOGFMT fixes most of the issues with UE_LOG. These techniques can still be useful if you want something more comfortable to use.

I have also published a sample library that implements some of the ideas presented by this series.

So far, we’ve replaced the fragile, legacy nightmare of FString::Printf with a modern, type-safe formatter suited to your taste that can be used with UE_LOG and/or AddOnScreenDebugMessage as desired.

Other than this directly making anything debuggable like AActor* or your own custom types having a readable string representation without having to go through hacks such as Thing ? *Thing->GetName() : "null", it also completely eliminates entire classes of issues, such as wasting time on “debugging” why a number was “always 0.0” when it was an int formatted with %f and correct all along, crashing into a null %s, or forgetting yet again that %hs exists (this one seems to be popular).

If you opted to go with an operator<< or std::format-based solution, that also prevents a mismatch between parameter placeholders and parameters at compile-time. Nice! Welcome to the early 2000s in other programming languages.

Next steps

One frequently-sought feature of logging is the ability to completely eliminate it from a shipping build, that is, absolutely 0 runtime CPU cost, and no string fragments for the… curious players to data mine. This was lightly touched upon in Part 1, but as always, we can do better.

In Part 3, we’ll add two new features to our fledging logging system, namely the ability to eliminate anything from Shipping builds, not just debug prints, and finer-grained runtime control of what gets debugged with cvars.

I’ll be going through various ideas on how to do this, that will hopefully serve as inspiration for your own logging system that matches your needs and preferences.

CVars

CVars, or console variables, are global variables directly exposed to the Unreal console and changeable at runtime by any developer or tester.

Unreal also provides some functionality to disable these in Shipping, but we’ll go one step beyond and conditionally not compile them.

There are many ways to define a cvar from code, here’s one:

TAutoConsoleVariable<int> GMyCVar(TEXT("MyCVar"), 0 /*default value*/,
                                  TEXT("Description of this cvar"));

// Then read from it like so:
int Value = GMyCVar.GetValueOnAnyThread(); // or GetValueOnGameThread, etc.

Unless you care about thread synchronization for these cvars (like Unreal does for game thread ↔ rendering), it’s fine to read it like so; the worst that can happen is that your debugs are one tick late. Since you’ll be typing a console command manually, you won’t be tick accurate anyway.

There’s some amount of boilerplate in the code above, so let’s do what LOCTEXT_NAMESPACE does and define a “debug namespace”.

For simplicity, the following code blocks will assume that you have unity build OFF, which is NOT the default. If you want to make this work for unity builds, you’ll need to mangle a variable name based on the Name parameter or CURRENT_FILE_ID (generated by UHT, so it won’t work in all files) or add an extra variable name parameter to your debug namespace macro. namespace{} is also less useful, since it will apply to your entire unity translation unit.

Auto-cvar

With unity off, we can comfortably place a macro at the top of a .cpp file without it leaking to other files, no #undef required.

#define DEBUG_NAMESPACE(Name) namespace { \
    TAutoConsoleVariable<int> GThisFileDebugCVar(TEXT("MyProject." #Name), 0, \
    TEXT("Debug level for " #Name)); \
} static_assert(true)

The static_assert(true) is the second best thing we can do to enforce a semicolon, since do{...}while(0) doesn’t work at this level. In Shipping, #define this to just static_assert(true) to not have the cvar.

Near the top of a .cpp file, DEBUG_NAMESPACE(Example); will provide a cvar called MyProject.Example which will be available in GThisFileDebugCVar. Since this is all in an unnamed namespace, every .cpp can safely have its own copy of the global variable, like a static global variable would work in C.

A wrapper macro using it could look like this:

#define MY_WARNING(...) do { \
    if (GThisFileDebugCVar.GetValueOnAnyThread() != 0) \
        MyWarningImpl(__VA_ARGS__); \
} while(0)

Using if constexpr

The macro above covers debug prints, but there are many other debug things that you might want to do conditionally, such as drawing shapes. These calls can get very complex and ugly if shoehorned into one line of code, so ideally, we’d like if an entire code block could be conditionally compiled out, similar to checkCode, but hopefully better.

The if can be moved out of the logging macro:

// The cvar is interpreted as 0=fatal only, 1=fatal+warnings, 2+=everything
#if NO_LOGGING
#define IF_MY_TRACE_ENABLED() if constexpr (false)
#define IF_MY_WARNING_ENABLED() if constexpr (false)
#define IF_MY_FATAL_ENABLED() if constexpr (false)
#else
#define IF_MY_TRACE_ENABLED() if (GThisFileDebugCVar.GetValueOnAnyThread() >= 2)
#define IF_MY_WARNING_ENABLED() if (GThisFileDebugCVar.GetValueOnAnyThread() >= 1)
#define IF_MY_FATAL_ENABLED() if constexpr (true)
#endif

The empty () makes the macro look more like an if(), which makes clang-format behave if you use it with IfMacros. Otherwise, it’s not needed as far as C++ is concerned, and you can drop it.

These macros let you write if-looking code that will even cleanly work with else!

IF_MY_TRACE_ENABLED()
{
    FVector From = CallExpensiveThing();
    FVector To = CallLengthyOtherThing(With, Many, Parameters, Because, Why, Not);
    DrawDebugLine(GetWorld(), From, To, ...);
}

Due to the if constexpr, this entire code block will not exist in Shipping.

With these if macros, the logging ones no longer have to be conditionally #defined to (void)0 in Shipping, and can always be the same:

#define MY_WARNING(...) \
    do{IF_MY_WARNING_ENABLED() MyWarningImpl(__VA_ARGS__);}while(0)

operator<<

If you’re using an operator<<-based formatter, conditional compilation gets a little trickier. You can if constexpr away using it, but if you don’t want to indent every single usage and retain the ability to use one-liners, the next best thing is to define the formatter as a trivial no-op in shipping. This WILL evaluate its arguments, though, and you’ll be relying on the compiler to discard as many useless parts as it can. This could (and probably will) lead to strings leaking.

struct FShippingLog
{
    template<typename T>
    FShippingLog& operator<<(T&&){return *this;}
};

As a hybrid solution, you can macro the entire expression so that it can be erased in Shipping. Consider operator, or a concatenating variadic function from Part 1 and __VA_ARGS__ in this case, though.

#define MY_EXAMPLE_LOG(Expr) \
    do{FMyLogger()<<Expr;}while(0)
// Use as: MY_EXAMPLE_LOG("Player " << PlayerID << " has logged off");

Reducing debug spam

This section targets AddOnScreenDebugMessage specifically and doesn’t affect UE_LOG.

One feature of AddOnScreenDebugMessage is that you can provide a Key for your text item, which will make any subsequent pieces of text with the same key replace its existing counterpart. This is really useful for messages that are repeated on tick: you can even build a small debug visualizer with clever use of keys with none of the additional code that you would use for a real debug visualizer (which remains useful in its own right and out of scope for this article).

Adding a keyed variant to our debug macros is trivial, but once again, we can do a little better than that.

Assuming that we don’t really care about two debug namespaces being turned on at the same time, we can rely on __LINE__ to generate debug keys that will be unique in a single file.

This could be integrated into the macro:

// Spam this on tick, it will only display 1 line on screen:
#define MY_WARNING_UNIQUE(...) \
    do{MyWarningImpl(__LINE__, __VA_ARGS__);}while(0)
// with MyWarningImpl taking uint64 Key as its first parameter

Or, if you want a few if/else writes to target the same key, you can use a slightly different macro:

void AActress::Tick(float DeltaSeconds)
{
    Super::Tick(DeltaSeconds);

    constexpr uint64 DebugKey = __LINE__;
    if (bAngry)
        MY_TRACE_KEYED(DebugKey, "{0} is angry due to {1}", this, AngerReason);
    else if (bFrightened)
        MY_TRACE_KEYED(DebugKey, "{0} is frightened", this);
    else
        MY_TRACE_KEYED(DebugKey, "{0} is in normal state", this);
}

The __LINE__ boilerplate can be easily wrapped in yet another macro if you prefer:

#define MY_DEBUG_KEY(Name) constexpr uint64 Name = __LINE__
// Or, going all out with modern C++ if you prefer:
#define MY_DEBUG_KEY(Name) constexpr uint64 Name = \
    std::source_location::current().line()

Since these keys are 64-bit wide, you can comfortably use their higher bits for a per-file numeric identifier to eliminate any collisions. This can be defined in, e.g., DEBUG_NAMESPACE:

#define DEBUG_NAMESPACE(ID, Name) namespace \
{   constexpr uint64 GThisFileHighKey = ((uint64)ID) << 32; \
    /* original macro contents go here */ }
#define MY_DEBUG_KEY(Name) constexpr uint64 Name = GThisFileHighKey | __LINE__

Use this version as, e.g., DEBUG_NAMESPACE('STAT', Stats), or DEBUG_NAMESPACE('WEPN', Weapons). Note that it’s ' and not ".

If you really want to automate this to the brim, you can use a constexpr function to hash __FILE__ and hope for no collisions, abuse &__FILE__ being a valid pointer, or drop the constexpr and instead use something like:

// Define it somewhere with a relatively high starting value
extern std::atomic<int> GMyGlobalDebugCounter;
#define MY_DEBUG_KEY(Name) static const uint64 Name = ++GMyGlobalDebugCounter

This works for both the UNIQUE and KEYED flavors of the macros above. Place the variable inside the scope of the do-while for UNIQUE.

Updated: