Debugging Tips for Unreal

Summary

There are a variety of methods that can be taken to aid in debugging an Unreal project. Unlike other traditional systems, games are realtime systems and this presents unique challenges for debugging. Although you can attach the debugger through Visual Studio or your favorite IDE, by stopping the world, we fundamentally change what is happening in the system. Unless you are troubleshooting a common crash and want to examine variables in the debugger or quickly verify some data, we need a less obtrusive way of verifying what is happening in our game.

TL;DR

The Visual Logger is the best debugging tool I have found so far. It combines the best from all the techniques and its downside of logging too much in a larger game can be overcome with a little bit of wrapper code.

Console Logs

This is a simplest diagnostic tool where you can print out text showing progress in your code. Simplicity and searchability are its main advantages and also you can look back later at all the details gathered and search through it in your favorite text editor. Its disadvantage is games are a visual medium and certain gameplay bugs will be hard to troubleshoot simply from text output.

As an example, if you want to see when the BeginPlay function is invoked on a AActor derived class, you could place the following macro in your code:

UE_LOG(LogTemp, Log, TEXT("%s: BeginPlay"), *GetName());

This output will print both to the editor console and to a log file in Saved/Logs.

It is a common practice to use macros for logging in C++. These have the advantage of being able to “compile-out” logging in certain build configurations or if the log level is more verbose than you want for that configuration. Additionally, macros allow potentially expensive logging format parameter evaluation to be prevented in the event that the logging is present but the verbosity level is not turned on for the current running game. You only pay the penalty of a branch evaluation in that case checking the current logging level for the category.

LogTemp is a Log Category but should only be used temporarily (as the name suggests) for quick one-off troubleshooting. You will quickly want to create your own log categories for the modules in your game. A general best practice to have one category per Unreal source module in your game. For info about the module system, this tutorial is really great. It definitely made things clear for me.

Since logging is an implementation detail of your module, you will generally want to create a header in the private folder of your module project. This is what I use, which is generated from a python skaffolding tool I wrote to auto-generate the boilerplate files for creating modules. I hope to share this tool in the future.

#pragma once
#include "CoreMinimal.h"
#if NO_LOGGING
    DECLARE_LOG_CATEGORY_EXTERN(LogMyModuleName, NoLogging, NoLogging);
#elif UE_BUILD_SHIPPING
    DECLARE_LOG_CATEGORY_EXTERN(LogMyModuleName, Warning, Warning);
#else
    DECLARE_LOG_CATEGORY_EXTERN(LogMyModuleName, Display, All);
#endif

In your module cpp file you should then have a single definition macro for your category

DEFINE_LOG_CATEGORY(LogMyModuleName);

Technically NO_LOGGING is defined for shipping builds so the second case is never realized and also that operates at a deeper fundamental level in each and every UE_LOG macro expansion, but I put this in here in case I wanted to change that in the future. The second parameter is the max logging level that can be enabled at runtime via the Config/DefaultEngine.ini file in your project. The third parameter is the max level that can be compiled into the source (assuming NO_LOGGING is not defined. Obviously, if the level is disabled at the compilation level it won’t be able to be enabled at runtime, so the third parameter should always be as or more verbose than the second.

A good reference for the console logging can be found here

Gameplay Debugger

A second debugging technique is the Gameplay Debugger

I have found this useful for quick AI Visualization, but in my opinion to expand on it requires too much boilerplate to be useful, and I can only see the visualization live and cannot replay it back later.

Console Variables

These can be used for “debugging shortcuts” for designers and to enable additional on-screen diagnostics. Further down in this blog, I piggy back on this to solve what I think is a major deficiency in another logging technique out of the box. For this I use TAutoConsoleVariable defined in a file-scoped variable. I then put them behind a preprocessor guard so they are compiled out of shipping builds.

namespace
{
#if VG_DEBUG_ENABLED
TAutoConsoleVariable<int32> CVarForceAIDirection(
  TEXT("ai.traffic.force-direction"),
  -1,
  TEXT("Forces traffic to always go in indicated direction (if available): -1=Off, 0=Straight, 1=Right, 2=Left"),
  ECVF_Scalability | ECVF_RenderThreadSafe);
#endif
}

Later on in the code during gameplay, we can read the current state of this variable and then use it to affect the runtime behiavor.

// ....
#if VG_DEBUG_ENABLED
const int32 ForceDirectionValue = CVarForceAIDirection.GetValueOnGameThread();
// ...
#endif
// ...

Console variables are described in depth in Epic’s documentation

Debug HUDs

This satisfies the same space as the Gameplay Debugger but in a simpler way. We can subclass AHud to create a ADebugHud where we can print on screen information or draw shapes in the world using the Canvas API. The advantage of this approach is we can separate our debugging code from our production code and not clutter it. The great Udemy Pro Unreal Engine Game Coding Coursecovers this technique. I highly recommend this course for anyone building a vehicle-heavy game in Unreal Engine. It does however use UE4, but the core principles still apply. See this post on GameDev.TV for additional vehicle tutorial content.

Visual Logger

This is something that escaped me for a long time but now that I’ve discovered it I don’t know how I lived without it :) Epic’s documentation is pretty good on this one and additionally this blog and GDC talk are great supplemental resources.

