IN THIS ARTICLE

Google Trace Event Format Metrics

Learn the JSON Trace Event Logger

The Trace Event Logger in Open 3D Engine (O3DE) provides the ability to log metrics compatible with the Google Trace Event Format .
The implementation is a limited subset of Google Trace format and only events types relevant for O3DE needs at the time have been implemented.

O3DE currently supports the following set of events:

Events	Description	Phase Markers
Duration	Provides a way to measure duration within a single thread. Duration events can be nested	B (begin), E(end)
Complete	Combines the Begin and End of a Duration Event into a single event.	X
Instant	Corresponds to an event that occurs at a point in time. It has no duration associated with it. For example an out of memory event might be logged as an “instant” event. An “s” scope parameter is available to provide the scope of the event. Valid scopes are “g” (global), “p” (process), “t” (thread). If no scope is provided it is assumed to be a thread scope event.	i
Counter	Provides a way to track multiple values over time. When an “id” is provided , it combines with the “name” field to form the counter name.	C
Async	Provides a way to measure asynchronous operations across multiple threads. This event may be used to output the frame time or network I/O stastistics. Events with the same “cat”(category) and “id” field values are considered to be from the same event tree. The “scope” argument is an optional string used to avoid id conflicts. When specified the “cat”, “id” and “scope” will be used to identify an event from the same event tree.	b (nestable start), n (nestable instant), e (nestable end)

The following set of events are not provided by the JSON Trace Event Logger in O3DE currently:

Events	Description	Phase Markers
Flow	Similar to an asynchronous event, except each thread can have a duration associated with it.	s (start), t (step), f (end)
Object	Provides a way to build complex structures in events. Normally used to track when an object instance is created(“N”) and destroyed(“D”) in-memory. The “O” object can be used to associate “snapshot” data with an object, which can be anything that is storable in an JSON object.	N (created), O (snapshot), D (destroyed)
Metadata	Allows associating associating custom data with one of the supported fields(“process_name”, “process_labels”, “process_sort_index”, “thread_name”, “thread_sort_index”). The “args” argument is used to specify that metadata.	M
Memory Dump	Corresponds to a memory dump of either the global OS memory or the running application process memory. The “V” phase is used for a global memory information such as system ram. The “v” phase is used for process statistics.	V (global), v (process)
Mark	(Not Needed for O3DE) Used for logging events when a web navigation timing API is used.	R
Clock Sync	(Not needed for O3DE) Used to perform sync clock synchronization among multiple event logs.	c
Context	Used to mark a sequence of events belonging to a context.	,

More information about each of these events can be found in the Event Descriptions section of the Google Trace Event Format document.

Event Logger API documentation

Detailed doxygen comments on the available interfaces for the Event Logger API is located within the header API files located within the Code/Framework/AzCore/AzCore/Metrics directory.
Within that directory the following are the most important files to examine to learn about the API:

File	Description
IEventLogger.h	Provides the interface for recording event data via using an Event Description. Structures definitions for specific Event Phase Types are also described in this file.
IEventLoggerFactory.h	Provides the interface for registration of Event Loggers with a global registrar. This can be used to access Event Loggers accross shared library boundaries or access an EventLogger without the needing to store it explicitly.
EventLoggerUtils.h	Contains utility functions to simplify recording of events using the Event Logger API. The functions can both query and Event Logger from the Event Logger Factory and record and event in a single call. This file also provides the simplified `AZ::Metrics::RecordEvent` api which can accept any type of supported Event Phase Type.

How to use the JSON Trace Event Logger

This section describes how to register to create an Event Factory and register it with a global interface, create an Event Logger, provide the Event Logger stream to record data output and to record sample metrics. By the end you will be able to view collected metrics in a Chromium-based browser.

The full source code in this section is available in the JsonTraceEventLogger Unit Tests and EventLoggerUtils Unit Tests

Create EventLogger Factory and register it as a global instance

//! The logger is created from a compile time hash of the "SampleEventLogger" string using the FNV-1a 64 bit algorithm
constexpr AZ::Metrics::EventLoggerId SampleLoggerId{ static_cast<AZ::u32>(AZStd::hash<AZStd::string_view>{}("SampleEventLogger")) };

//! This is a google test fixture class used for illustration purposes of recording using the Event Logger API
class JsonTraceEventLoggerTest
    : public ::UnitTest::ScopedAllocatorSetupFixture
{
public:
    JsonTraceEventLoggerTest()
    {
        // Create an event logger factory
        m_eventLoggerFactory = AZStd::make_unique<AZ::Metrics::EventLoggerFactoryImpl>();

        // Register it as a global instance
        AZ::Metrics::EventLoggerFactory::Register(m_eventLoggerFactory.get());

        //...
    }

protected:
    AZStd::string m_metricsOutput;
    AZStd::unique_ptr<AZ::Metrics::IEventLoggerFactory> m_eventLoggerFactory;
};

