Trace

Trace is a structured logging framework for tracing instrumentation events from a running process for Unreal Insights.

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.

Select Skin
Light
Dark
언리얼 엔진 문서의 미래를 함께 만들어주세요! 더 나은 서비스를 제공할 수 있도록 문서 사용에 대한 피드백을 주세요.
설문조사에 참여해 주세요
건너뛰기

새로운 언리얼 엔진 4 문서 사이트에 오신 것을 환영합니다!

문서 사이트에 대한 의견을 모을 수 있는 피드백 시스템을 포함해서 여러가지 새로운 기능을 준비하고 있습니다. 아래 Documentation Feedback 포럼(영문) 또는 언리얼 엔진 네이버 공식 카페(한글) 중 편하신 곳에 의견이나 문제점을 알려 주세요.

새 시스템이 준비되면 알려 드리겠습니다.

네이버 카페
공식 포럼