The huge advantage of this technique is it allows you to both visually see what’s happening live AND replay it back later through a saved log file in the map in which it was recorded. You can even combine a traditional UE_LOG statement with one that prints in the correct context in the visual logger via UE_VLOG_UELOG convenience macro.

Keep in mind though if the visual logger is disabled in the build, the UE_LOG statement will also not execute. These will likely be enabled hand in hand in the same build but something to keep in mind. Just like with UE_LOG it will be compiled out completely in builds where visual logging is not enabled. Keep in mind though by default all logging categories and verbosity levels will be logged when visual logging is recording, which is something I addressed. If logging is not recording, though, this will only have the almost surely neglible impact on performance by testing the visual logger flag and then executing the regular UE_LOG macro. The code maintenance and troubleshooting benefits greatly outweigh the possible performance impacts here, and in shipping builds it won’t be present at all.

I created some useful extensions to the core FVisualLogger functionality that I hope to share more completely in the future and will describe them briefly below and share a few snippets.

Exposing to non-editor development builds

The core FVisualLogger class does not have any key bindings out of the box to turn visual logging on/off in non-editor builds or be able to auto save the logging info to file at the end of the session, which is needed for testers as helpful info for bug reports. To address the recording deficiencies I created a visual logging extension class that adds additional member function wrappers around the FVisualLogger c++ functions.

// In UVisualLoggerEx source
void UVisualLoggerEx::Save()
{
    auto& VisualLogger = FVisualLogger::Get();
    if (!IsLoggingToFile())
    {
        return;
    }
    VisualLogger.Flush();
}
void UVisualLoggerEx::EnableLogToFile(bool bLogToFile)
{
    auto& VisualLogger = FVisualLogger::Get();
    if (bLogToFile == VisualLogger.IsRecordingToFile())
    {
        return;
    }
    if (bLogToFile)
    {
        VisualLogger.SetIsRecordingToFile(true);
    }
    else
    {
        VisualLogger.DiscardRecordingToFile();
    }
}
bool UVisualLoggerEx::IsLoggingToFile()
{
    return FVisualLogger::Get().IsRecordingToFile();
}
void UVisualLoggerEx::ResetData(UWorld* WorldContext)
{
    auto& VisualLogger = FVisualLogger::Get();
    // Discard any recording that is being done to file, cleanup in memory data structure, and restart file recording if it is already running
    if (VisualLogger.IsRecordingToFile())
    {
        VisualLogger.DiscardRecordingToFile();
        VisualLogger.Cleanup(WorldContext);
        // start the recording again
        VisualLogger.SetIsRecordingToFile(true);
    }
    else
    {
        VisualLogger.Cleanup(WorldContext);
    }
}

The core FVisualLogger class does have full support for category, level, and even object level filtering but it is not exposed to blueprints or console variables where it will be most useful to toggle. To address the category filter deficiencies I created a visual logging extension class that adds additional member function wrappers around the FVisualLogger c++ functions and also exposed some FAutoConsoleCommand console exec functions to allow changing the recording log level. This simply wraps the blueprint-exposed function so that the same functionality can be invoked through the console. The main reason to do this is for performance. You will quickly find that if you use the Visual Logger heavily it will crawl with a lot of logging since it is logging everything all the time. The file sizes will also be massive and likely cause an out of memory for a long record session. If you know what you need to troubleshoot you can set it to only record that info much like the filtering capability present in the console logging system.