Create a JSON Trace Event Logger that writes to an in-memory string and register it with the Event Logger Factory

    JsonTraceEventLoggerTest()
    {
        //... Previous logic to register event factory

        // Create an byte container stream that allows event logger output to be logged in-memory
        auto metricsStream = AZStd::make_unique<AZ::IO::ByteContainerStream<AZStd::string>>(&m_metricsOutput);
        // Create the trace event logger that logs to the Google Trace Event format
        auto eventLogger = AZStd::make_unique<AZ::Metrics::JsonTraceEventLogger>(AZStd::move(metricsStream));

        // Register the Google Trace Event Logger with the Event Logger Factory
        auto registerOutcome = m_eventLoggerFactory->RegisterEventLogger(SampleLoggerId, AZStd::move(eventLogger));
        // Validate that the registration of the factory succeeded
        EXPECT_TRUE(registerOutcome);
    }

Generate duration trace metrics and record them to the Event Logger

The following block of code shows how to record a string and a number using the event logger:

{
    constexpr AZStd::string_view eventString = "Hello world";
    constexpr AZ::s64 eventInt64 = -2;


    // Populate the "args" container to associate with each events "args" field
    AZ::Metrics::EventObjectStorage argsContainer;
    argsContainer.emplace_back("string", eventString);
    argsContainer.emplace_back("int64_t", eventInt64);

    {
        // Record Duration Begin and End Events
        AZ::Metrics::DurationArgs durationArgs;
        durationArgs.m_name = "Duration Event";
        durationArgs.m_cat = "Test";
        durationArgs.m_args = argsContainer;
        durationArgs.m_id = "0";
        auto resultOutcome = AZ::Metrics::RecordEvent(SampleLoggerId, AZ::Metrics::EventPhase::DurationBegin, durationArgs);
        EXPECT_TRUE(resultOutcome);

        // Update the string value to "GoodbyeWorld and the integer value to "400"
        argsContainer[0].m_value = "Goodbye world";
        argsContainer[1]= 400;

        // Re-update the durationArgs argument container to have the latetst argument values
        durationArgs.m_args = argsContainer;

        resultOutcome = AZ::Metrics::RecordEvent(SampleLoggerId, AZ::Metrics::EventPhase::DurationEnd, durationArgs);
        EXPECT_TRUE(resultOutcome);
    }
}

Flush the metrics string to a text file

At this point the the metrics can be logged to stdout, sent over the network or written to a JSON file on disk.
The example will write the metrics a file named with the prefix “sample_metrics_” with the current time formatted using the ISO 8601 standard. An example filename is sample_metrics_2023-01-01T120000.123456.json.

{
    constexpr AZ::IO::OpenMode openMode = AZ::IO::OpenMode::ModeWrite;
    auto metricsFilepath = AZ::IO::FixedMaxPath(AZ::Utils::GetProjectUserPath()) / "metrics/sample_metrics_";
    //! Append a ISO 8601 timestamp to the metrics filename to make it unique across runs
    AZ::Date::Iso8601TimestampString currentUtcTimestamp;
    AZ::Date::GetFilenameCompatibleFormatNowWithMicroseconds(currentUtcTimestamp)
    metricsFilepath.Native() += currentUtcTimestamp;
    metricsFilepath.Native() += ".json";

    AZ::IO::SystemFileStream systemFileStream(metricsFilepath.c_str(), openMode);
    // The metrics were written to the ByteContainerStream which was backed by the @m_metricsOutput member
    systemFileStream.Write(m_metricsOutput.size(), m_metricsOutput.c_str());
}

Event Metrics JSON output

The following example shows logging of metrics using multithreads, to illustrate that the thread ID is associated with each metric.

[
  {"name":"Duration Event","id":"0","cat":"Test","ph":"B","ts":1664329933375019,"pid":31760,"tid":36036,"args":{"string":"Hello world","int64_t":-2}},
  {"name":"Duration Event","id":"0","cat":"Test","ph":"E","ts":1664329933375119,"pid":31760,"tid":36036,"args":{"string":"Goodbye world","int64_t":400}}
]

Viewing the event metrics

Using a Cchromium-based browser about:tracing page or the trace-viewer provided by the catapult repo , the recorded metrics can be visualized based on their event types.

about::tracing