// Copyright (c) 2011 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. // Trace events are for tracking application performance. // // Events are issued against categories. Whereas LOG's // categories are statically defined, TRACE categories are created // implicitly with a string. For example: // TRACE_EVENT_INSTANT0("MY_SUBSYSTEM", "SomeImportantEvent") // // Events can be INSTANT, or can be pairs of BEGIN and END: // TRACE_EVENT_BEGIN0("MY_SUBSYSTEM", "SomethingCostly") // doSomethingCostly() // TRACE_EVENT_END0("MY_SUBSYSTEM", "SomethingCostly") // // A common use case is to trace entire function scopes. This // issues a trace BEGIN and END automatically: // void doSomethingCostly() { // TRACE_EVENT0("MY_SUBSYSTEM", "doSomethingCostly"); // ... // } // // Additional parameters can be associated with an event: // void doSomethingCostly2(int howMuch) { // TRACE_EVENT1("MY_SUBSYSTEM", "doSomethingCostly", // "howMuch", StringPrintf("%i", howMuch).c_str()); // ... // } // // The trace system will automatically add to this information the // current process id, thread id, a timestamp down to the // microsecond, as well as the file and line number of the calling location. // // By default, trace collection is compiled in, but turned off at runtime. // Collecting trace data is the responsibility of the embedding // application. In Chrome's case, navigating to about:gpu will turn on // tracing and display data collected across all active processes. // // // Thread Safety: // A thread safe singleton and mutex are used for thread safety. Category // enabled flags are used to limit the performance impact when the system // is not enabled. // // TRACE_EVENT macros first cache a pointer to a category. The categories are // statically allocated and safe at all times, even after exit. Fetching a // category is protected by the TraceLog::lock_. Multiple threads initializing // the static variable is safe, as they will be serialized by the lock and // multiple calls will return the same pointer to the category. // // Then the category.enabled flag is checked. This is a volatile bool, and // not intended to be multithread safe. It optimizes access to AddTraceEvent // which is threadsafe internally via TraceLog::lock_. The enabled flag may // cause some threads to incorrectly call or skip calling AddTraceEvent near // the time of the system being enabled or disabled. This is acceptable as // we tollerate some data loss while the system is being enabled/disabled and // because AddTraceEvent is threadsafe internally and checks the enabled state // again under lock. // // Without the use of these static category pointers and enabled flags all // trace points would carry a significant performance cost of aquiring a lock // and resolving the category. // // ANNOTATE_BENIGN_RACE is used to suppress the warning on the static category // pointers. #ifndef BASE_DEBUG_TRACE_EVENT_H_ #define BASE_DEBUG_TRACE_EVENT_H_ #pragma once #include "build/build_config.h" #include #include #include "base/callback.h" #include "base/memory/singleton.h" #include "base/string_util.h" #include "base/third_party/dynamic_annotations/dynamic_annotations.h" #include "base/timer.h" // Older style trace macros with explicit id and extra data // Only these macros result in publishing data to ETW as currently implemented. #define TRACE_EVENT_BEGIN_ETW(name, id, extra) \ base::debug::TraceLog::AddTraceEventEtw( \ base::debug::TRACE_EVENT_PHASE_BEGIN, \ __FILE__, __LINE__, name, reinterpret_cast(id), extra); #define TRACE_EVENT_END_ETW(name, id, extra) \ base::debug::TraceLog::AddTraceEventEtw( \ base::debug::TRACE_EVENT_PHASE_END, \ __FILE__, __LINE__, name, reinterpret_cast(id), extra); #define TRACE_EVENT_INSTANT_ETW(name, id, extra) \ base::debug::TraceLog::AddTraceEventEtw( \ base::debug::TRACE_EVENT_PHASE_INSTANT, \ __FILE__, __LINE__, name, reinterpret_cast(id), extra); // Implementation detail: trace event macros create temporary variables // to keep instrumentation overhead low. These macros give each temporary // variable a unique name based on the line number to prevent name collissions. #define TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b) a##b #define TRACE_EVENT_UNIQUE_IDENTIFIER2(a,b) \ TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b) #define TRACE_EVENT_UNIQUE_IDENTIFIER(name_prefix) \ TRACE_EVENT_UNIQUE_IDENTIFIER2(name_prefix, __LINE__) // Records a pair of begin and end events called "name" for the current // scope, with 0, 1 or 2 associated arguments. If the category is not // enabled, then this does nothing. // - category and name strings must have application lifetime (statics or // literals). They may not include " chars. // - ANNOTATE_BENIGN_RACE, see Thread Safety above. #define TRACE_EVENT0(category, name) \ TRACE_EVENT1(category, name, NULL, 0) #define TRACE_EVENT1(category, name, arg1_name, arg1_val) \ TRACE_EVENT2(category, name, arg1_name, arg1_val, NULL, 0) #define TRACE_EVENT2(category, name, arg1_name, arg1_val, arg2_name, arg2_val) \ static const base::debug::TraceCategory* \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = NULL; \ ANNOTATE_BENIGN_RACE(&TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ "trace_event category"); \ if (!TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)) \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \ base::debug::TraceLog::GetCategory(category); \ if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled) { \ base::debug::TraceLog::GetInstance()->AddTraceEvent( \ base::debug::TRACE_EVENT_PHASE_BEGIN, \ __FILE__, __LINE__, \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ name, \ arg1_name, arg1_val, \ arg2_name, arg2_val); \ } \ base::debug::internal::TraceEndOnScopeClose \ TRACE_EVENT_UNIQUE_IDENTIFIER(profileScope) ( \ __FILE__, __LINE__, \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), name); // Records a single event called "name" immediately, with 0, 1 or 2 // associated arguments. If the category is not enabled, then this // does nothing. // - category and name strings must have application lifetime (statics or // literals). They may not include " chars. // - ANNOTATE_BENIGN_RACE, see Thread Safety above. #define TRACE_EVENT_INSTANT0(category, name) \ TRACE_EVENT_INSTANT1(category, name, NULL, 0) #define TRACE_EVENT_INSTANT1(category, name, arg1_name, arg1_val) \ TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, NULL, 0) #define TRACE_EVENT_INSTANT2(category, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ static const base::debug::TraceCategory* \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = NULL; \ ANNOTATE_BENIGN_RACE(&TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ "trace_event category"); \ if (!TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)) \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \ base::debug::TraceLog::GetCategory(category); \ if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled) { \ base::debug::TraceLog::GetInstance()->AddTraceEvent( \ base::debug::TRACE_EVENT_PHASE_INSTANT, \ __FILE__, __LINE__, \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ name, \ arg1_name, arg1_val, \ arg2_name, arg2_val); \ } // Records a single BEGIN event called "name" immediately, with 0, 1 or 2 // associated arguments. If the category is not enabled, then this // does nothing. // - category and name strings must have application lifetime (statics or // literals). They may not include " chars. // - ANNOTATE_BENIGN_RACE, see Thread Safety above. #define TRACE_EVENT_BEGIN0(category, name) \ TRACE_EVENT_BEGIN1(category, name, NULL, 0) #define TRACE_EVENT_BEGIN1(category, name, arg1_name, arg1_val) \ TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, NULL, 0) #define TRACE_EVENT_BEGIN2(category, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ static const base::debug::TraceCategory* \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = NULL; \ ANNOTATE_BENIGN_RACE(&TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ "trace_event category"); \ if (!TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)) \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \ base::debug::TraceLog::GetCategory(category); \ if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled) { \ base::debug::TraceLog::GetInstance()->AddTraceEvent( \ base::debug::TRACE_EVENT_PHASE_BEGIN, \ __FILE__, __LINE__, \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ name, \ arg1_name, arg1_val, \ arg2_name, arg2_val); \ } // Records a single END event for "name" immediately. If the category // is not enabled, then this does nothing. // - category and name strings must have application lifetime (statics or // literals). They may not include " chars. // - ANNOTATE_BENIGN_RACE, see Thread Safety above. #define TRACE_EVENT_END0(category, name) \ TRACE_EVENT_END1(category, name, NULL, 0) #define TRACE_EVENT_END1(category, name, arg1_name, arg1_val) \ TRACE_EVENT_END2(category, name, arg1_name, arg1_val, NULL, 0) #define TRACE_EVENT_END2(category, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ static const base::debug::TraceCategory* \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = NULL; \ ANNOTATE_BENIGN_RACE(&TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ "trace_event category"); \ if (!TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)) \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \ base::debug::TraceLog::GetCategory(category); \ if (TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic)->enabled) { \ base::debug::TraceLog::GetInstance()->AddTraceEvent( \ base::debug::TRACE_EVENT_PHASE_END, \ __FILE__, __LINE__, \ TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ name, \ arg1_name, arg1_val, \ arg2_name, arg2_val); \ } namespace base { namespace debug { // Categories allow enabling/disabling of streams of trace events struct TraceCategory { const char* name; volatile bool enabled; }; const size_t kTraceMaxNumArgs = 2; // Phase indicates the nature of an event entry. E.g. part of a begin/end pair. enum TraceEventPhase { TRACE_EVENT_PHASE_BEGIN, TRACE_EVENT_PHASE_END, TRACE_EVENT_PHASE_INSTANT }; // Simple union of values. This is much lighter weight than base::Value, which // requires dynamic allocation and a vtable. To keep the trace runtime overhead // low, we want constant size storage here. class BASE_API TraceValue { public: enum Type { TRACE_TYPE_UNDEFINED, TRACE_TYPE_BOOL, TRACE_TYPE_UINT, TRACE_TYPE_INT, TRACE_TYPE_DOUBLE, TRACE_TYPE_POINTER, TRACE_TYPE_STRING }; TraceValue() : type_(TRACE_TYPE_UNDEFINED) { value_.as_uint = 0ull; } TraceValue(bool rhs) : type_(TRACE_TYPE_BOOL) { value_.as_bool = rhs; } TraceValue(uint64 rhs) : type_(TRACE_TYPE_UINT) { value_.as_uint = rhs; } TraceValue(uint32 rhs) : type_(TRACE_TYPE_UINT) { value_.as_uint = rhs; } TraceValue(uint16 rhs) : type_(TRACE_TYPE_UINT) { value_.as_uint = rhs; } TraceValue(uint8 rhs) : type_(TRACE_TYPE_UINT) { value_.as_uint = rhs; } TraceValue(int64 rhs) : type_(TRACE_TYPE_INT) { value_.as_int = rhs; } TraceValue(int32 rhs) : type_(TRACE_TYPE_INT) { value_.as_int = rhs; } TraceValue(int16 rhs) : type_(TRACE_TYPE_INT) { value_.as_int = rhs; } TraceValue(int8 rhs) : type_(TRACE_TYPE_INT) { value_.as_int = rhs; } TraceValue(double rhs) : type_(TRACE_TYPE_DOUBLE) { value_.as_double = rhs; } TraceValue(const void* rhs) : type_(TRACE_TYPE_POINTER) { value_.as_pointer = rhs; } TraceValue(const char* rhs) : type_(TRACE_TYPE_STRING) { value_.as_string_refptr = new RefCountedString(); value_.as_string_refptr->AddRef(); DCHECK(value_.as_string_refptr->HasOneRef()); value_.as_string_refptr->data = rhs; } TraceValue(const TraceValue& rhs) : type_(TRACE_TYPE_UNDEFINED) { operator=(rhs); } ~TraceValue() { Destroy(); } TraceValue& operator=(const TraceValue& rhs); void Destroy(); void AppendAsJSON(std::string* out) const; Type type() const { return type_; } uint64 as_uint() const { return value_.as_uint; } bool as_bool() const { return value_.as_bool; } int64 as_int() const { return value_.as_int; } double as_double() const { return value_.as_double; } const void* as_pointer() const { return value_.as_pointer; } const char* as_string() const { return value_.as_string_refptr->data.c_str(); } typedef RefCountedData RefCountedString; private: union Value { bool as_bool; uint64 as_uint; int64 as_int; double as_double; const void* as_pointer; RefCountedString* as_string_refptr; }; Type type_; Value value_; }; // Output records are "Events" and can be obtained via the // OutputCallback whenever the tracing system decides to flush. This // can happen at any time, on any thread, or you can programatically // force it to happen. struct TraceEvent { TraceEvent(); ~TraceEvent(); // Serialize event data to JSON static void AppendEventsAsJSON(const std::vector& events, size_t start, size_t count, std::string* out); void AppendAsJSON(std::string* out) const; unsigned long process_id; unsigned long thread_id; TimeTicks timestamp; TraceEventPhase phase; const TraceCategory* category; const char* name; const char* arg_names[kTraceMaxNumArgs]; TraceValue arg_values[kTraceMaxNumArgs]; }; class BASE_API TraceLog { public: static TraceLog* GetInstance(); // Global enable of tracing. Currently enables all categories or not. // TODO(scheib): Replace with an Enable/DisableCategory() that // implicitly controls the global logging state. void SetEnabled(bool enabled); bool IsEnabled() { return enabled_; } float GetBufferPercentFull() const; // When enough events are collected, they are handed (in bulk) to // the output callback. If no callback is set, the output will be // silently dropped. The callback must be thread safe. typedef RefCountedData RefCountedString; typedef base::Callback OutputCallback; void SetOutputCallback(const OutputCallback& cb); // The trace buffer does not flush dynamically, so when it fills up, // subsequent trace events will be dropped. This callback is generated when // the trace buffer is full. The callback must be thread safe. typedef base::Callback BufferFullCallback; void SetBufferFullCallback(const BufferFullCallback& cb); // Flushes all logged data to the callback. void Flush(); // Called by TRACE_EVENT* macros, don't call this directly. static const TraceCategory* GetCategory(const char* name); // Called by TRACE_EVENT* macros, don't call this directly. void AddTraceEvent(TraceEventPhase phase, const char* file, int line, const TraceCategory* category, const char* name, const char* arg1_name, TraceValue arg1_val, const char* arg2_name, TraceValue arg2_val); static void AddTraceEventEtw(TraceEventPhase phase, const char* file, int line, const char* name, const void* id, const char* extra); static void AddTraceEventEtw(TraceEventPhase phase, const char* file, int line, const char* name, const void* id, const std::string& extra) { AddTraceEventEtw(phase, file, line, name, id, extra.c_str()); } // Exposed for unittesting only, allows resurrecting our // singleton instance post-AtExit processing. static void Resurrect(); private: // This allows constructor and destructor to be private and usable only // by the Singleton class. friend struct StaticMemorySingletonTraits; TraceLog(); ~TraceLog(); const TraceCategory* GetCategoryInternal(const char* name); // TODO(nduca): switch to per-thread trace buffers to reduce thread // synchronization. Lock lock_; bool enabled_; OutputCallback output_callback_; BufferFullCallback buffer_full_callback_; std::vector logged_events_; DISALLOW_COPY_AND_ASSIGN(TraceLog); }; namespace internal { // Used by TRACE_EVENTx macro. Do not use directly. class BASE_API TraceEndOnScopeClose { public: TraceEndOnScopeClose(const char* file, int line, const TraceCategory* category, const char* name) : file_(file) , line_(line) , category_(category) , name_(name) { } ~TraceEndOnScopeClose() { if (category_->enabled) base::debug::TraceLog::GetInstance()->AddTraceEvent( base::debug::TRACE_EVENT_PHASE_END, file_, line_, category_, name_, NULL, 0, NULL, 0); } private: const char* file_; int line_; const TraceCategory* category_; const char* name_; }; } // namespace internal } // namespace debug } // namespace base #endif // BASE_DEBUG_TRACE_EVENT_H_