blob: e16a0d76a076783c737a3805bd2ed38c8d202767 [file] [log] [blame] [view]
# Trace Logging Library Usage
The idea behind Trace Logging is that we can choose to trace a function and
then, with minimal additional code, determine how long function execution ran
for, whether the function was successful, and connect all of this information to
any existing informational logs. The below provides information about how this
can be achieved with OSP's TraceLogging Infrastructure.
## Compilation
By default, TraceLogging is enabled as part of the build.
To disable TraceLogging, include flag `--args="enable_trace_logging=false"`
when calling `gn gen` as part of building this library.
## Imports
To use TraceLogging, import the following header file:
```c++
#include "util/trace_logging.h"
```
This file will import all other Trace Logging dependencies.
## Trace IDs
When a Trace Log is created, a new unsigned integer is associated with this
specific trace, which will going forward be referred to as a Trace ID.
Associating a Trace ID has the following benefits:
* The same Trace ID can be associated with all Informational Logs generated
during this traced method’s execution. This will allow for all informational
logs to easily be associated with a method execution, so that if an unexpected
failure occurs or edge case pops up we will have additional information useful
in debugging this issue and can more easily determine the state of the system
leading to this issue.
* If another Trace Log is created during the execution of this first traced
method, we will have a hierarchy of Trace IDs. This will allow us to easily
create an execution tree (through trivial scripting, preexisting tool, or
database operations) to get a better view of how execution is proceeding.
Together, the IDs associated with these calls form a Trace ID Hierarchy. The
Hierarchy has the following format:
* *Current Trace ID*: The ID of the function currently being traced.
* *Parent Trace ID*: The ID of the function which was being traced when this
Trace was initiated.
* *Root Trace ID*: The ID of the first traced function under which this the
current Trace was called.
As an example:
``` c++
public void DoThings() {
TRACE_SCOPED(category, "outside");
{
TRACE_SCOPED(category, "middle");
{
TRACE_SCOPED(category, "inside");
}
}
}
```
This could result in the following Trace ID Information:
| NAME | ROOT ID | PARENT ID | TRACE ID | RESULT |
|---------|----------|------------|-----------|---------|
| outside | 100 | 0 | 100 | success |
| middle | 100 | 100 | 101 | success |
| inside | 100 | 101 | 102 | success |
Note that, prior to any trace calls, the Trace ID is considered to be 0x0 by
convention.
## Trace Results
The "result" of a trace is meant to indicate whether the traced function
completed successfully or not. Results are handled differently for synchronous
and asynchronous traces.
For scoped traces, the trace is by default assumed to be successful. If an error
state is desired, this should be set using `TRACE_SET_RESULT(result)` where
result is some Error::Code enum value.
For asynchronous calls, the result must be set as part of the `TRACE_ASYNC_END`
call. As with scoped traces, the result must be some Error::Code enum value.
## Tracing Functions
All of the below functions rely on the Platform Layer's IsTraceLoggingEnabled()
function. When logging is disabled, either for the specific category of trace
logging which the Macro specifies or for TraceCategory::Any in all other cases,
the below functions will be treated as a NoOp.
### Synchronous Tracing
#### Tracing the Current Scope
```c++
TRACE_SCOPED(category, name)
TRACE_SCOPED(category, name, traceId, parentId, rootId)
TRACE_SCOPED(category, name, traceIdHierarchy)
```
If logging is enabled for the provided |category|, trace the current scope. The scope
should encompass the operation described by |name|. The latter two uses of this macro are
for manually providing the trace ID hierarchy; the first auto-generates a new trace ID for
this scope and sets its parent trace ID to that of the encompassing scope (if any).
#### Tracing the Current Scope (with default signatures)
```c++
TRACE_DEFAULT_SCOPED(category)
TRACE_DEFAULT_SCOPED(category, traceId, parentId, rootId)
TRACE_DEFAULT_SCOPED(category, traceIdHierarchy)
```
Same as `TRACE_SCOPED()`, but use the current function/method signature as the operation
name.
#### Tracing with Arguments
Both synchronous and asynchronous tracing can also be done with either one or two arguments provided
as strings.
```c++
TRACE_SCOPED1(category, name, argname, argval)
TRACE_SCOPED1(category, name, argname, argval, traceId, parentId, rootId)
TRACE_SCOPED1(category, name, argname, argval, traceIdHierarchy)
TRACE_DEFAULT_SCOPED1(category, argname, argval)
TRACE_DEFAULT_SCOPED1(category, argname, argval, traceId, parentId, rootId)
TRACE_DEFAULT_SCOPED1(category, argname, argval, traceIdHierarchy)
TRACE_SCOPED2(category, name, argname, argval, argname_two, argval_two)
TRACE_SCOPED2(category, name, argname, argval, argname_two, argval_two, traceId, parentId, rootId)
TRACE_SCOPED2(category, name, argname, argval, argname_two, argval_two, traceIdHierarchy)
TRACE_DEFAULT_SCOPED2(category, argname, argval, argname_two, argval_two)
TRACE_DEFAULT_SCOPED2(category, argname, argval, argname_two, argval_two, traceId, parentId, rootId)
TRACE_DEFAULT_SCOPED2(category, argname, argval, argname_two, argval_two, traceIdHierarchy)
```
### Asynchronous Tracing
#### Tracing an Asynchronous Function or Task
```c++
TRACE_ASYNC_START(category, name)
TRACE_ASYNC_START1(category, name, argname, argval)
TRACE_ASYNC_START2(category, name, argname, argval, argname_two, argval_two)
```
If logging is enabled for the provided category, these functions will initiate
a new asynchronous function trace with name as provided. It will not end
until `TRACE_ASYNC_END` is called with the same Trace ID generated for this
async trace. When these calls are used, the Trace ID Hierarchy will be
determined automatically and the caller does not need to worry about it and,
as such, **these calls should be used in the majority of asynchronous tracing
cases**.
#### Tracing with Explicit, Parameterized Hierarchy
```c++
TRACE_ASYNC_START(category, name)
TRACE_ASYNC_START1(category, name, argname, argval, traceId, parentId, rootId)
TRACE_ASYNC_START2(category, name, argname, argval, argname_two, argval_two, traceId, parentId, rootId)
```
If logging is enabled for the provided category, these versions of the start macros
will initiate a new asynchronous function trace with name and full trace ID Hierarchy as
provided. It will not end until `TRACE_ASYNC_END` is called with the same
Trace ID provided for this async trace. Each of trace ID, parent ID, and
root ID is optional, so providing only a subset of these values is also
valid if the caller only desires to set specific ones.
#### Tracing with the `TRACE_HIERARCHY` Macro
```c++
TRACE_ASYNC_START(category, name, traceIdHierarchy)
TRACE_ASYNC_START1(category, name, argname, argval, traceIdHierarchy)
TRACE_ASYNC_START2(category, name, argname, argval, argname_two, argval_two, traceIdHierarchy)
```
This version of the start macro is intended for use in conjunction with the `TRACE_HIERARCHY` macro
(as described below). These versions of the start macro will initiate a new asynchronous
function trace with name and full Trace ID Hierarchy as provided. It will
not end until `TRACE_ASYNC_END` is called with the same Trace ID provided for
this async trace.
#### Ending an Asynchronous Trace
```c++
TRACE_ASYNC_END(category, id, result)
```
This call will end a trace initiated by `TRACE_ASYNC_START` (as described
above) if logging is enabled for the associated category. The id is expected
to match that used by an `TRACE_ASYNC_START` call, and result is the same as
`TRACE_SET_RESULT`'s argument.
### Flow Tracing
Flow events are used to connect trace events across different threads, processes,
or even machines. They share a `flow_id` which links them together visually in
trace viewers (like Perfetto).
#### Flow Macros: `TRACE_FLOW_BEGIN`, `TRACE_FLOW_STEP`, `TRACE_FLOW_END`
```c++
TRACE_FLOW_BEGIN(category, name, flow_id)
TRACE_FLOW_STEP(category, name, flow_id)
TRACE_FLOW_END(category, name, flow_id)
```
* `TRACE_FLOW_BEGIN`: Marks the start of a flow.
* `TRACE_FLOW_STEP`: Marks an intermediate step in the flow.
* `TRACE_FLOW_END`: Marks the end of the flow.
The `flow_id` can be an integer, a `FrameId`, or any type that is convertible to
`uint64_t` or has a `.value()` method returning a numeric type that is castable
to `uint64_t`.
#### Flow Tracing with Explicit Timestamps
If you need to log a flow event that occurred in the past (e.g., retroactively
tracing a capture event), use the `_WITH_TIME` variants.
```c++
TRACE_FLOW_BEGIN_WITH_TIME(category, name, flow_id, timestamp)
TRACE_FLOW_STEP_WITH_TIME(category, name, flow_id, timestamp)
TRACE_FLOW_END_WITH_TIME(category, name, flow_id, timestamp)
```
* `timestamp`: A `Clock::time_point` representing when the event occurred.
#### Default Flow Macros
```c++
TRACE_FLOW_DEFAULT_BEGIN(category, flow_id)
TRACE_FLOW_DEFAULT_STEP(category, flow_id)
TRACE_FLOW_DEFAULT_END(category, flow_id)
```
These macros behave identically to the ones above but automatically use the
current function name (`__PRETTY_FUNCTION__`) as the flow event name.
For an example usage of flows for on tracking video/audio frame lifecycles, see
[Frame Flow Tracing](../cast/docs/frame_flow_tracing.md).
### Other Tracing Macros
#### `TRACE_CURRENT_ID`
This macro returns the current Trace ID at this point in time.
#### `TRACE_ROOT_ID`
This macro returns the root Trace ID at this point in time.
#### `TRACE_HIERARCHY`
This macro returns an instance of struct Trace ID Hierarchy containing the
current Trace ID Hierarchy. This is intended to be used with
`TRACE_SET_HIERARCHY` (described below) so that Trace ID Hierarchy can be
maintained when crossing thread or machine boundaries.
#### `TRACE_SET_HIERARCHY(ids)`
This macro sets the current Trace Id Hierarchy without initiating a scoped
trace. The set ids will cease to apply when the current scope ends. This is
intended to be used with `TRACE_HIERARCHY` (described above) so that Trace
ID Hierarchy can be maintained when crossing thread or machine boundaries.
#### `TRACE_SET_RESULT(result)`
Sets the current scoped trace's result to be the same as the Error::Code
argument provided.
### Example Code
Synchronous Tracing:
``` c++
public void DoThings(int important_value) {
TRACE_SCOPED(category, "DoThings", "important_value", important_value);
// Do Things.
// A trace log is generated when the scope containing the above call ends.
TRACE_SET_RESULT(Error::Code::kNone);
}
```
Asynchronous tracing with known Trace ID (recommended):
This approach allows for asynchronous tracing when the function being traced can
be associated with a known Trace ID. For instance, a packet ID, a request ID, or
another ID which will live for the duration of the trace but will not need to be
passed around separately.
``` c++
public void DoThingsStart() {
TRACE_ASYNC_START(category, "DoThings", kKnownId);
}
public void DoThingsEnd() {
TRACE_ASYNC_END(category, kKnownId, Error::Code::kNone);
}
```
Asynchronous tracing with unknown Trace ID (not recommended):
This approach allows for asynchronous tracing even when no existing ID can be
associated with the trace.
``` c++
public TraceId DoThingsStart() {
TRACE_ASYNC_START(category, "DoThings");
return TRACE_CURRENT_ID;
}
public void DoThingsEnd(TraceId trace_id) {
TRACE_ASYNC_END(category, trace_id, Error::Code::kNone);
}
```
## File Division
The code for Trace Logging is divided up as follows:
* *util/trace_logging.h*: the macros Open Screen library code is expected to
use to log trace events.
* *platform/base/trace_logging_types.h*: the types/enums used in the platform
API as well as internal library code.
* *util/trace_logging/*: the internal infrastructure backing the macros in
*trace_logging.h*, and connecting it to the platform API.
* *platform/api/trace_logging_platform.h*: the platform implementation that is
used as the trace logging destination while tracing is active.
This information is intended to be only explanatory for embedders - only the one
file mentioned above in Imports must be imported.
## Embedder-Specific Tracing Implementations
For an embedder to create a custom TraceLogging implementation:
1. *Create a TraceLoggingPlatform*
In platform/api/trace_logging_platform.h, the interface TraceLoggingPlatform
is defined. An embedder must define a class implementing this interface. The
methods should be as performance-optimal as possible, since they might be
called frequently (especially `IsLoggingEnabled(TraceCategory)`) and are often
in the critical execution path of the library's code.
2. *Call `openscreen::StartTracing()` and `StopTracing()`*
These activate/deactivate tracing by providing the TraceLoggingPlatform
instance and later clearing references to it.
**The default implementation of this layer can be seen in
platform/impl/trace_logging_platform.cc.**