Optimizing Unreal Engine : Part 4
Adding Task Data to Traces

In Part 3 we used Unreal Insights to sample performance data and display it like this:

width100

By default there is no simple way to connect the timing events on the Game Thread track, which create tasks, with the timing events on the other tracks which execute those tasks. We can see from the picture that the Foreground Worker #0 track has timing events from ExecuteForegroundTask() but that is all.

Unreal Tasks

Unreal divides work to be executed into tasks. Tasks are added to a task graph and then the scheduler allocates tasks to threads for execution. The Foreground Worker and Background Worker threads show in the Timing panel can be allocated tasks from the pool. The main game thread can also be allocated tasks.

Tasks have a priority, the scheduler will try to execute higher priorty task first.

Tasks can have prerequisites which are other tasks which must be completed before a task is started. Tasks can have child tasks. One task might divide its work into a number of other tasks which might need to be executed sequentially one after another, or might be executed all at the same time in parallel. Or there might be a mixture of both.

Enabling Task tracing

There are two ways to do this. It can be configured using the editor menus, in which case it works when running the program to be traced in the same process as the editor, or by specifying command line options, which works with standalone programs.

Enabling Task tracing in the Editor

From the Trace menu on the toolbar at the bottom of the editor window choose Channels and the tick the "Task" channel like this:

width50

This will make tracing collect task data but will only work when tracing in the same process as the editor, such as when the program is running in the "New Editor Window (PIE)" mode, but it won't work running in Standalone mode (at least it does not work in Unreal 5.4.2).

Enabling Task tracing from the Command Line

Here we want to run the project executable from the command line. The executables are found in the Binaries\Win64 directory of the project. The are named as follows:

Configuration Name For Spawn Project
Debug [ProjectName]-Win64-Debug.exe Spawn-Win64-Debug.exe
Debug Game [ProjectName]-Win64-DebugGame.exe Spawn-Win64-DebugGame.exe
Shipping [ProjectName]-Win64-Shipping.exe Spawn-Win64-Shipping.exe
Development [ProjectName].exe Spawn.exe

We want to launch the program on the command line with the same paramaters used when running in Standalone mode from the editor. We can get these parameters from the Sessions tab of the Unreal Insights window when we have opened any Standalone session:

width50

With these parameters we can assemble the command line and add "-trace=default,task" at the end of it to enable task tracing. The full command line is:

Binaries\Win64\Spawn.exe /Game/ThirdPerson/Maps/ThirdPersonMap -game -Multiprocess GameUserSettingsINI=PIEGameUserSettings0 -MultiprocessSaveConfig -forcepassthrough -messaging -SessionName="Play in Standalone Game" -windowed -WinX=-2036 -WinY=117 SAVEWINPOS=1 -ResX=1920 -ResY=1080 -trace=default,task

This command line only does tracing if the Session Browser is already running, so run it first and then run the command line.

Checking Task Tracing is working

A quick way to checking that task tracing did work is to open the trace file in Unreal Insights and right click the "Other" menu in the Timing view - you should see a Tasks submenu like this:

width50

What's New in the task view

With task tracing enabled a number of new features appear in the Unreal Insights UI:

Task Info on tooltips

When mousing over a timing event which is waiting on a task we see that in the tooltip:

width50

There might be many tasks - in the simple text project with ~1500 actors multiple tasks are generated for each actor, so there are thousands of tasks and we see tooltips like this:

width50

If the timing event is executing a task we see a tooltip identifying which task it is:

width50

The Task Overview track and task connections

To show this more clearly we create a new example class derived from AActor and place one instance of this class on the map. This actor has this code in the .cpp file:

namespace
{
	void Factorize(unsigned long long n) {

		TRACE_CPUPROFILER_EVENT_SCOPE(Factorize);

		for (unsigned long long i = 1; i * i <= n; ++i) {
			if (n % i == 0) {
				UE_LOG(LogTemp, Warning, TEXT("A factor of %ld is %ld"), n, i);
			}
		}
	}
}

The Factorize() function serves as something which takes some time to process so will be easier to see in the Timing view.

In addition we have this code in the BeginPlay() function of the actor:

