Trace | Unreal Engine 4.27 Documentation | Epic Developer Community

Trace is a structured logging framework for tracing instrumentation events from a running process. The framework is designed to produce a stream of high-frequency traced events that is self-describing, easily consumed, and easily shared. The modules TraceLog and TraceAnalysis are the principal modules that constitute the framework. Unreal Insights is Trace's primary customer.

A Tour of Trace

(#Events)

Events

The complete system is composed of elements that form a pipeline from emission at runtime through to later consumption during analysis. The first element is a trace event, defined as follows:

	UE_TRACE_EVENT_BEGIN(LoggerName, EventName[, Flags])
		UE_TRACE_EVENT_FIELD(Type, FieldName)
	UE_TRACE_EVENT_END()

The EventName and FieldName parameters define the event and specify a field that the event should include. Events are grouped by "loggers", a semantic-only concept that helps to namespace events and ease subscription when analyzing a Trace stream. The optional Flags modify how events are traced.

Event Flag	Description
`NoSync`	By default, events are synchronized with events being traced on other threads. Events with the `NoSync` flag skip this synchronization; they're smaller and much faster to trace at the expense of being uncoordinated with other threads during analysis.

Field types can be the standard integer or floating-point primitives (such as uint32, float, and so on), as well as arrays and strings (see the Miscellaneous section for more information on the latter two). There is no support for nested structures/events as fields.

Events are usually defined at a global scope in a .cpp file. If you need to trace events from multiple translation units, you can use the UE_TRACE_EVENT_BEGIN_[EXTERN|DEFINE] pair.

Log an event at runtime like this:

	UE_TRACE_LOG(RainbowLogger, ZippyEvent, ItvChannel)
		<< ZippyEvent.Field0(Value0)
		<< ZippyEvent.Field1(BundleValue)
		<< ZippyEvent.Field2(Data, Num);
		<< ZippyEvent.Field3(String[, Num]);

Provided the Channel "ItvChannel" is enabled, this will add a 'RainbowLogger.ZippyEvent' event to the Trace stream. When assigning values to fields, ensure that they have no side effects. This is particularly important for side effects that involve tracing additional events, as a log site is not re-entrant.

There is no delta or run-length compression when tracing events. All defined fields are present, even if no data was written to them at a particular UE_TRACE_LOG call. A traced event is essentially analogous to a struct declared with #pragma pack(1). We recommend that developers think strategically to use these features to their fullest.

This system makes heavy use of macros both to hide a large amount of boilerplate, and so that definitions and log sites compile to nothing when Trace is off without requiring developers to use #if and #endif pairs throughout their code.

Channels

Channels in Trace help to constrain the stream of events based on the user's interest. This also improves CPU and memory usage efficiency by focusing on the most relevant data to what the user is trying to observe. You can define a Channel with the following syntax:

	UE_TRACE_CHANNEL(ItvChannel);

There is an EXTERN/DEFINE pair for more specific use cases. By default, Channels are disabled and must be explicitly opted into either via the -trace=itv command line option or the Trace::ToggleChannel() API.

Channels override the bitwise OR operator such that they can be combined with log sites to control the tracing of an event with multiple channels. A UE_TRACE_LOG(..., ItvChannel|BbcChannel) will only emit an event if both the "Itv" and "Bbc" channels are enabled.

Despite its appearance matching a bitwise OR operator, this operator's behavior partially resembles a logical AND operation.

Analysis

Now that we have defined a new event, enabled the related Channel or Channels, and added at least one log site, we can consume and analyze the events. We use the TraceAnalysis module to do this.

Analyzers derive from the IAnalyzer interface, and implement two primary methods:

OnAnalysisBegin to subscribe to events.
OnEvent to receive those subscriptions.

When analysis encounters an event that the analyzer has subscribed to, the analyzer's OnEvent method runs. Access to the event's data is available through FEventContext.EventData.Get* methods. This API reflects the self-describing nature of Trace streams; there is no binary or runtime-code dependency on interpreting Trace streams. Each received event also has associated thread information and (in some very rare circumstances) some timing information.

Running analysis on a Trace session involves describing the analyzers to use and feeding Trace data into the newly-created analysis session.

	struct : IInDataStream { ... } TraceData;
	FGeorgeAnalyzer GeorgeAnalyzer;
	FAnalysisContext Context;
	Context.AddAnalyzer(GeorgeAnalyzer);
	FAnalysisProcessor Processor = Context.Process(TraceData)
	Processor.Wait();

The predominant thread ID is not the same as the system thread ID, although the system ID is available. This removes the need for special handling to guard against cases where the OS might reuse a thread ID. As a result, you may encounter reuse of system IDs from one thread to the next, but the ID coming from Trace should be unique.

Recorder/Store

The TraceAnalysis module includes two components that together form a service for receiving, storing, and retrieving trace data. The implementation uses asynchronous IO so that it can scale easily to many clients (predominantly inbound trace data). Getting a store up and running is straightforward:

	FStoreService::FDesc Desc = {
		StoreDir, /* directory path on disk */
		RecorderPort, /* -1=off, 0=auto-assign */
		1, /* Number of IOCP threads */
	};
	auto Store = TUniquePtr<FStoreService>(FStoreService::Create(Desc));

The Recorder listens on a TCP port for incoming traces. When a runtime makes a connection to the recorder, the recorder creates a new trace with the store and begins relaying the received data into this new trace. Port 1980 is used by default but it is possible to ask the OS to assign an ephemeral port.

The Store's main role is to manage a directory of traces. It enables the creation of new traces, the enumeration of available traces, and the retrieval of a particular trace's data. There is a REST-like protocol built on top for communicating with a store. The protocol is CBOR-based for interoperability. FStoreClient is an implementation of this protocol;

	const auto* Store = GetWellKnownTraceStoreServer();
	if (auto Client = FStoreClient::Connect(Store->Ip, Store->Port))
	{
		for (int i = 0, n = Client.GetTraceCount(); i < n; ++i)
		{
			const auto* Info = Client.GetTraceInfo(i);
			/* ... */
		}
	}

The recorder-store component is optional. It is possible to ask the runtime to trace to a file. You can also write a recorder-like script in Python to receive trace data over a socket.

Runtime Details

Normal Events

When an event is traced at a UE_TRACE_LOG() site, the system writes a small header and the event's fields' values into a buffer local to the current thread. These thread local storage (TLS) buffers have a small, fixed size and link together to form a list. Trace's worker thread traverses the list of buffers, sending event data that has been committed (and is therefore complete and fully visible).

The benefit of using TLS is that it avoids conflicts between tracing threads. Order across threads is of significance for some event types and must be reconstructed when trace data is analyzed; for example, allocation and free events where memory addresses can be reused. For synchronization, Trace precedes each event with an atomically incrementing serial number, implemented as a 24-bit integer. Developers can use the NoSync flag when setting up an event to opt out of this feature; doing so avoids incurring the associated performance cost, but removes the ability to coordinate with other threads during analysis. Ideally, all event types should opt out of synchronization.

Worker Thread

A worker thread is used to collect traced events from the TLS and shared buffering schemes, compress and cache important events, handle command-control communications, and manage the destination IO (socket or file). This runs at a fixed interval and is a free thread (for example, not a job or task kicked as part of the engine's loop).

In some cases it may not be suitable to have trace events consumed and dispatched by a worker thread (for example, forking on Linux). Events can be opted-out of bUseWorkerThread during initialization which defaults to the value returned from FPlatformProcess::SupportsMultithreading(). When disabled it is the user's responsibility to update trace so that events are consumed with Trace::Update(). Note that lower frequency updates will result in higher memory use buffering traced events. By default this is all taken care of by Core's TraceAuxiliary.

Transport

Trace data travels in packets, known as the Transport. Each packet starts with an internal identifier indicating which thread the events came from, and a size. Packets are LZ4-compressed unless they are too small to benefit from compression.

These packets can be sent by the runtime to one of two places; to a file with the -tracefile= argument, or procedurally with the Trace::WriteTo function, or over a TCP socket (-tracehost=/Trace::SendTo()). The default TCP port is 1980.

There is a small block of handshake data sent right at the beginning of the trace stream along with a block of unstructured metadata.

Command-Control And Late-Connect

There are occasions when a tool such as Unreal Insights might need to control the trace system from which it is receiving data. When this happens, the runtime launches a rudimentary command / control server that mostly mirrors the Trace public API. There is a simple class in TraceAnalysis to facilitate communication:

	FControlClient ControlClient;
	if (ControlClient.Connect(Bungle.GetHostName())
	{
		ControlClient.SendToggleChannel(L"ItvChannel", true);
		ControlClient.SendWriteTo(L"X:/Rainbow.utrace");
	}

This simple server listens on port 1985. The port number can change if 1985 is not available. The port number is embedded in the metadata following the stream's handshake (accessible via TraceAnalysis' Recorder).

Because the port is a well-known value (at least by default), it is possible to connect to an instance that is already running and tell it to begin tracing data. This is known as late-connect.

(#Miscellaneous)

Miscellaneous

(#Arrays)

Arrays

You can add variable-length fields to a Trace event by defining them as arrays with unspecified sizes.

	UE_TRACE_EVENT_BEGIN(BoniLogger, BerkEvent)
		UE_TRACE_EVENT_FIELD(int32[], DruttField)
	UE_TRACE_EVENT_END()

Array-type fields have no storage cost in an event's payload if no data is set on the field. Array data follows the main event's data in the trace stream and is rejoined at analysis time. Tracing an array field only requires a pointer to the array data and an integer count indicating the number of elements in the array, like this:

	UE_TRACE_LOG(BoniLogger, BerkEvent, UpstairsChannel)
		<< BerkEvent.DruttField(IntPtr, IntNum);

Attachments

Initially, Trace did not support variable length fields. Attachments were introduced as opaque binary blobs that the system would append to events. We recommend using Array-type fields instead of attachments because they benefit from being structured and reflected at analysis time. Furthermore, attachment support incurs a cost that every logged event has to pay, whereas array-type fields do not. In the future, attachments may become opt-in to optimize away this overhead.

Strings

Trace events support string-type fields using the Trace::AnsiString or Trace::WideString types when declaring events' fields with UE_TRACE_EVENT_FIELD().

	UE_TRACE_EVENT_BEGIN(MyLogger, MyEvent)
		UE_TRACE_EVENT_FIELD(Trace::AnsiString, MyFieldA)
		UE_TRACE_EVENT_FIELD(Trace::WideString, MyFieldW)
	UE_TRACE_EVENT_END()

String-type fields are written much the same as primitive-type fields, with a few additional extras; ASCII-type fields will automatically truncate wide strings to 7-bit characters, and an optional string length can be given (preferable for performance if string length is already known).

	UE_TRACE_LOG(MyLogger, MyEvent)
		<< MyFieldA(AnAnsiBuffer, [, ExplicitStringLen])
		<< MyFieldW(WideName)

Limitations

The Trace system is global and can only perform one trace at a time. Because some tools available in the editor are now using the Trace system, the editor no longer automatically connects to and traces Unreal Insights when it is running. If you want to profile the editor, you must start it with the -tracehost=127.0.0.1 argument, or use trace.start in-editor (depending on a project's plugins).

Unreal Engine 4 Notes

Some events are only ever traced once. This is common for events that assign IDs to names, such as the names of CPU events. Unfortunately, this makes it impossible to stop tracing and restart at a later time, as contextual information from trace-once events is lost. A common indicator of this scenario are "unknown" CPU events or threads in Unreal Insights. The trace.stop command does not only stop tracing; it also disables all channels as a way to mitigate this limitation. Future versions of the engine will have a concept of "Important Events"; one-time events cached and resent when a trace connection is established, thus seamlessly supporting drop-in / drop-out profiling workflows.