Choose your operating system:
Windows
macOS
Linux
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 and 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
The complete system is composed of elements that form a pipeline from emission at runtime through to later consumption during analysis. The first of which is a trace event which are 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 should hopefully be self-explanatory. 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 Mark |
Description |
---|---|
NoSync |
By default events are synchronised with events being traced on other threads. Events marked "NoSync" skip this synchronisation; they're smaller and much faster to trace at the expense of being uncoordinated with other threads during analysis. |
Important |
Some events are only sent once and required to interpret later trace events (mapping a name to an integer identified for example). Such events are marked as "important" so they can be retained and later resent. This is for Unreal Engine 5. |
Field types can be the standard integer or floating-point primitives (for example, uint32, float, etc.), as well as arrays and strings (see below 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 events need to be traced from multiple translation units the
UE_TRACE_EVENT_BEGIN_[EXTERN|DEFINE]
pair can be used.
The logging of an event at runtime is done 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. Care should be taken when assigning values to fields such that they have no side effects, ones that trace additional events in particular as a log site is not reentrant.
There is no delta or run-length compression happening when events are traced. All defined fields are present too even if they were not written to at a particular
UE_TRACE_LOG()
call. A traced event is essentially analogous to a
#pragma pack(1)
-declared struct. It is advisable to think strategically as to how those bits are used to their fullest.
Side note; The thought process behind the use of a macro-soup was two fold; to hide a lot of boilerplate behind simple where details like offsets are known at compile time, and secondly so that definitions and log sites compile to nothing when Trace is off without littering
#if/end
everywhere.
Channels
In order to constrain the stream of events to what the user is interested in there is the concept of channels. This helps to focus CPU and memory resources on what is important to the observations being made. Channels are easily defined like this:
UE_TRACE_CHANNEL(ItvChannel);
There is a
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. The astute reader will notice that this is, somewhat confusingly, the opposite of what one might expect from a bitwise OR.
Analysis
Now that we have defined a new event, added enabled the channel(s) they're keyed off, and added a log site or two, we will want to consume and analyze the events. This is done using the TraceAnalysis module.
Analyzers are created by deriving from
IAnalyzer
and implementing two primary methods; the
OnAnalysisBegin()
to subscribe to events, and
OnEvent()
to receive those subscriptions.
When analysis encounters an event that the analyzer has subscribed to the analyzer's
OnEvent()
method is called. Access to the event's data is done via
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 is straightforward by describing the analyzers to use and feeding the created analysis session the trace data.
struct : IInDataStream { ... } TraceData;
FGeorgeAnalyzer GeorgeAnalyzer;
FAnalysisContext Context;
Context.AddAnalyzer(GeorgeAnalyzer);
FAnalysisProcessor Processor = Context.Process(TraceData)
Processor.Wait();
The predominant thread ID is not quite the same as the system thread ID, although the system ID is available. This is to better guard against handling in cases where the OS might reuse a thread ID. So expect that the system ID will get reused from one thread to the next. Trace's ID will not, or at least they are considerably less likely to do so.
Recorder/Store
-
async-io
-
optional
Runtime Details
Normal Events
-
tls
-
fixed size buffers, linked list
-
-
synchronised, nosync opt-out
Important Events
This is for Unreal Engine 5.
-
shared buffer
-
collected by worker thread
-
cached, lz4 compressed
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 (i.e. forking on Linux). This 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. Ordinarily this is all taken care of by Core's TraceAuxiliary.
Transport
-
wire, port 1980
-
file
Command-control/Late-connect
-
command/control on port 1985
Miscellaneous
Arrays
Attachments
In the early days of trace there was no support for variable length fields. A concept of attachments was introduced where opaque binary blobs could be appended to traced events. The use of attachments is discouraged — array-type fields should be used instead which benefit from being structured and reflected at analysis time. Furthermore, attachment support incurs a cost that every logged event has to pay so it is possible that it may be changed to be an opt-in component in the future 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 trace to one thing at once. Because some tools available in the editor are now using the trace system, the editor no longer automatically connects to and traces to a running Unreal Insights. If you wish to profile the editor the
-tracehost=127.0.0.1
argument must be given when starting the editor (or possibly the
trace.start
in-editor depending on a project's plugins).
Unreal Engine 4 Notes
Some of the events traced are one-shots — they are only ever traced once. This is common to assign IDs to names, CPU events' names for example. Unfortunately this makes it impossible to stop tracing and later restart it 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
is in fact not really a stop but a disablement of channels as a mitigation to this limitation. Future versions of the engine have a concept of "Important Events". One-time events are cached and resent them when a trace connection is established, thus seamlessly supporting drop-in/out profiling workflows.