void AFactorizeActor::BeginPlay()
{
	TRACE_CPUPROFILER_EVENT_SCOPE(AFactorizeActor::BeginPlay);
	Super::BeginPlay();
	unsigned long long LargeNumber = 99999993700377;

	UE::Tasks::Launch(
		UE_SOURCE_LOCATION,
		[LargeNumber] { Factorize(LargeNumber); }
	);
}

The UE::Tasks::Launch() function creates a task and adds it to the task graph scheduled to run asynchronously. In thie example we don't do anything with the return value from the function; we don't wait for it to complete, we just know it will run sometime in the future.

If we have the Task display options enabled like this:

width30

then we see a connection in the Timing view show us that the BeginPlay() method launched an asynchronous task:

width90

Note that if you know the name of the timing event you can search the Timing view by right-clicking and filling the Quick Find dialog with the name of the event, like this:

width80

The Find First button in the bottom left corner will then take you to the event.

In the above code we added a timing event TRACE_CPUPROFILER_EVENT_SCOPE(AFactorizeActor::BeginPlay) to make it clear that our BeginPlay() method launched the asynchronous task. Without this the BeginPlay() method would not appear in the Timing view (because only event scopes appear in the view, not all functions) and the connection would start in the UGameInstance::StartGameInstance() event like this:

width80

If we change the code which calls the Factorize() method to wait until it has completed, in addition to seeing a connection into the start of the task we see one at the end of the task as well. The code now stores the return value from the Launch() function and calls Wait() on it:

void AFactorizeActor::BeginPlay()
{
	TRACE_CPUPROFILER_EVENT_SCOPE(AFactorizeActor::BeginPlay);
	Super::BeginPlay();
	unsigned long long LargeNumber = 99999993700377;

	UE::Tasks::FTask Task = UE::Tasks::Launch(
		UE_SOURCE_LOCATION,
		[LargeNumber] { Factorize(LargeNumber); }
	);
	Task.Wait();
}

And on the Timing view it looks like this:

width90

If we change the code to launch two tasks and make one a prerequsite of the other, so that task 1 must complete before task 2, the code is:

void AFactorizeActor::BeginPlay()
{
	TRACE_CPUPROFILER_EVENT_SCOPE(AFactorizeActor::BeginPlay);

	Super::BeginPlay();

	unsigned long long LargeNumber = 99999993700377;

	UE::Tasks::FTask Task1 = UE::Tasks::Launch(
		UE_SOURCE_LOCATION,
		[LargeNumber] { Factorize(LargeNumber); }
	);

	UE::Tasks::FTask Task2 = UE::Tasks::Launch(
		UE_SOURCE_LOCATION,
		[LargeNumber] { Factorize(LargeNumber); },
		Task1 // Prerequisite
	);

	Task2.Wait();
}

And the Timing view shows the dependency like this:

width90

As a final example this code shows a nested task, where Task 2 is nested within Task 1, so Task 1 will be completed only when the code in Task 1 is complete and Task 2 is also complete:

void AFactorizeActor::BeginPlay()
{
	TRACE_CPUPROFILER_EVENT_SCOPE(AFactorizeActor::BeginPlay);

	Super::BeginPlay();

	unsigned long long LargeNumber = 99999993700377;

	UE::Tasks::FTask Task1 = UE::Tasks::Launch(
		UE_SOURCE_LOCATION,
		[LargeNumber] 
		{ 
			UE::Tasks::FTask Task2 = UE::Tasks::Launch(
				UE_SOURCE_LOCATION,
				[LargeNumber] { FactorizeTask2(LargeNumber); }
			);

			UE::Tasks::AddNested(Task2);

			FactorizeTask1(LargeNumber); 
		}
	);

	Task1.Wait();
}

This code produces these connections:

width90

By random chance the Task 1 has executed on the game thread which launched it. This example also uses two copied of the Factorize() function which have different values passed to the TRACE_CPUPROFILER_EVENT_SCOPE macro just to make the example clearer.

The Tasks View

When viewing a trace with task data if you select a task in the Timing view and then press Enter to select it, a table of task information is displayed in the Tasks view like this:

width90

In this view you can see various data about tasks and filter the view to show active tasks, tasked launched by the selected task and several other filters.

Reference

Task Graph Insights

Task System

Feedback

Please leave any feedback about this article here