diff options
Diffstat (limited to 'base')
| -rw-r--r-- | base/base.gyp | 1 | ||||
| -rw-r--r-- | base/base.gypi | 1 | ||||
| -rw-r--r-- | base/debug/trace_event.cc | 452 | ||||
| -rw-r--r-- | base/debug/trace_event.h | 508 | ||||
| -rw-r--r-- | base/debug/trace_event_unittest.cc | 397 | ||||
| -rw-r--r-- | base/debug/trace_event_win.cc | 47 | ||||
| -rw-r--r-- | base/debug/trace_event_win.h | 46 | ||||
| -rw-r--r-- | base/debug/trace_event_win_unittest.cc | 49 |
8 files changed, 1194 insertions, 307 deletions
diff --git a/base/base.gyp b/base/base.gyp index da5d018..6953ede 100644 --- a/base/base.gyp +++ b/base/base.gyp @@ -117,6 +117,7 @@ 'cpu_unittest.cc', 'debug/leak_tracker_unittest.cc', 'debug/stack_trace_unittest.cc', + 'debug/trace_event_unittest.cc', 'debug/trace_event_win_unittest.cc', 'dir_reader_posix_unittest.cc', 'environment_unittest.cc', diff --git a/base/base.gypi b/base/base.gypi index 51f50ed..578e50d 100644 --- a/base/base.gypi +++ b/base/base.gypi @@ -404,7 +404,6 @@ # regression to page cycler moz. 'sha1_win.cc', 'string16.cc', - 'debug/trace_event.cc', ], },], ['OS=="freebsd" or OS=="openbsd"', { diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc index c219cec..58ff82f 100644 --- a/base/debug/trace_event.cc +++ b/base/debug/trace_event.cc @@ -1,16 +1,15 @@ -// Copyright (c) 2010 The Chromium Authors. All rights reserved. +// 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. #include "base/debug/trace_event.h" +#if defined(OS_WIN) +#include "base/debug/trace_event_win.h" +#endif #include "base/format_macros.h" -#include "base/file_path.h" -#include "base/file_util.h" -#include "base/path_service.h" #include "base/process_util.h" #include "base/stringprintf.h" -#include "base/threading/platform_thread.h" #include "base/utf_string_conversions.h" #include "base/time.h" @@ -19,149 +18,368 @@ namespace base { namespace debug { -static const char* kEventTypeNames[] = { - "BEGIN", - "END", - "INSTANT" +// Controls the number of trace events we will buffer in-memory +// before throwing them away. +const size_t kTraceEventBufferSize = 500000; +const size_t kTraceEventBatchSize = 1000; + +#define TRACE_EVENT_MAX_CATEGORIES 42 + +static TraceCategory g_categories[TRACE_EVENT_MAX_CATEGORIES] = { + { "tracing already shutdown", false }, + { "tracing categories exhausted; must increase TRACE_EVENT_MAX_CATEGORIES", + false } }; +static const TraceCategory* const g_category_already_shutdown = + &g_categories[0]; +static const TraceCategory* const g_category_categories_exhausted = + &g_categories[1]; +static int g_category_index = 2; // skip initial 2 error categories -static const FilePath::CharType* kLogFileName = - FILE_PATH_LITERAL("trace_%d.log"); +//////////////////////////////////////////////////////////////////////////////// +// +// TraceValue +// +//////////////////////////////////////////////////////////////////////////////// -// static -TraceLog* TraceLog::GetInstance() { - return Singleton<TraceLog, DefaultSingletonTraits<TraceLog> >::get(); +void TraceValue::Destroy() { + if (type_ == TRACE_TYPE_STRING) { + value_.as_string_refptr->Release(); + value_.as_string_refptr = NULL; + } + type_ = TRACE_TYPE_UNDEFINED; + value_.as_uint = 0ull; } -// static -bool TraceLog::IsTracing() { - return TraceLog::GetInstance()->enabled_; +TraceValue& TraceValue::operator=(const TraceValue& rhs) { + if (this == &rhs) + return *this; + + Destroy(); + + type_ = rhs.type_; + switch(type_) { + case TRACE_TYPE_UNDEFINED: + return *this; + case TRACE_TYPE_BOOL: + value_.as_bool = rhs.value_.as_bool; + return *this; + case TRACE_TYPE_UINT: + value_.as_uint = rhs.value_.as_uint; + return *this; + case TRACE_TYPE_INT: + value_.as_int = rhs.value_.as_int; + return *this; + case TRACE_TYPE_DOUBLE: + value_.as_double = rhs.value_.as_double; + return *this; + case TRACE_TYPE_POINTER: + value_.as_pointer = rhs.value_.as_pointer; + return *this; + case TRACE_TYPE_STRING: + value_.as_string_refptr = rhs.value_.as_string_refptr; + value_.as_string_refptr->AddRef(); + return *this; + default: + NOTREACHED(); + return *this; + } } -// static -bool TraceLog::StartTracing() { - return TraceLog::GetInstance()->Start(); +void TraceValue::AppendAsJSON(std::string* out) const { + char temp_string[128]; + std::string::size_type start_pos; + switch (type_) { + case TRACE_TYPE_BOOL: + *out += as_bool()? "true" : "false"; + break; + case TRACE_TYPE_UINT: + base::snprintf(temp_string, arraysize(temp_string), "%llu", + static_cast<unsigned long long>(as_uint())); + *out += temp_string; + break; + case TRACE_TYPE_INT: + base::snprintf(temp_string, arraysize(temp_string), "%lld", + static_cast<long long>(as_int())); + *out += temp_string; + break; + case TRACE_TYPE_DOUBLE: + base::snprintf(temp_string, arraysize(temp_string), "%f", as_double()); + *out += temp_string; + break; + case TRACE_TYPE_POINTER: + base::snprintf(temp_string, arraysize(temp_string), "%llu", + static_cast<unsigned long long>( + reinterpret_cast<intptr_t>( + as_pointer()))); + *out += temp_string; + break; + case TRACE_TYPE_STRING: + *out += "\""; + start_pos = out->size(); + *out += as_string(); + // replace " character with ' + while ((start_pos = out->find_first_of('\"', start_pos)) != + std::string::npos) + (*out)[start_pos] = '\''; + *out += "\""; + break; + default: + NOTREACHED() << "Don't know how to print this value"; + break; + } } -// static -void TraceLog::StopTracing() { - return TraceLog::GetInstance()->Stop(); +//////////////////////////////////////////////////////////////////////////////// +// +// TraceEvent +// +//////////////////////////////////////////////////////////////////////////////// + +namespace { + +const char* GetPhaseStr(TraceEventPhase phase) { + switch(phase) { + case TRACE_EVENT_PHASE_BEGIN: + return "B"; + case TRACE_EVENT_PHASE_INSTANT: + return "I"; + case TRACE_EVENT_PHASE_END: + return "E"; + default: + NOTREACHED() << "Invalid phase argument"; + return "?"; + } } -void TraceLog::Trace(const std::string& name, - EventType type, - const void* id, - const std::wstring& extra, - const char* file, - int line) { - if (!enabled_) - return; - Trace(name, type, id, WideToUTF8(extra), file, line); +} // namespace + +TraceEvent::TraceEvent() + : process_id(0), + thread_id(0), + phase(TRACE_EVENT_PHASE_BEGIN), + category(NULL), + name(NULL) { + memset(arg_names, 0, sizeof(arg_names)); } -void TraceLog::Trace(const std::string& name, - EventType type, - const void* id, - const std::string& extra, - const char* file, - int line) { - if (!enabled_) - return; +TraceEvent::~TraceEvent() { +} -#ifdef USE_UNRELIABLE_NOW - TimeTicks tick = TimeTicks::HighResNow(); -#else - TimeTicks tick = TimeTicks::Now(); -#endif - TimeDelta delta = tick - trace_start_time_; - int64 usec = delta.InMicroseconds(); - std::string msg = - StringPrintf("{'pid':'0x%lx', 'tid':'0x%lx', 'type':'%s', " - "'name':'%s', 'id':'%p', 'extra':'%s', 'file':'%s', " - "'line_number':'%d', 'usec_begin': %" PRId64 "},\n", - static_cast<unsigned long>(base::GetCurrentProcId()), - static_cast<unsigned long>(PlatformThread::CurrentId()), - kEventTypeNames[type], - name.c_str(), - id, - extra.c_str(), - file, - line, - usec); - - Log(msg); -} - -TraceLog::TraceLog() : enabled_(false), log_file_(NULL) { - base::ProcessHandle proc = base::GetCurrentProcessHandle(); -#if !defined(OS_MACOSX) - process_metrics_.reset(base::ProcessMetrics::CreateProcessMetrics(proc)); -#else - // The default port provider is sufficient to get data for the current - // process. - process_metrics_.reset(base::ProcessMetrics::CreateProcessMetrics(proc, - NULL)); -#endif +void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events, + size_t start, + size_t count, + std::string* out) { + *out += "["; + for (size_t i = 0; i < count && start + i < events.size(); ++i) { + if (i > 0) + *out += ","; + events[i + start].AppendAsJSON(out); + } + *out += "]"; } -TraceLog::~TraceLog() { - Stop(); -} - -bool TraceLog::OpenLogFile() { - FilePath::StringType pid_filename = - StringPrintf(kLogFileName, base::GetCurrentProcId()); - FilePath log_file_path; - if (!PathService::Get(base::DIR_EXE, &log_file_path)) - return false; - log_file_path = log_file_path.Append(pid_filename); - log_file_ = file_util::OpenFile(log_file_path, "a"); - if (!log_file_) { - // try the current directory - log_file_ = file_util::OpenFile(FilePath(pid_filename), "a"); - if (!log_file_) { - return false; - } +void TraceEvent::AppendAsJSON(std::string* out) const { + const char* phase_str = GetPhaseStr(phase); + int64 time_int64 = timestamp.ToInternalValue(); + // Category name checked at category creation time. + DCHECK(!strchr(name, '"')); + StringAppendF(out, + "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%lld," + "\"ph\":\"%s\",\"name\":\"%s\",\"args\":{", + category->name, + static_cast<int>(process_id), + static_cast<int>(thread_id), + static_cast<long long>(time_int64), + phase_str, + name); + + // Output argument names and values, stop at first NULL argument name. + for (size_t i = 0; i < kTraceMaxNumArgs && arg_names[i]; ++i) { + if (i > 0) + *out += ","; + *out += "\""; + *out += arg_names[i]; + *out += "\":"; + arg_values[i].AppendAsJSON(out); } - return true; + *out += "}}"; +} + +//////////////////////////////////////////////////////////////////////////////// +// +// TraceLog +// +//////////////////////////////////////////////////////////////////////////////// + +// static +TraceLog* TraceLog::GetInstance() { + return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get(); +} + +TraceLog::TraceLog() + : enabled_(false) { + logged_events_.reserve(1024); } -void TraceLog::CloseLogFile() { - if (log_file_) { - file_util::CloseFile(log_file_); +TraceLog::~TraceLog() { +} + +const TraceCategory* TraceLog::GetCategory(const char* name) { + TraceLog* tracelog = GetInstance(); + if (!tracelog){ + CHECK(!g_category_already_shutdown->enabled); + return g_category_already_shutdown; } + return tracelog->GetCategoryInternal(name); } -bool TraceLog::Start() { - if (enabled_) - return true; - enabled_ = OpenLogFile(); - if (enabled_) { - Log("var raw_trace_events = [\n"); - trace_start_time_ = TimeTicks::Now(); - timer_.Start(TimeDelta::FromMilliseconds(250), this, &TraceLog::Heartbeat); +const TraceCategory* TraceLog::GetCategoryInternal(const char* name) { + AutoLock lock(lock_); + DCHECK(!strchr(name, '"')) << "Names may not contain double quote char"; + + // Search for pre-existing category matching this name + for (int i = 0; i < g_category_index; i++) { + if (strcmp(g_categories[i].name, name) == 0) + return &g_categories[i]; } - return enabled_; + + // Create a new category + DCHECK(g_category_index < TRACE_EVENT_MAX_CATEGORIES) << + "must increase TRACE_EVENT_MAX_CATEGORIES"; + if (g_category_index < TRACE_EVENT_MAX_CATEGORIES) { + int new_index = g_category_index++; + g_categories[new_index].name = name; + DCHECK(!g_categories[new_index].enabled); + g_categories[new_index].enabled = enabled_; + return &g_categories[new_index]; + } else { + return g_category_categories_exhausted; + } +} + +void TraceLog::SetEnabled(bool enabled) { + { + AutoLock lock(lock_); + if (enabled == enabled_) + return; + enabled_ = enabled; + for (int i = 0; i < g_category_index; i++) { + //TODO(scheib): If changed to enable specific categories instead of all + // check GetCategoryInternal creation code that users TraceLog::enabled_ + g_categories[i].enabled = enabled; + } + } // release lock + if (!enabled) + Flush(); +} + +float TraceLog::GetBufferPercentFull() const { + return (float)((double)logged_events_.size()/(double)kTraceEventBufferSize); +} + +void TraceLog::SetOutputCallback(const TraceLog::OutputCallback& cb) { + AutoLock lock(lock_); + output_callback_ = cb; + logged_events_.clear(); +} + +void TraceLog::SetBufferFullCallback(const TraceLog::BufferFullCallback& cb) { + AutoLock lock(lock_); + buffer_full_callback_ = cb; } -void TraceLog::Stop() { - if (enabled_) { - enabled_ = false; - Log("];\n"); - CloseLogFile(); - timer_.Stop(); +void TraceLog::Flush() { + std::vector<TraceEvent> previous_logged_events; + OutputCallback output_callback_copy; + { + AutoLock lock(lock_); + previous_logged_events.swap(logged_events_); + output_callback_copy = output_callback_; + } // release lock + + if (output_callback_copy.is_null()) + return; + + for (size_t i = 0; + i < previous_logged_events.size(); + i += kTraceEventBatchSize) { + scoped_refptr<RefCountedString> json_events_str_ptr = + new RefCountedString(); + TraceEvent::AppendEventsAsJSON(previous_logged_events, + i, + kTraceEventBatchSize, + &(json_events_str_ptr->data)); + output_callback_copy.Run(json_events_str_ptr.get()); } } -void TraceLog::Heartbeat() { - std::string cpu = StringPrintf("%.0f", process_metrics_->GetCPUUsage()); - TRACE_EVENT_INSTANT("heartbeat.cpu", 0, cpu); +void TraceLog::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) { + DCHECK(file && name); +#ifdef USE_UNRELIABLE_NOW + TimeTicks now = TimeTicks::HighResNow(); +#else + TimeTicks now = TimeTicks::Now(); +#endif + BufferFullCallback buffer_full_callback_copy; + { + AutoLock lock(lock_); + if (!enabled_ || !category->enabled) + return; + if (logged_events_.size() >= kTraceEventBufferSize) + return; + logged_events_.push_back(TraceEvent()); + TraceEvent& event = logged_events_.back(); + event.process_id = static_cast<unsigned long>(base::GetCurrentProcId()); + event.thread_id = PlatformThread::CurrentId(); + event.timestamp = now; + event.phase = phase; + event.category = category; + event.name = name; + event.arg_names[0] = arg1_name; + event.arg_values[0] = arg1_val; + event.arg_names[1] = arg2_name; + event.arg_values[1] = arg2_val; + COMPILE_ASSERT(kTraceMaxNumArgs == 2, TraceEvent_arg_count_out_of_sync); + + if (logged_events_.size() == kTraceEventBufferSize) { + buffer_full_callback_copy = buffer_full_callback_; + } + } // release lock + + if (!buffer_full_callback_copy.is_null()) + buffer_full_callback_copy.Run(); } -void TraceLog::Log(const std::string& msg) { - AutoLock lock(file_lock_); +void TraceLog::AddTraceEventEtw(TraceEventPhase phase, + const char* file, int line, + const char* name, + const void* id, + const char* extra) { + // Legacy trace points on windows called to ETW +#if defined(OS_WIN) + TraceEventETWProvider::Trace(name, phase, id, extra); +#endif + + // Also add new trace event behavior + static const TraceCategory* category = GetCategory("ETW Trace Event"); + if (category->enabled) { + TraceLog* tracelog = TraceLog::GetInstance(); + if (!tracelog) + return; + tracelog->AddTraceEvent(phase, file, line, category, name, + "id", id, + "extra", extra ? extra : ""); + } +} - fprintf(log_file_, "%s", msg.c_str()); +void TraceLog::Resurrect() { + StaticMemorySingletonTraits<TraceLog>::Resurrect(); } } // namespace debug diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h index 3b4afc5..9476d71 100644 --- a/base/debug/trace_event.h +++ b/base/debug/trace_event.h @@ -2,15 +2,40 @@ // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. -// Trace events to track application performance. Events consist of a name -// a type (BEGIN, END or INSTANT), a tracking id and extra string data. -// In addition, the current process id, thread id, a timestamp down to the -// microsecond and a file and line number of the calling location. +// Trace events are for tracking application performance. // -// The current implementation logs these events into a log file of the form -// trace_<pid>.log where it's designed to be post-processed to generate a -// trace report. In the future, it may use another mechansim to facilitate -// real-time analysis. +// 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. #ifndef BASE_DEBUG_TRACE_EVENT_H_ #define BASE_DEBUG_TRACE_EVENT_H_ @@ -18,132 +43,401 @@ #include "build/build_config.h" -#if defined(OS_WIN) -// On Windows we always pull in an alternative implementation -// which logs to Event Tracing for Windows. -// -// Note that the Windows implementation is always enabled, irrespective the -// value of the CHROMIUM_ENABLE_TRACE_EVENT define. The Windows implementation -// is controlled by Event Tracing for Windows, which will turn tracing on only -// if there is someone listening for the events it generates. -#include "base/debug/trace_event_win.h" -#else // defined(OS_WIN) - #include <string> +#include <vector> -#include "base/memory/scoped_ptr.h" +#include "base/callback.h" #include "base/memory/singleton.h" -#include "base/synchronization/lock.h" -#include "base/time.h" +#include "base/string_util.h" #include "base/timer.h" -#ifndef CHROMIUM_ENABLE_TRACE_EVENT -#define TRACE_EVENT_BEGIN(name, id, extra) ((void) 0) -#define TRACE_EVENT_END(name, id, extra) ((void) 0) -#define TRACE_EVENT_INSTANT(name, id, extra) ((void) 0) - -#else // CHROMIUM_ENABLE_TRACE_EVENT -// Use the following macros rather than using the TraceLog class directly as the -// underlying implementation may change in the future. Here's a sample usage: -// TRACE_EVENT_BEGIN("v8.run", documentId, scriptLocation); -// RunScript(script); -// TRACE_EVENT_END("v8.run", documentId, scriptLocation); - -// Record that an event (of name, id) has begun. All BEGIN events should have -// corresponding END events with a matching (name, id). -#define TRACE_EVENT_BEGIN(name, id, extra) \ - base::debug::TraceLog::GetInstance()->Trace( \ - name, \ - base::debug::TraceLog::EVENT_BEGIN, \ - reinterpret_cast<const void*>(id), \ - extra, \ - __FILE__, \ - __LINE__) - -// Record that an event (of name, id) has ended. All END events should have -// corresponding BEGIN events with a matching (name, id). -#define TRACE_EVENT_END(name, id, extra) \ - base::debug::TraceLog::GetInstance()->Trace( \ - name, \ - base::debug::TraceLog::EVENT_END, \ - reinterpret_cast<const void*>(id), \ - extra, \ - __FILE__, \ - __LINE__) - -// Record that an event (of name, id) with no duration has happened. -#define TRACE_EVENT_INSTANT(name, id, extra) \ - base::debug::TraceLog::GetInstance()->Trace( \ - name, \ - base::debug::TraceLog::EVENT_INSTANT, \ - reinterpret_cast<const void*>(id), \ - extra, \ - __FILE__, \ - __LINE__) -#endif // CHROMIUM_ENABLE_TRACE_EVENT +// 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<const void*>(id), extra); -namespace base { +#define TRACE_EVENT_END_ETW(name, id, extra) \ + base::debug::TraceLog::AddTraceEventEtw( \ + base::debug::TRACE_EVENT_PHASE_END, \ + __FILE__, __LINE__, name, reinterpret_cast<const void*>(id), extra); -class ProcessMetrics; +#define TRACE_EVENT_INSTANT_ETW(name, id, extra) \ + base::debug::TraceLog::AddTraceEventEtw( \ + base::debug::TRACE_EVENT_PHASE_INSTANT, \ + __FILE__, __LINE__, name, reinterpret_cast<const void*>(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. +#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) = \ + 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. +#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) = \ + 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. +#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) = \ + 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. +#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) = \ + 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 { -class BASE_API TraceLog { +// 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 EventType { - EVENT_BEGIN, - EVENT_END, - EVENT_INSTANT + 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<std::string> 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<TraceEvent>& 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(); - // Is tracing currently enabled. - static bool IsTracing(); - // Start logging trace events. - static bool StartTracing(); - // Stop logging trace events. - static void StopTracing(); - - // Log a trace event of (name, type, id) with the optional extra string. - void Trace(const std::string& name, - EventType type, - const void* id, - const std::wstring& extra, - const char* file, - int line); - void Trace(const std::string& name, - EventType type, - const void* id, - const std::string& extra, - const char* file, - int line); + // 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<std::string> RefCountedString; + typedef base::Callback<void(RefCountedString*)> 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<void(void)> 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 DefaultSingletonTraits<TraceLog>; + friend struct StaticMemorySingletonTraits<TraceLog>; TraceLog(); ~TraceLog(); - bool OpenLogFile(); - void CloseLogFile(); - bool Start(); - void Stop(); - void Heartbeat(); - void Log(const std::string& msg); + const TraceCategory* GetCategoryInternal(const char* name); + // TODO(nduca): switch to per-thread trace buffers to reduce thread + // synchronization. + Lock lock_; bool enabled_; - FILE* log_file_; - base::Lock file_lock_; - TimeTicks trace_start_time_; - scoped_ptr<base::ProcessMetrics> process_metrics_; - RepeatingTimer<TraceLog> timer_; + OutputCallback output_callback_; + BufferFullCallback buffer_full_callback_; + std::vector<TraceEvent> 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 // defined(OS_WIN) - #endif // BASE_DEBUG_TRACE_EVENT_H_ diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc new file mode 100644 index 0000000..360468d --- /dev/null +++ b/base/debug/trace_event_unittest.cc @@ -0,0 +1,397 @@ +// 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. + +#include "base/debug/trace_event.h" + +#include "base/bind.h" +#include "base/command_line.h" +#include "base/json/json_reader.h" +#include "base/json/json_writer.h" +#include "base/memory/scoped_ptr.h" +#include "base/stringprintf.h" +#include "base/synchronization/waitable_event.h" +#include "base/threading/thread.h" +#include "base/values.h" +#include "testing/gmock/include/gmock/gmock.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace base { +namespace debug { + +namespace { + +class TraceEventTestFixture : public testing::Test { + public: + void ManualTestSetUp(); + void OnTraceDataCollected(TraceLog::RefCountedString* json_events_str); + + std::string trace_string_; + ListValue trace_parsed_; + + private: + // We want our singleton torn down after each test. + ShadowingAtExitManager at_exit_manager_; +}; + +void TraceEventTestFixture::ManualTestSetUp() { + TraceLog::Resurrect(); + TraceLog* tracelog = TraceLog::GetInstance(); + ASSERT_TRUE(tracelog); + ASSERT_FALSE(tracelog->IsEnabled()); + tracelog->SetOutputCallback( + base::Bind(&TraceEventTestFixture::OnTraceDataCollected, + base::Unretained(this))); +} + +void TraceEventTestFixture::OnTraceDataCollected( + TraceLog::RefCountedString* json_events_str) { + trace_string_ += json_events_str->data; + + scoped_ptr<Value> root; + root.reset(base::JSONReader::Read(json_events_str->data, false)); + + ListValue* root_list = NULL; + ASSERT_TRUE(root.get()); + ASSERT_TRUE(root->GetAsList(&root_list)); + + // Move items into our aggregate collection + while (root_list->GetSize()) { + Value* item = NULL; + root_list->Remove(0, &item); + trace_parsed_.Append(item); + } +} + +bool IsStringInDict(const char* string_to_match, DictionaryValue* dict) { + for (DictionaryValue::key_iterator ikey = dict->begin_keys(); + ikey != dict->end_keys(); ++ikey) { + Value* child = NULL; + if (!dict->GetWithoutPathExpansion(*ikey, &child)) + continue; + + if ((*ikey).find(string_to_match) != std::string::npos) + return true; + + std::string value_str; + child->GetAsString(&value_str); + if (value_str.find(string_to_match) != std::string::npos) + return true; + } + + // Recurse to test arguments + DictionaryValue* args_dict = NULL; + dict->GetDictionary("args", &args_dict); + if (args_dict) + return IsStringInDict(string_to_match, args_dict); + + return false; +} + +DictionaryValue* FindTraceEntry(const ListValue& trace_parsed, + const char *string_to_match, + DictionaryValue* match_after_this_item = NULL) { + // Scan all items + size_t trace_parsed_count = trace_parsed.GetSize(); + for (size_t i = 0; i < trace_parsed_count; i++) { + Value* value = NULL; + trace_parsed.Get(i, &value); + if (match_after_this_item) { + if (value == match_after_this_item) + match_after_this_item = NULL; + continue; + } + if (!value || value->GetType() != Value::TYPE_DICTIONARY) + continue; + DictionaryValue* dict = static_cast<DictionaryValue*>(value); + + if (IsStringInDict(string_to_match, dict)) + return dict; + } + return NULL; +} + +void DataCapturedCallTraces(WaitableEvent* task_complete_event) { + { + TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 1122, "extrastring1"); + TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 3344, "extrastring2"); + TRACE_EVENT_INSTANT_ETW("TRACE_EVENT_INSTANT_ETW call", + 5566, "extrastring3"); + + TRACE_EVENT0("all", "TRACE_EVENT0 call"); + TRACE_EVENT1("all", "TRACE_EVENT1 call", "name1", "value1"); + TRACE_EVENT2("all", "TRACE_EVENT2 call", + "name1", "value1", + "name2", "value2"); + + TRACE_EVENT_INSTANT0("all", "TRACE_EVENT_INSTANT0 call"); + TRACE_EVENT_INSTANT1("all", "TRACE_EVENT_INSTANT1 call", "name1", "value1"); + TRACE_EVENT_INSTANT2("all", "TRACE_EVENT_INSTANT2 call", + "name1", "value1", + "name2", "value2"); + + TRACE_EVENT_BEGIN0("all", "TRACE_EVENT_BEGIN0 call"); + TRACE_EVENT_BEGIN1("all", "TRACE_EVENT_BEGIN1 call", "name1", "value1"); + TRACE_EVENT_BEGIN2("all", "TRACE_EVENT_BEGIN2 call", + "name1", "value1", + "name2", "value2"); + + TRACE_EVENT_END0("all", "TRACE_EVENT_END0 call"); + TRACE_EVENT_END1("all", "TRACE_EVENT_END1 call", "name1", "value1"); + TRACE_EVENT_END2("all", "TRACE_EVENT_END2 call", + "name1", "value1", + "name2", "value2"); + } // Scope close causes TRACE_EVENT0 etc to send their END events. + + if (task_complete_event) + task_complete_event->Signal(); +} + +void DataCapturedValidateTraces(const ListValue& trace_parsed, + const std::string& trace_string) { + DictionaryValue* item = NULL; + +#define EXPECT_FIND_(string) \ + EXPECT_TRUE((item = FindTraceEntry(trace_parsed, string))); +#define EXPECT_NOT_FIND_(string) \ + EXPECT_FALSE((item = FindTraceEntry(trace_parsed, string))); +#define EXPECT_SUB_FIND_(string) \ + if (item) EXPECT_TRUE((IsStringInDict(string, item))); + + EXPECT_FIND_("ETW Trace Event"); + EXPECT_FIND_("all"); + EXPECT_FIND_("TRACE_EVENT_BEGIN_ETW call"); + { + int int_val = 0; + EXPECT_TRUE(item && item->GetInteger("args.id", &int_val)); + EXPECT_EQ(1122, int_val); + } + EXPECT_SUB_FIND_("extrastring1"); + EXPECT_FIND_("TRACE_EVENT_END_ETW call"); + EXPECT_FIND_("TRACE_EVENT_INSTANT_ETW call"); + EXPECT_FIND_("TRACE_EVENT0 call"); + { + std::string ph_begin; + std::string ph_end; + EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call"))); + EXPECT_TRUE((item && item->GetString("ph", &ph_begin))); + EXPECT_TRUE((item = FindTraceEntry(trace_parsed, "TRACE_EVENT0 call", + item))); + EXPECT_TRUE((item && item->GetString("ph", &ph_end))); + EXPECT_EQ("B", ph_begin); + EXPECT_EQ("E", ph_end); + } + EXPECT_FIND_("TRACE_EVENT1 call"); + EXPECT_FIND_("TRACE_EVENT2 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_SUB_FIND_("name2"); + EXPECT_SUB_FIND_("value2"); + EXPECT_FIND_("TRACE_EVENT_INSTANT0 call"); + EXPECT_FIND_("TRACE_EVENT_INSTANT1 call"); + EXPECT_FIND_("TRACE_EVENT_INSTANT2 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_SUB_FIND_("name2"); + EXPECT_SUB_FIND_("value2"); + EXPECT_FIND_("TRACE_EVENT_BEGIN0 call"); + EXPECT_FIND_("TRACE_EVENT_BEGIN1 call"); + EXPECT_FIND_("TRACE_EVENT_BEGIN2 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_SUB_FIND_("name2"); + EXPECT_SUB_FIND_("value2"); + EXPECT_FIND_("TRACE_EVENT_END0 call"); + EXPECT_FIND_("TRACE_EVENT_END1 call"); + EXPECT_FIND_("TRACE_EVENT_END2 call"); + EXPECT_SUB_FIND_("name1"); + EXPECT_SUB_FIND_("value1"); + EXPECT_SUB_FIND_("name2"); + EXPECT_SUB_FIND_("value2"); +} + +} // namespace + +// Simple Test for emitting data and validating it was received. +TEST_F(TraceEventTestFixture, DataCaptured) { + ManualTestSetUp(); + TraceLog::GetInstance()->SetEnabled(true); + + DataCapturedCallTraces(NULL); + + TraceLog::GetInstance()->SetEnabled(false); + + DataCapturedValidateTraces(trace_parsed_, trace_string_); +} + +// Test that data sent from other threads is gathered +TEST_F(TraceEventTestFixture, DataCapturedOnThread) { + ManualTestSetUp(); + TraceLog::GetInstance()->SetEnabled(true); + + Thread thread("1"); + WaitableEvent task_complete_event(false, false); + thread.Start(); + + thread.message_loop()->PostTask( + FROM_HERE, NewRunnableFunction(&DataCapturedCallTraces, + &task_complete_event)); + task_complete_event.Wait(); + + TraceLog::GetInstance()->SetEnabled(false); + thread.Stop(); + DataCapturedValidateTraces(trace_parsed_, trace_string_); +} + +namespace { + +void DataCapturedCallManyTraces(int thread_id, int num_events, + WaitableEvent* task_complete_event) { + for (int i = 0; i < num_events; i++) { + TRACE_EVENT_INSTANT2("all", "multi thread event", + "thread", thread_id, + "event", i); + } + + if (task_complete_event) + task_complete_event->Signal(); +} + +void DataCapturedValidateManyTraces(const ListValue& trace_parsed, + const std::string& trace_string, + int num_threads, int num_events) { + std::map<int, std::map<int, bool> > results; + + size_t trace_parsed_count = trace_parsed.GetSize(); + for (size_t i = 0; i < trace_parsed_count; i++) { + Value* value = NULL; + trace_parsed.Get(i, &value); + if (!value || value->GetType() != Value::TYPE_DICTIONARY) + continue; + DictionaryValue* dict = static_cast<DictionaryValue*>(value); + std::string name; + dict->GetString("name", &name); + if (name != "multi thread event") + continue; + + int thread = 0; + int event = 0; + EXPECT_TRUE(dict->GetInteger("args.thread", &thread)); + EXPECT_TRUE(dict->GetInteger("args.event", &event)); + results[thread][event] = true; + } + + EXPECT_FALSE(results[-1][-1]); + for (int thread = 0; thread < num_threads; thread++) { + for (int event = 0; event < num_events; event++) { + EXPECT_TRUE(results[thread][event]); + } + } +} + +} // namespace + +// Test that data sent from multiple threads is gathered +TEST_F(TraceEventTestFixture, DataCapturedManyThreads) { + ManualTestSetUp(); + TraceLog::GetInstance()->SetEnabled(true); + + const int num_threads = 4; + const int num_events = 4000; + Thread* threads[num_threads]; + WaitableEvent* task_complete_events[num_threads]; + for (int i = 0; i < num_threads; i++) { + threads[i] = new Thread(StringPrintf("Thread %d", i).c_str()); + task_complete_events[i] = new WaitableEvent(false, false); + threads[i]->Start(); + threads[i]->message_loop()->PostTask( + FROM_HERE, NewRunnableFunction(&DataCapturedCallManyTraces, + i, num_events, task_complete_events[i])); + } + + for (int i = 0; i < num_threads; i++) { + task_complete_events[i]->Wait(); + } + + TraceLog::GetInstance()->SetEnabled(false); + + for (int i = 0; i < num_threads; i++) { + threads[i]->Stop(); + delete threads[i]; + delete task_complete_events[i]; + } + + DataCapturedValidateManyTraces(trace_parsed_, trace_string_, + num_threads, num_events); +} + +void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) { + TRACE_EVENT0("category name1", name_str); + TRACE_EVENT_INSTANT0("category name2", name_str); + TRACE_EVENT_BEGIN0("category name3", name_str); + TRACE_EVENT_END0("category name4", name_str); +} + +// Test trace calls made after tracing singleton shut down. +// +// The singleton is destroyed by our base::AtExitManager, but there can be +// code still executing as the C++ static objects are destroyed. This test +// forces the singleton to destroy early, and intentinally makes trace calls +// afterwards. +TEST_F(TraceEventTestFixture, AtExit) { + // Repeat this test a few times. Besides just showing robustness, it also + // allows us to test that events at shutdown do not appear with valid events + // recorded after the system is started again. + for (int i = 0; i < 4; i++) { + // Scope to contain the then destroy the TraceLog singleton. + { + base::ShadowingAtExitManager exit_manager_will_destroy_singletons; + + // Setup TraceLog singleton inside this test's exit manager scope + // so that it will be destroyed when this scope closes. + ManualTestSetUp(); + + TRACE_EVENT_INSTANT0("all", "not recorded; system not enabled"); + + TraceLog::GetInstance()->SetEnabled(true); + + TRACE_EVENT_INSTANT0("all", "is recorded 1; system has been enabled"); + // Trace calls that will cache pointers to categories; they're valid here + TraceCallsWithCachedCategoryPointersPointers( + "is recorded 2; system has been enabled"); + + TraceLog::GetInstance()->SetEnabled(false); + } // scope to destroy singleton + ASSERT_FALSE(TraceLog::GetInstance()); + + // Now that singleton is destroyed, check what trace events were recorded + DictionaryValue* item = NULL; + ListValue& trace_parsed = trace_parsed_; + EXPECT_FIND_("is recorded 1"); + EXPECT_FIND_("is recorded 2"); + EXPECT_NOT_FIND_("not recorded"); + + // Make additional trace event calls on the shutdown system. They should + // all pass cleanly, but the data not be recorded. We'll verify that next + // time around the loop (the only way to flush the trace buffers). + TRACE_EVENT_BEGIN_ETW("not recorded; system shutdown", 0, NULL); + TRACE_EVENT_END_ETW("not recorded; system shutdown", 0, NULL); + TRACE_EVENT_INSTANT_ETW("not recorded; system shutdown", 0, NULL); + TRACE_EVENT0("all", "not recorded; system shutdown"); + TRACE_EVENT_INSTANT0("all", "not recorded; system shutdown"); + TRACE_EVENT_BEGIN0("all", "not recorded; system shutdown"); + TRACE_EVENT_END0("all", "not recorded; system shutdown"); + + TRACE_EVENT0("new category 0!", "not recorded; system shutdown"); + TRACE_EVENT_INSTANT0("new category 1!", "not recorded; system shutdown"); + TRACE_EVENT_BEGIN0("new category 2!", "not recorded; system shutdown"); + TRACE_EVENT_END0("new category 3!", "not recorded; system shutdown"); + + // Cached categories should be safe to check, and still disable traces + TraceCallsWithCachedCategoryPointersPointers( + "not recorded; system shutdown"); + } +} + +} // namespace debug +} // namespace base diff --git a/base/debug/trace_event_win.cc b/base/debug/trace_event_win.cc index 4929944..bba4713 100644 --- a/base/debug/trace_event_win.cc +++ b/base/debug/trace_event_win.cc @@ -1,7 +1,6 @@ // 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. - #include "base/debug/trace_event_win.h" #include "base/logging.h" @@ -27,24 +26,26 @@ const GUID kTraceEventClass64 = { 0x97be602d, 0x2930, 0x4ac3, 0x80, 0x46, 0xb6, 0x76, 0x3b, 0x63, 0x1d, 0xfe}; -TraceLog::TraceLog() : EtwTraceProvider(kChromeTraceProviderName) { +TraceEventETWProvider::TraceEventETWProvider() : + EtwTraceProvider(kChromeTraceProviderName) { Register(); } -TraceLog* TraceLog::GetInstance() { - return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get(); +TraceEventETWProvider* TraceEventETWProvider::GetInstance() { + return Singleton<TraceEventETWProvider, + StaticMemorySingletonTraits<TraceEventETWProvider> >::get(); } -bool TraceLog::StartTracing() { +bool TraceEventETWProvider::StartTracing() { return true; } -void TraceLog::TraceEvent(const char* name, - size_t name_len, - EventType type, - const void* id, - const char* extra, - size_t extra_len) { +void TraceEventETWProvider::TraceEvent(const char* name, + size_t name_len, + TraceEventPhase type, + const void* id, + const char* extra, + size_t extra_len) { // Make sure we don't touch NULL. if (name == NULL) name = ""; @@ -53,14 +54,14 @@ void TraceLog::TraceEvent(const char* name, EtwEventType etw_type = 0; switch (type) { - case TraceLog::EVENT_BEGIN: + case TRACE_EVENT_PHASE_BEGIN: etw_type = kTraceEventTypeBegin; break; - case TraceLog::EVENT_END: + case TRACE_EVENT_PHASE_END: etw_type = kTraceEventTypeEnd; break; - case TraceLog::EVENT_INSTANT: + case TRACE_EVENT_PHASE_INSTANT: etw_type = kTraceEventTypeInstant; break; @@ -93,13 +94,13 @@ void TraceLog::TraceEvent(const char* name, Log(event.get()); } -void TraceLog::Trace(const char* name, - size_t name_len, - EventType type, - const void* id, - const char* extra, - size_t extra_len) { - TraceLog* provider = TraceLog::GetInstance(); +void TraceEventETWProvider::Trace(const char* name, + size_t name_len, + TraceEventPhase type, + const void* id, + const char* extra, + size_t extra_len) { + TraceEventETWProvider* provider = TraceEventETWProvider::GetInstance(); if (provider && provider->IsTracing()) { // Compute the name & extra lengths if not supplied already. if (name_len == -1) @@ -111,8 +112,8 @@ void TraceLog::Trace(const char* name, } } -void TraceLog::Resurrect() { - StaticMemorySingletonTraits<TraceLog>::Resurrect(); +void TraceEventETWProvider::Resurrect() { + StaticMemorySingletonTraits<TraceEventETWProvider>::Resurrect(); } } // namespace debug diff --git a/base/debug/trace_event_win.h b/base/debug/trace_event_win.h index 9049bdb..6e6bcb4 100644 --- a/base/debug/trace_event_win.h +++ b/base/debug/trace_event_win.h @@ -10,29 +10,9 @@ #include <string> #include "base/base_api.h" +#include "base/debug/trace_event.h" #include "base/win/event_trace_provider.h" -#define TRACE_EVENT_BEGIN(name, id, extra) \ - base::debug::TraceLog::Trace( \ - name, \ - base::debug::TraceLog::EVENT_BEGIN, \ - reinterpret_cast<const void*>(id), \ - extra); - -#define TRACE_EVENT_END(name, id, extra) \ - base::debug::TraceLog::Trace( \ - name, \ - base::debug::TraceLog::EVENT_END, \ - reinterpret_cast<const void*>(id), \ - extra); - -#define TRACE_EVENT_INSTANT(name, id, extra) \ - base::debug::TraceLog::Trace( \ - name, \ - base::debug::TraceLog::EVENT_INSTANT, \ - reinterpret_cast<const void*>(id), \ - extra); - // Fwd. template <typename Type> struct StaticMemorySingletonTraits; @@ -42,14 +22,8 @@ namespace debug { // This EtwTraceProvider subclass implements ETW logging // for the macros above on Windows. -class BASE_API TraceLog : public base::win::EtwTraceProvider { +class BASE_API TraceEventETWProvider : public base::win::EtwTraceProvider { public: - enum EventType { - EVENT_BEGIN, - EVENT_END, - EVENT_INSTANT - }; - // Start logging trace events. // This is a noop in this implementation. static bool StartTracing(); @@ -63,14 +37,14 @@ class BASE_API TraceLog : public base::win::EtwTraceProvider { // be used for length. static void Trace(const char* name, size_t name_len, - EventType type, + TraceEventPhase type, const void* id, const char* extra, size_t extra_len); // Allows passing extra as a std::string for convenience. static void Trace(const char* name, - EventType type, + TraceEventPhase type, const void* id, const std::string& extra) { return Trace(name, -1, type, id, extra.c_str(), extra.length()); @@ -79,7 +53,7 @@ class BASE_API TraceLog : public base::win::EtwTraceProvider { // Allows passing extra as a const char* to avoid constructing temporary // std::string instances where not needed. static void Trace(const char* name, - EventType type, + TraceEventPhase type, const void* id, const char* extra) { return Trace(name, -1, type, id, extra, -1); @@ -87,7 +61,7 @@ class BASE_API TraceLog : public base::win::EtwTraceProvider { // Retrieves the singleton. // Note that this may return NULL post-AtExit processing. - static TraceLog* GetInstance(); + static TraceEventETWProvider* GetInstance(); // Returns true iff tracing is turned on. bool IsTracing() { @@ -101,7 +75,7 @@ class BASE_API TraceLog : public base::win::EtwTraceProvider { // string will be used. void TraceEvent(const char* name, size_t name_len, - EventType type, + TraceEventPhase type, const void* id, const char* extra, size_t extra_len); @@ -112,10 +86,10 @@ class BASE_API TraceLog : public base::win::EtwTraceProvider { private: // Ensure only the provider can construct us. - friend struct StaticMemorySingletonTraits<TraceLog>; - TraceLog(); + friend struct StaticMemorySingletonTraits<TraceEventETWProvider>; + TraceEventETWProvider(); - DISALLOW_COPY_AND_ASSIGN(TraceLog); + DISALLOW_COPY_AND_ASSIGN(TraceEventETWProvider); }; // The ETW trace provider GUID. diff --git a/base/debug/trace_event_win_unittest.cc b/base/debug/trace_event_win_unittest.cc index 4c5ed45..785943e 100644 --- a/base/debug/trace_event_win_unittest.cc +++ b/base/debug/trace_event_win_unittest.cc @@ -1,4 +1,4 @@ -// Copyright (c) 2010 The Chromium Authors. All rights reserved. +// 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. @@ -9,8 +9,11 @@ #include "base/at_exit.h" #include "base/basictypes.h" #include "base/file_util.h" +#include "base/debug/trace_event.h" +#include "base/debug/trace_event_win.h" #include "base/win/event_trace_consumer.h" #include "base/win/event_trace_controller.h" +#include "base/win/event_trace_provider.h" #include "base/win/windows_version.h" #include "testing/gmock/include/gmock/gmock.h" #include "testing/gtest/include/gtest/gtest.h" @@ -84,9 +87,9 @@ class TestEventConsumer: public EtwTraceConsumerBase<TestEventConsumer> { TestEventConsumer* TestEventConsumer::current_ = NULL; -class TraceEventTest: public testing::Test { +class TraceEventWinTest: public testing::Test { public: - TraceEventTest() { + TraceEventWinTest() { } void SetUp() { @@ -103,10 +106,10 @@ class TraceEventTest: public testing::Test { // start the private, in-proc session, but on XP we need the global // session created and the provider enabled before we register our // provider. - TraceLog* tracelog = NULL; + TraceEventETWProvider* tracelog = NULL; if (!is_xp) { - TraceLog::Resurrect(); - tracelog = TraceLog::GetInstance(); + TraceEventETWProvider::Resurrect(); + tracelog = TraceEventETWProvider::GetInstance(); ASSERT_TRUE(tracelog != NULL); ASSERT_FALSE(tracelog->IsTracing()); } @@ -141,8 +144,8 @@ class TraceEventTest: public testing::Test { 0)); if (is_xp) { - TraceLog::Resurrect(); - tracelog = TraceLog::GetInstance(); + TraceEventETWProvider::Resurrect(); + tracelog = TraceEventETWProvider::GetInstance(); } ASSERT_TRUE(tracelog != NULL); EXPECT_TRUE(tracelog->IsTracing()); @@ -204,16 +207,16 @@ class TraceEventTest: public testing::Test { } // namespace -TEST_F(TraceEventTest, TraceLog) { +TEST_F(TraceEventWinTest, TraceLog) { ExpectPlayLog(); // The events should arrive in the same sequence as the expects. InSequence in_sequence; // Full argument version, passing lengths explicitly. - TraceLog::Trace(kName, + TraceEventETWProvider::Trace(kName, strlen(kName), - TraceLog::EVENT_BEGIN, + base::debug::TRACE_EVENT_PHASE_BEGIN, kId, kExtra, strlen(kExtra)); @@ -225,8 +228,8 @@ TEST_F(TraceEventTest, TraceLog) { kExtra, strlen(kExtra)); // Const char* version. - TraceLog::Trace(static_cast<const char*>(kName), - TraceLog::EVENT_END, + TraceEventETWProvider::Trace(static_cast<const char*>(kName), + base::debug::TRACE_EVENT_PHASE_END, kId, static_cast<const char*>(kExtra)); @@ -237,8 +240,8 @@ TEST_F(TraceEventTest, TraceLog) { kExtra, strlen(kExtra)); // std::string extra version. - TraceLog::Trace(static_cast<const char*>(kName), - TraceLog::EVENT_INSTANT, + TraceEventETWProvider::Trace(static_cast<const char*>(kName), + base::debug::TRACE_EVENT_PHASE_INSTANT, kId, std::string(kExtra)); @@ -250,9 +253,9 @@ TEST_F(TraceEventTest, TraceLog) { // Test for sanity on NULL inputs. - TraceLog::Trace(NULL, + TraceEventETWProvider::Trace(NULL, 0, - TraceLog::EVENT_BEGIN, + base::debug::TRACE_EVENT_PHASE_BEGIN, kId, NULL, 0); @@ -263,9 +266,9 @@ TEST_F(TraceEventTest, TraceLog) { kId, kEmpty, 0); - TraceLog::Trace(NULL, + TraceEventETWProvider::Trace(NULL, -1, - TraceLog::EVENT_END, + base::debug::TRACE_EVENT_PHASE_END, kId, NULL, -1); @@ -279,27 +282,27 @@ TEST_F(TraceEventTest, TraceLog) { PlayLog(); } -TEST_F(TraceEventTest, Macros) { +TEST_F(TraceEventWinTest, Macros) { ExpectPlayLog(); // The events should arrive in the same sequence as the expects. InSequence in_sequence; - TRACE_EVENT_BEGIN(kName, kId, kExtra); + TRACE_EVENT_BEGIN_ETW(kName, kId, kExtra); ExpectEvent(kTraceEventClass32, kTraceEventTypeBegin, kName, strlen(kName), kId, kExtra, strlen(kExtra)); - TRACE_EVENT_END(kName, kId, kExtra); + TRACE_EVENT_END_ETW(kName, kId, kExtra); ExpectEvent(kTraceEventClass32, kTraceEventTypeEnd, kName, strlen(kName), kId, kExtra, strlen(kExtra)); - TRACE_EVENT_INSTANT(kName, kId, kExtra); + TRACE_EVENT_INSTANT_ETW(kName, kId, kExtra); ExpectEvent(kTraceEventClass32, kTraceEventTypeInstant, kName, strlen(kName), |