1# Trace Logging Library Usage 2 3The idea behind Trace Logging is that we can choose to trace a function and 4then, with minimal additional code, determine how long function execution ran 5for, whether the function was successful, and connect all of this information to 6any existing informational logs. The below provides information about how this 7can be achieved with OSP's TraceLogging Infrastructure. 8 9## Compilation 10 11By default, TraceLogging is enabled as part of the build. 12To disable TraceLogging, include flag `--args="enable_trace_logging=false"` 13when calling `gn gen` as part of building this library. 14 15## Imports 16 17To use TraceLogging, import the following header file: 18 * *util/trace_logging.h* 19This file will import all other Trace Logging dependencies. 20 21## Trace IDs 22 23When a Trace Log is created, a new unsigned integer is associated with this 24specific trace, which will going forward be referred to as a Trace ID. 25Associating a Trace ID has the following benefits: 26 27* The same Trace ID can be associated with all Informational Logs generated 28 during this traced method’s execution. This will allow for all informational 29 logs to easily be associated with a method execution, so that if an unexpected 30 failure occurs or edge case pops up we will have additional information useful 31 in debugging this issue and can more easily determine the state of the system 32 leading to this issue. 33 34* If another Trace Log is created during the execution of this first traced 35 method, we will have a hierarchy of Trace IDs. This will allow us to easily 36 create an execution tree (through trivial scripting, preexisting tool, or 37 database operations) to get a better view of how execution is proceeding. 38 Together, the IDs associated with these calls form a Trace ID Hierarchy. The 39 Hierarchy has the following format: 40 * *Current Trace ID*: The ID of the function currently being traced. 41 * *Parent Trace ID*: The ID of the function which was being traced when this 42 Trace was initiated. 43 * *Root Trace ID*: The ID of the first traced function under which this the 44 current Trace was called. 45 46As an example: 47``` cpp 48 public void DoThings() { 49 TRACE_SCOPED(category, "outside"); 50 { 51 TRACE_SCOPED(category, "middle"); 52 { 53 TRACE_SCOPED(category, "inside"); 54 } 55 } 56 } 57``` 58 59This could result in the following Trace ID Information: 60 61| NAME | ROOT ID | PARENT ID | TRACE ID | RESULT | 62|---------|----------|------------|-----------|---------| 63| outside | 100 | 0 | 100 | success | 64| middle | 100 | 100 | 101 | success | 65| inside | 100 | 101 | 102 | success | 66 67Note that, prior to any trace calls, the Trace ID is considered to be 0x0 by 68convention. 69 70## Trace Results 71 72The "result" of a trace is meant to indicate whether the traced function 73completed successfully or not. Results are handled differently for synchronous 74and asynchronous traces. 75 76For scoped traces, the trace is by default assumed to be successful. If an error 77state is desired, this should be set using `TRACE_SET_RESULT(result)` where 78result is some Error::Code enum value. 79 80For asynchronous calls, the result must be set as part of the `TRACE_ASYNC_END` 81call. As with scoped traces, the result must be some Error::Code enum value. 82 83## Tracing Functions 84All of the below functions rely on the Platform Layer's IsTraceLoggingEnabled() 85function. When logging is disabled, either for the specific category of trace 86logging which the Macro specifies or for TraceCategory::Any in all other cases, 87the below functions will be treated as a NoOp. 88 89### Synchronous Tracing 90 ```c++ 91 TRACE_SCOPED(category, name) 92 TRACE_SCOPED(category, name, traceId, parentId, rootId) 93 TRACE_SCOPED(category, name, traceIdHierarchy) 94 ``` 95 If logging is enabled for the provided |category|, trace the current scope. The scope 96 should encompass the operation described by |name|. The latter two uses of this macro are 97 for manually providing the trace ID hierarchy; the first auto-generates a new trace ID for 98 this scope and sets its parent trace ID to that of the encompassing scope (if any). 99 100 ```c++ 101 TRACE_DEFAULT_SCOPED(category) 102 TRACE_DEFAULT_SCOPED(category, traceId, parentId, rootId) 103 TRACE_DEFAULT_SCOPED(category, traceIdHierarchy) 104 ``` 105 Same as TRACE_SCOPED(), but use the current function/method signature as the operation 106 name. 107 108### Asynchronous Tracing 109 `TRACE_ASYNC_START(category, name)` 110 If logging is enabled for the provided category, this function will initiate 111 a new asynchronous function trace with name as provided. It will not end 112 until TRACE_ASYNC_END is called with the same Trace ID generated for this 113 async trace. When this call is used, the Trace ID Hierarchy will be 114 determined automatically and the caller does not need to worry about it and, 115 as such, **this call should be used in the majority of asynchronous tracing 116 cases**. 117 118 `TRACE_ASYNC_START(category, name, traceId, parentId, rootId)` 119 If logging is enabled for the provided category, this function will initiate 120 a new asynchronous function trace with name and full Trac ID Hierarchy as 121 provided. It will not end until TRACE_ASYNC_END is called with the same 122 Trace ID provided for this async trace. Each of trace ID, parent ID, and 123 root ID is optional, so providing only a subset of these values is also 124 valid if the caller only desires to set specific ones. 125 126 `TRACE_ASYNC_START(category, name, traceIdHierarchy)` 127 This call is intended for use in conjunction with the TRACE_HIERARCHY macro 128 (as described below). this function will initiate a new asynchronous 129 function trace with name and full Trace ID Hierarchy as provided. It will 130 not end until TRACE_ASYNC_END is called with the same Trace ID provided for 131 this async trace. 132 133 `TRACE_ASYNC_END(category, id, result)` 134 This call will end a trace initiated by TRACE_ASYNC_START (as described 135 above) if logging is enabled for the associated category. The id is expected 136 to match that used by an TRACE_ASYNC_START call, and result is the same as 137 TRACE_SET_RESULT's argument. 138 139### Other Tracing Macros 140 `TRACE_CURRENT_ID` 141 This macro returns the current Trace ID at this point in time. 142 143 `TRACE_ROOT_ID` 144 This macro returns the root Trace ID at this point in time. 145 146 `TRACE_HIERARCHY` 147 This macro returns an instance of struct Trace ID Hierarchy containing the 148 current Trace ID Hierarchy. This is intended to be used with 149 `TRACE_SET_HIERARCHY` (described below) so that Trace ID Hierarchy can be 150 maintained when crossing thread or machine boundaries. 151 152 `TRACE_SET_HIERARCHY(ids)` 153 This macro sets the current Trace Id Hierarchy without initiating a scoped 154 trace. The set ids will cease to apply when the current scope ends. This is 155 intended to be used with `TRACE_HIERARCHY` (described above) so that Trace 156 ID Hierarchy can be maintained when crossing thread or machine boundaries. 157 158 `TRACE_SET_RESULT(result)` 159 Sets the current scoped trace's result to be the same as the Error::Code 160 argument provided. 161 162### Example Code 163Synchronous Tracing: 164``` cpp 165 public void DoThings() { 166 TRACE_SCOPED(category, "DoThings"); 167 168 // Do Things. 169 // A trace log is generated when the scope containing the above call ends. 170 171 TRACE_SET_RESULT(Error::Code::kNone); 172 } 173``` 174 175Asynchronous tracing with known Trace ID (recommended): 176This approach allows for asynchronous tracing when the function being traced can 177be associated with a known Trace ID. For instance, a packet ID, a request ID, or 178another ID which will live for the duration of the trace but will not need to be 179passed around separately. 180``` cpp 181 public void DoThingsStart() { 182 TRACE_ASYNC_START(category, "DoThings", kKnownId); 183 } 184 185 public void DoThingsEnd() { 186 TRACE_ASYNC_END(category, kKnownId, Error::Code::kNone); 187 } 188``` 189 190Asynchronous tracing with unknown Trace ID (not recommended): 191This approach allows for asynchronous tracing even when no existing ID can be 192associated with the trace. 193``` cpp 194 public TraceId DoThingsStart() { 195 TRACE_ASYNC_START(category, "DoThings"); 196 return TRACE_CURRENT_ID; 197 } 198 199 public void DoThingsEnd(TraceId trace_id) { 200 TRACE_ASYNC_END(category, trace_id, Error::Code::kNone); 201 } 202``` 203 204## File Division 205The code for Trace Logging is divided up as follows: 206 * *util/trace_logging.h*: the macros Open Screen library code is expected to 207 use to log trace events. 208 * *platform/base/trace_logging_types.h*: the types/enums used in the platform 209 API as well as internal library code. 210 * *util/trace_logging/*: the internal infrastructure backing the macros in 211 *trace_logging.h*, and connecting it to the platform API. 212 * *platform/api/trace_logging_platform.h*: the platform implementation that is 213 used as the trace logging destination while tracing is active. 214This information is intended to be only eplanatory for embedders - only the one 215file mentioned above in Imports must be imported. 216 217## Embedder-Specific Tracing Implementations 218 219For an embedder to create a custom TraceLogging implementation: 220 2211. *Create a TraceLoggingPlatform* 222 In platform/api/trace_logging_platform.h, the interface TraceLoggingPlatform 223 is defined. An embedder must define a class implementing this interface. The 224 methods should be as performance-optimal as possible, since they might be 225 called frequently (especially `IsLoggingEnabled(TraceCategory)`) and are often 226 in the critical execution path of the library's code. 227 2282. *Call `openscreen::StartTracing()` and `StopTracing()`* 229 These activate/deactivate tracing by providing the TraceLoggingPlatform 230 instance and later clearing references to it. 231 232**The default implementation of this layer can be seen in 233platform/impl/trace_logging_platform.cc.** 234