1 // Copyright 2015 The Chromium Authors 2 // Use of this source code is governed by a BSD-style license that can be 3 // found in the LICENSE file. 4 5 #ifndef BASE_TRACE_EVENT_COMMON_TRACE_EVENT_COMMON_H_ 6 #define BASE_TRACE_EVENT_COMMON_TRACE_EVENT_COMMON_H_ 7 8 // Trace events are for tracking application performance and resource usage. 9 // Macros are provided to track: 10 // Begin and end of function calls 11 // Counters 12 // 13 // Events are issued against categories. Whereas LOG's 14 // categories are statically defined, TRACE categories are created 15 // implicitly with a string. For example: 16 // TRACE_EVENT_INSTANT0("MY_SUBSYSTEM", "SomeImportantEvent", 17 // TRACE_EVENT_SCOPE_THREAD) 18 // 19 // It is often the case that one trace may belong in multiple categories at the 20 // same time. The first argument to the trace can be a comma-separated list of 21 // categories, forming a category group, like: 22 // 23 // TRACE_EVENT_INSTANT0("input,views", "OnMouseOver", TRACE_EVENT_SCOPE_THREAD) 24 // 25 // We can enable/disable tracing of OnMouseOver by enabling/disabling either 26 // category. 27 // 28 // Events can be INSTANT, or can be pairs of BEGIN and END in the same scope: 29 // TRACE_EVENT_BEGIN0("MY_SUBSYSTEM", "SomethingCostly") 30 // doSomethingCostly() 31 // TRACE_EVENT_END0("MY_SUBSYSTEM", "SomethingCostly") 32 // Note: our tools can't always determine the correct BEGIN/END pairs unless 33 // these are used in the same scope. Use ASYNC_BEGIN/ASYNC_END macros if you 34 // need them to be in separate scopes. 35 // 36 // A common use case is to trace entire function scopes. This 37 // issues a trace BEGIN and END automatically: 38 // void doSomethingCostly() { 39 // TRACE_EVENT0("MY_SUBSYSTEM", "doSomethingCostly"); 40 // ... 41 // } 42 // 43 // Additional parameters can be associated with an event: 44 // void doSomethingCostly2(int howMuch) { 45 // TRACE_EVENT1("MY_SUBSYSTEM", "doSomethingCostly", 46 // "howMuch", howMuch); 47 // ... 48 // } 49 // 50 // The trace system will automatically add to this information the 51 // current process id, thread id, and a timestamp in microseconds. 52 // 53 // To trace an asynchronous procedure such as an IPC send/receive, use 54 // NESTABLE_ASYNC_BEGIN and NESTABLE_ASYNC_END: 55 // [single threaded sender code] 56 // static int send_count = 0; 57 // ++send_count; 58 // TRACE_EVENT_NESTABLE_ASYNC_BEGIN0( 59 // "ipc", "message", TRACE_ID_WITH_SCOPE("message", send_count)); 60 // Send(new MyMessage(send_count)); 61 // [receive code] 62 // void OnMyMessage(send_count) { 63 // TRACE_NESTABLE_EVENT_ASYNC_END0( 64 // "ipc", "message", TRACE_ID_WITH_SCOPE("message", send_count)); 65 // } 66 // The third parameter is a unique ID to match NESTABLE_ASYNC_BEGIN/ASYNC_END 67 // pairs. NESTABLE_ASYNC_BEGIN and ASYNC_END can occur on any thread of any 68 // traced process. // Pointers can be used for the ID parameter, and they will 69 // be annotated internally so that the same pointer on two different processes 70 // will not match. For example: 71 // class MyTracedClass { 72 // public: 73 // MyTracedClass() { 74 // TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("category", "MyTracedClass", 75 // TRACE_ID_LOCAL(this)); 76 // } 77 // ~MyTracedClass() { 78 // TRACE_EVENT_NESTABLE_ASYNC_END0("category", "MyTracedClass", 79 // TRACE_ID_LOCAL(this)); 80 // } 81 // } 82 // 83 // Trace event also supports counters, which is a way to track a quantity 84 // as it varies over time. Counters are created with the following macro: 85 // TRACE_COUNTER1("MY_SUBSYSTEM", "myCounter", g_myCounterValue); 86 // 87 // Counters are process-specific. The macro itself can be issued from any 88 // thread, however. 89 // 90 // Sometimes, you want to track two counters at once. You can do this with two 91 // counter macros: 92 // TRACE_COUNTER1("MY_SUBSYSTEM", "myCounter0", g_myCounterValue[0]); 93 // TRACE_COUNTER1("MY_SUBSYSTEM", "myCounter1", g_myCounterValue[1]); 94 // Or you can do it with a combined macro: 95 // TRACE_COUNTER2("MY_SUBSYSTEM", "myCounter", 96 // "bytesPinned", g_myCounterValue[0], 97 // "bytesAllocated", g_myCounterValue[1]); 98 // This indicates to the tracing UI that these counters should be displayed 99 // in a single graph, as a summed area chart. 100 // 101 // Since counters are in a global namespace, you may want to disambiguate with a 102 // unique ID, by using the TRACE_COUNTER_ID* variations. 103 // 104 // By default, trace collection is compiled in, but turned off at runtime. 105 // Collecting trace data is the responsibility of the embedding 106 // application. In Chrome's case, navigating to about:tracing will turn on 107 // tracing and display data collected across all active processes. 108 // 109 // 110 // Memory scoping note: 111 // Tracing copies the pointers, not the string content, of the strings passed 112 // in for category_group, name, and arg_names. Thus, the following code will 113 // cause problems: 114 // char* str = strdup("importantName"); 115 // TRACE_EVENT_INSTANT0("SUBSYSTEM", str); // BAD! 116 // free(str); // Trace system now has dangling pointer 117 // 118 // To avoid this issue with the |name| and |arg_name| parameters, use the 119 // TRACE_EVENT_COPY_XXX overloads of the macros at additional runtime overhead. 120 // Notes: The category must always be in a long-lived char* (i.e. static const). 121 // The |arg_values|, when used, are always deep copied with the _COPY 122 // macros. 123 // 124 // When are string argument values copied: 125 // const char* arg_values are only referenced by default: 126 // TRACE_EVENT1("category", "name", 127 // "arg1", "literal string is only referenced"); 128 // Use TRACE_STR_COPY to force copying of a const char*: 129 // TRACE_EVENT1("category", "name", 130 // "arg1", TRACE_STR_COPY("string will be copied")); 131 // std::string arg_values are always copied: 132 // TRACE_EVENT1("category", "name", 133 // "arg1", std::string("string will be copied")); 134 // 135 // 136 // Convertable notes: 137 // Converting a large data type to a string can be costly. To help with this, 138 // the trace framework provides an interface ConvertableToTraceFormat. If you 139 // inherit from it and implement the AppendAsTraceFormat method the trace 140 // framework will call back to your object to convert a trace output time. This 141 // means, if the category for the event is disabled, the conversion will not 142 // happen. 143 // 144 // class MyData : public base::trace_event::ConvertableToTraceFormat { 145 // public: 146 // MyData() {} 147 // 148 // MyData(const MyData&) = delete; 149 // MyData& operator=(const MyData&) = delete; 150 // 151 // void AppendAsTraceFormat(std::string* out) const override { 152 // out->append("{\"foo\":1}"); 153 // } 154 // private: 155 // ~MyData() override {} 156 // }; 157 // 158 // TRACE_EVENT1("foo", "bar", "data", 159 // std::unique_ptr<ConvertableToTraceFormat>(new MyData())); 160 // 161 // The trace framework will take ownership if the passed pointer and it will 162 // be free'd when the trace buffer is flushed. 163 // 164 // Note, we only do the conversion when the buffer is flushed, so the provided 165 // data object should not be modified after it's passed to the trace framework. 166 // 167 // 168 // Thread Safety: 169 // A thread safe singleton and mutex are used for thread safety. Category 170 // enabled flags are used to limit the performance impact when the system 171 // is not enabled. 172 // 173 // TRACE_EVENT macros first cache a pointer to a category. The categories are 174 // statically allocated and safe at all times, even after exit. Fetching a 175 // category is protected by the TraceLog::lock_. Multiple threads initializing 176 // the static variable is safe, as they will be serialized by the lock and 177 // multiple calls will return the same pointer to the category. 178 // 179 // Then the category_group_enabled flag is checked. This is a unsigned char, and 180 // not intended to be multithread safe. It optimizes access to AddTraceEvent 181 // which is threadsafe internally via TraceLog::lock_. The enabled flag may 182 // cause some threads to incorrectly call or skip calling AddTraceEvent near 183 // the time of the system being enabled or disabled. This is acceptable as 184 // we tolerate some data loss while the system is being enabled/disabled and 185 // because AddTraceEvent is threadsafe internally and checks the enabled state 186 // again under lock. 187 // 188 // Without the use of these static category pointers and enabled flags all 189 // trace points would carry a significant performance cost of acquiring a lock 190 // and resolving the category. 191 192 //////////////////////////////////////////////////////////////////////////////// 193 // Perfetto trace macros 194 195 #include "base/threading/platform_thread.h" 196 #include "base/time/time.h" 197 #include "build/build_config.h" 198 199 #if BUILDFLAG(ENABLE_BASE_TRACING) 200 201 // Enable legacy trace event macros (e.g., TRACE_EVENT{0,1,2}). 202 #define PERFETTO_ENABLE_LEGACY_TRACE_EVENTS 1 203 204 // Macros for reading the current trace time (bypassing any virtual time 205 // overrides). 206 #define TRACE_TIME_TICKS_NOW() ::base::subtle::TimeTicksNowIgnoringOverride() 207 #define TRACE_TIME_NOW() ::base::subtle::TimeNowIgnoringOverride() 208 209 // Implementation detail: trace event macros create temporary variables 210 // to keep instrumentation overhead low. These macros give each temporary 211 // variable a unique name based on the line number to prevent name collisions. 212 #define INTERNAL_TRACE_EVENT_UID(name_prefix) PERFETTO_UID(name_prefix) 213 214 // Declare debug annotation converters for base time types, so they can be 215 // passed as trace event arguments. 216 // TODO(skyostil): Serialize timestamps using perfetto::TracedValue instead. 217 namespace perfetto { 218 namespace protos { 219 namespace pbzero { 220 class DebugAnnotation; 221 } // namespace pbzero 222 } // namespace protos 223 namespace internal { 224 225 void BASE_EXPORT 226 WriteDebugAnnotation(protos::pbzero::DebugAnnotation* annotation, 227 ::base::TimeTicks); 228 void BASE_EXPORT 229 WriteDebugAnnotation(protos::pbzero::DebugAnnotation* annotation, ::base::Time); 230 231 } // namespace internal 232 } // namespace perfetto 233 234 // Pull in the tracing macro definitions from Perfetto. 235 #include "third_party/perfetto/include/perfetto/tracing/track_event.h" // IWYU pragma: export 236 #include "third_party/perfetto/include/perfetto/tracing/track_event_legacy.h" // IWYU pragma: export 237 238 namespace perfetto { 239 namespace legacy { 240 241 template <> 242 perfetto::ThreadTrack BASE_EXPORT 243 ConvertThreadId(const ::base::PlatformThreadId& thread); 244 245 #if BUILDFLAG(IS_WIN) 246 template <> 247 perfetto::ThreadTrack BASE_EXPORT ConvertThreadId(const int& thread); 248 #endif // BUILDFLAG(IS_WIN) 249 250 } // namespace legacy 251 252 template <> 253 struct BASE_EXPORT TraceTimestampTraits<::base::TimeTicks> { 254 static TraceTimestamp ConvertTimestampToTraceTimeNs( 255 const ::base::TimeTicks& ticks); 256 }; 257 258 } // namespace perfetto 259 260 #else // !BUILDFLAG(ENABLE_BASE_TRACING) 261 262 // This macro is still used in some components even when base tracing is 263 // disabled. 264 // TODO(crbug/336718643): Make sure no code affected by 265 // enable_base_tracing=false includes this file directly, then move the define 266 // to trace_event_stub.h. 267 #define TRACE_DISABLED_BY_DEFAULT(name) "disabled-by-default-" name 268 269 #endif // !BUILDFLAG(ENABLE_BASE_TRACING) 270 271 #endif // BASE_TRACE_EVENT_COMMON_TRACE_EVENT_COMMON_H_ 272