// In UVisualLoggerEx source
void UVisualLoggerEx::ToggleAllowAllCategory(bool bAllowAll)
{
  auto& VisualLogger = FVisualLogger::Get();
  VisualLogger.BlockAllCategories(!bAllowAll);
}
void UVisualLoggerEx::AddAllowedCategory(FName CategoryName)
{
  auto& VisualLogger = FVisualLogger::Get();
  VisualLogger.AddCategoryToAllowList(CategoryName);
}
void UVisualLoggerEx::ResetAllowedCategories()
{
  auto& VisualLogger = FVisualLogger::Get();
  VisualLogger.ClearCategoryAllowList();
}
void UVisualLoggerEx::AddAllowedClass(UClass* Class)
{
  if (!Class)
  {
    return;
  }
  auto& VisualLogger = FVisualLogger::Get();
  VisualLogger.AddClassToAllowList(*Class);
}
namespace
{
  void VLogExFilterCategoriesConsoleCommand(const TArray<FString>& Args);
  void VLogExAllowCategoryConsoleCommand(const TArray<FString>& Args);
  void VLogExResetCategoriesConsoleCommand(const TArray<FString>& Args);
  void VLogExAllowClassConsoleCommand(const TArray<FString>& Args);
   FAutoConsoleCommand CVlogExFilterCategories(
     TEXT("vlog.filterCategories"),
     TEXT("Toggles visual log category filtering on/off"),
     FConsoleCommandWithArgsDelegate::CreateStatic(VLogExFilterCategoriesConsoleCommand), ECVF_Default
   );
   FAutoConsoleCommand CVlogExAllowCategory(
     TEXT("vlog.allowCategory"),
     TEXT("Adds the specified visual log category name"),
     FConsoleCommandWithArgsDelegate::CreateStatic(VLogExAllowCategoryConsoleCommand), ECVF_Default
   );
   FAutoConsoleCommand CVlogExResetCategories(
     TEXT("vlog.resetCategories"),
     TEXT("Removes any added visual log allow categories"),
     FConsoleCommandWithArgsDelegate::CreateStatic(VLogExResetCategoriesConsoleCommand), ECVF_Default
   );
   FAutoConsoleCommand CVlogExAllowClass(
     TEXT("vlog.allowClass"),
     TEXT("Adds the specified log owner or object owner class or those derived from them to the allowed visual logging\nWARNING: Once this is invoked it can only be undone with an editor restart\ne.g. vlog.allowClass /Script/MyModule.MyActorClass"),
     FConsoleCommandWithArgsDelegate::CreateStatic(VLogExAllowClassConsoleCommand), ECVF_Default
   );
   void VLogExFilterCategoriesConsoleCommand(const TArray<FString>& Args)
   {
      if (Args.IsEmpty())
      {
         return;
      }
      UVisualLoggerEx::ToggleAllowAllCategory(!Args[0].ToBool());
   }
   void VLogExAllowCategoryConsoleCommand(const TArray<FString>& Args)
   {
      if (Args.IsEmpty())
      {
         return;
      }
      UVisualLoggerEx::AddAllowedCategory(FName(Args[0]));
    }
    void VLogExResetCategoriesConsoleCommand(const TArray<FString>& Args)
    {
       UVisualLoggerEx::ResetAllowedCategories();
    }
    void VLogExAllowClassConsoleCommand(const TArray<FString>& Args)
    {
       if (Args.IsEmpty())
       {
          return;
       }
       const FString& ClassName = Args[0];
       // Find the UClass by name
       UClass* Class = Cast<UClass>(StaticFindObject(UClass::StaticClass(), FTopLevelAssetPath(ClassName), false));
       UVisualLoggerEx::AddAllowedClass(Class);
    }
}

Unit Testing

Although this post is focused on debugging techniques, unit tests are a great way of adding automation to ensure code quality and verification of functionality. With real-time systems, it is a challenge to create comprehensive automated tests, but these are very useful for internal headless systems or data structures. This post I made on GameDev.TV forums provides some sample code and additional links showing the approach. This is a snippet from one of my other games AI Guys.