diff options
49 files changed, 1258 insertions, 1391 deletions
diff --git a/base/base.gyp b/base/base.gyp index f629350..868e20e 100644 --- a/base/base.gyp +++ b/base/base.gyp @@ -115,7 +115,6 @@ '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 578e50d..51f50ed 100644 --- a/base/base.gypi +++ b/base/base.gypi @@ -404,6 +404,7 @@ # 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 e1f6061..c219cec 100644 --- a/base/debug/trace_event.cc +++ b/base/debug/trace_event.cc @@ -1,15 +1,16 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2010 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" @@ -18,368 +19,149 @@ namespace base { namespace debug { -// 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 char* kEventTypeNames[] = { + "BEGIN", + "END", + "INSTANT" }; -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 - -//////////////////////////////////////////////////////////////////////////////// -// -// TraceValue -// -//////////////////////////////////////////////////////////////////////////////// - -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; -} - -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; - } -} - -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; - } -} - -//////////////////////////////////////////////////////////////////////////////// -// -// TraceEvent -// -//////////////////////////////////////////////////////////////////////////////// -namespace { +static const FilePath::CharType* kLogFileName = + FILE_PATH_LITERAL("trace_%d.log"); -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 "?"; - } +// static +TraceLog* TraceLog::GetInstance() { + return Singleton<TraceLog, DefaultSingletonTraits<TraceLog> >::get(); } -} // 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)); +// static +bool TraceLog::IsTracing() { + return TraceLog::GetInstance()->enabled_; } -TraceEvent::~TraceEvent() { +// static +bool TraceLog::StartTracing() { + return TraceLog::GetInstance()->Start(); } -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 += "]"; +// static +void TraceLog::StopTracing() { + return TraceLog::GetInstance()->Stop(); } -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); - } - *out += "}}"; +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); } -//////////////////////////////////////////////////////////////////////////////// -// -// TraceLog -// -//////////////////////////////////////////////////////////////////////////////// - -// static -TraceLog* TraceLog::GetInstance() { - return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get(); -} +void TraceLog::Trace(const std::string& name, + EventType type, + const void* id, + const std::string& extra, + const char* file, + int line) { + if (!enabled_) + return; -TraceLog::TraceLog() - : enabled_(false) { - logged_events_.reserve(1024); +#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 } 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; + 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; + } } - return tracelog->GetCategoryInternal(name); + return true; } -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]; - } - - // 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::CloseLogFile() { + if (log_file_) { + file_util::CloseFile(log_file_); } } -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) { - Flush(); - AutoLock lock(lock_); - output_callback_ = cb; -} - -void TraceLog::SetBufferFullCallback(const TraceLog::BufferFullCallback& cb) { - AutoLock lock(lock_); - buffer_full_callback_ = cb; +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); + } + return enabled_; } -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::Stop() { + if (enabled_) { + enabled_ = false; + Log("];\n"); + CloseLogFile(); + timer_.Stop(); } } -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::Heartbeat() { + std::string cpu = StringPrintf("%.0f", process_metrics_->GetCPUUsage()); + TRACE_EVENT_INSTANT("heartbeat.cpu", 0, cpu); } -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 : ""); - } -} +void TraceLog::Log(const std::string& msg) { + AutoLock lock(file_lock_); -void TraceLog::Resurrect() { - StaticMemorySingletonTraits<TraceLog>::Resurrect(); + fprintf(log_file_, "%s", msg.c_str()); } } // namespace debug diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h index ef0fb8c..3b4afc5 100644 --- a/base/debug/trace_event.h +++ b/base/debug/trace_event.h @@ -2,40 +2,15 @@ // 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. +// 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. // -// 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. +// 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. #ifndef BASE_DEBUG_TRACE_EVENT_H_ #define BASE_DEBUG_TRACE_EVENT_H_ @@ -43,406 +18,132 @@ #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/callback.h" +#include "base/memory/scoped_ptr.h" #include "base/memory/singleton.h" -#include "base/string_util.h" +#include "base/synchronization/lock.h" +#include "base/time.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<const void*>(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<const void*>(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<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); \ - } +#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 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; +class ProcessMetrics; -// 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 -}; +namespace debug { -// 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 TraceValue { +class BASE_API TraceLog { public: - enum Type { - TRACE_TYPE_UNDEFINED, - TRACE_TYPE_BOOL, - TRACE_TYPE_UINT, - TRACE_TYPE_INT, - TRACE_TYPE_DOUBLE, - TRACE_TYPE_POINTER, - TRACE_TYPE_STRING + enum EventType { + EVENT_BEGIN, + EVENT_END, + EVENT_INSTANT }; - 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); - bool operator!=(const TraceValue& rhs) const { - return !operator==(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; - }; - - bool operator==(const TraceValue& rhs) const; - - 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(); - // 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(); + // 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); private: // This allows constructor and destructor to be private and usable only // by the Singleton class. - friend struct StaticMemorySingletonTraits<TraceLog>; + friend struct DefaultSingletonTraits<TraceLog>; TraceLog(); ~TraceLog(); - const TraceCategory* GetCategoryInternal(const char* name); + bool OpenLogFile(); + void CloseLogFile(); + bool Start(); + void Stop(); + void Heartbeat(); + void Log(const std::string& msg); - // 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<TraceEvent> logged_events_; - - DISALLOW_COPY_AND_ASSIGN(TraceLog); -}; - -namespace internal { - -// Used by TRACE_EVENTx macro. Do not use directly. -class 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_; + FILE* log_file_; + base::Lock file_lock_; + TimeTicks trace_start_time_; + scoped_ptr<base::ProcessMetrics> process_metrics_; + RepeatingTimer<TraceLog> timer_; }; -} // 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 deleted file mode 100644 index 360468d..0000000 --- a/base/debug/trace_event_unittest.cc +++ /dev/null @@ -1,397 +0,0 @@ -// 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 bba4713..4929944 100644 --- a/base/debug/trace_event_win.cc +++ b/base/debug/trace_event_win.cc @@ -1,6 +1,7 @@ // 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" @@ -26,26 +27,24 @@ const GUID kTraceEventClass64 = { 0x97be602d, 0x2930, 0x4ac3, 0x80, 0x46, 0xb6, 0x76, 0x3b, 0x63, 0x1d, 0xfe}; -TraceEventETWProvider::TraceEventETWProvider() : - EtwTraceProvider(kChromeTraceProviderName) { +TraceLog::TraceLog() : EtwTraceProvider(kChromeTraceProviderName) { Register(); } -TraceEventETWProvider* TraceEventETWProvider::GetInstance() { - return Singleton<TraceEventETWProvider, - StaticMemorySingletonTraits<TraceEventETWProvider> >::get(); +TraceLog* TraceLog::GetInstance() { + return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get(); } -bool TraceEventETWProvider::StartTracing() { +bool TraceLog::StartTracing() { return true; } -void TraceEventETWProvider::TraceEvent(const char* name, - size_t name_len, - TraceEventPhase type, - const void* id, - const char* extra, - size_t extra_len) { +void TraceLog::TraceEvent(const char* name, + size_t name_len, + EventType type, + const void* id, + const char* extra, + size_t extra_len) { // Make sure we don't touch NULL. if (name == NULL) name = ""; @@ -54,14 +53,14 @@ void TraceEventETWProvider::TraceEvent(const char* name, EtwEventType etw_type = 0; switch (type) { - case TRACE_EVENT_PHASE_BEGIN: + case TraceLog::EVENT_BEGIN: etw_type = kTraceEventTypeBegin; break; - case TRACE_EVENT_PHASE_END: + case TraceLog::EVENT_END: etw_type = kTraceEventTypeEnd; break; - case TRACE_EVENT_PHASE_INSTANT: + case TraceLog::EVENT_INSTANT: etw_type = kTraceEventTypeInstant; break; @@ -94,13 +93,13 @@ void TraceEventETWProvider::TraceEvent(const char* name, Log(event.get()); } -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(); +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(); if (provider && provider->IsTracing()) { // Compute the name & extra lengths if not supplied already. if (name_len == -1) @@ -112,8 +111,8 @@ void TraceEventETWProvider::Trace(const char* name, } } -void TraceEventETWProvider::Resurrect() { - StaticMemorySingletonTraits<TraceEventETWProvider>::Resurrect(); +void TraceLog::Resurrect() { + StaticMemorySingletonTraits<TraceLog>::Resurrect(); } } // namespace debug diff --git a/base/debug/trace_event_win.h b/base/debug/trace_event_win.h index 6e6bcb4..9049bdb 100644 --- a/base/debug/trace_event_win.h +++ b/base/debug/trace_event_win.h @@ -10,9 +10,29 @@ #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; @@ -22,8 +42,14 @@ namespace debug { // This EtwTraceProvider subclass implements ETW logging // for the macros above on Windows. -class BASE_API TraceEventETWProvider : public base::win::EtwTraceProvider { +class BASE_API TraceLog : 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(); @@ -37,14 +63,14 @@ class BASE_API TraceEventETWProvider : public base::win::EtwTraceProvider { // be used for length. static void Trace(const char* name, size_t name_len, - TraceEventPhase type, + EventType 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, - TraceEventPhase type, + EventType type, const void* id, const std::string& extra) { return Trace(name, -1, type, id, extra.c_str(), extra.length()); @@ -53,7 +79,7 @@ class BASE_API TraceEventETWProvider : 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, - TraceEventPhase type, + EventType type, const void* id, const char* extra) { return Trace(name, -1, type, id, extra, -1); @@ -61,7 +87,7 @@ class BASE_API TraceEventETWProvider : public base::win::EtwTraceProvider { // Retrieves the singleton. // Note that this may return NULL post-AtExit processing. - static TraceEventETWProvider* GetInstance(); + static TraceLog* GetInstance(); // Returns true iff tracing is turned on. bool IsTracing() { @@ -75,7 +101,7 @@ class BASE_API TraceEventETWProvider : public base::win::EtwTraceProvider { // string will be used. void TraceEvent(const char* name, size_t name_len, - TraceEventPhase type, + EventType type, const void* id, const char* extra, size_t extra_len); @@ -86,10 +112,10 @@ class BASE_API TraceEventETWProvider : public base::win::EtwTraceProvider { private: // Ensure only the provider can construct us. - friend struct StaticMemorySingletonTraits<TraceEventETWProvider>; - TraceEventETWProvider(); + friend struct StaticMemorySingletonTraits<TraceLog>; + TraceLog(); - DISALLOW_COPY_AND_ASSIGN(TraceEventETWProvider); + DISALLOW_COPY_AND_ASSIGN(TraceLog); }; // The ETW trace provider GUID. diff --git a/base/debug/trace_event_win_unittest.cc b/base/debug/trace_event_win_unittest.cc index 785943e..4c5ed45 100644 --- a/base/debug/trace_event_win_unittest.cc +++ b/base/debug/trace_event_win_unittest.cc @@ -1,4 +1,4 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2010 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,11 +9,8 @@ #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" @@ -87,9 +84,9 @@ class TestEventConsumer: public EtwTraceConsumerBase<TestEventConsumer> { TestEventConsumer* TestEventConsumer::current_ = NULL; -class TraceEventWinTest: public testing::Test { +class TraceEventTest: public testing::Test { public: - TraceEventWinTest() { + TraceEventTest() { } void SetUp() { @@ -106,10 +103,10 @@ class TraceEventWinTest: 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. - TraceEventETWProvider* tracelog = NULL; + TraceLog* tracelog = NULL; if (!is_xp) { - TraceEventETWProvider::Resurrect(); - tracelog = TraceEventETWProvider::GetInstance(); + TraceLog::Resurrect(); + tracelog = TraceLog::GetInstance(); ASSERT_TRUE(tracelog != NULL); ASSERT_FALSE(tracelog->IsTracing()); } @@ -144,8 +141,8 @@ class TraceEventWinTest: public testing::Test { 0)); if (is_xp) { - TraceEventETWProvider::Resurrect(); - tracelog = TraceEventETWProvider::GetInstance(); + TraceLog::Resurrect(); + tracelog = TraceLog::GetInstance(); } ASSERT_TRUE(tracelog != NULL); EXPECT_TRUE(tracelog->IsTracing()); @@ -207,16 +204,16 @@ class TraceEventWinTest: public testing::Test { } // namespace -TEST_F(TraceEventWinTest, TraceLog) { +TEST_F(TraceEventTest, TraceLog) { ExpectPlayLog(); // The events should arrive in the same sequence as the expects. InSequence in_sequence; // Full argument version, passing lengths explicitly. - TraceEventETWProvider::Trace(kName, + TraceLog::Trace(kName, strlen(kName), - base::debug::TRACE_EVENT_PHASE_BEGIN, + TraceLog::EVENT_BEGIN, kId, kExtra, strlen(kExtra)); @@ -228,8 +225,8 @@ TEST_F(TraceEventWinTest, TraceLog) { kExtra, strlen(kExtra)); // Const char* version. - TraceEventETWProvider::Trace(static_cast<const char*>(kName), - base::debug::TRACE_EVENT_PHASE_END, + TraceLog::Trace(static_cast<const char*>(kName), + TraceLog::EVENT_END, kId, static_cast<const char*>(kExtra)); @@ -240,8 +237,8 @@ TEST_F(TraceEventWinTest, TraceLog) { kExtra, strlen(kExtra)); // std::string extra version. - TraceEventETWProvider::Trace(static_cast<const char*>(kName), - base::debug::TRACE_EVENT_PHASE_INSTANT, + TraceLog::Trace(static_cast<const char*>(kName), + TraceLog::EVENT_INSTANT, kId, std::string(kExtra)); @@ -253,9 +250,9 @@ TEST_F(TraceEventWinTest, TraceLog) { // Test for sanity on NULL inputs. - TraceEventETWProvider::Trace(NULL, + TraceLog::Trace(NULL, 0, - base::debug::TRACE_EVENT_PHASE_BEGIN, + TraceLog::EVENT_BEGIN, kId, NULL, 0); @@ -266,9 +263,9 @@ TEST_F(TraceEventWinTest, TraceLog) { kId, kEmpty, 0); - TraceEventETWProvider::Trace(NULL, + TraceLog::Trace(NULL, -1, - base::debug::TRACE_EVENT_PHASE_END, + TraceLog::EVENT_END, kId, NULL, -1); @@ -282,27 +279,27 @@ TEST_F(TraceEventWinTest, TraceLog) { PlayLog(); } -TEST_F(TraceEventWinTest, Macros) { +TEST_F(TraceEventTest, Macros) { ExpectPlayLog(); // The events should arrive in the same sequence as the expects. InSequence in_sequence; - TRACE_EVENT_BEGIN_ETW(kName, kId, kExtra); + TRACE_EVENT_BEGIN(kName, kId, kExtra); ExpectEvent(kTraceEventClass32, kTraceEventTypeBegin, kName, strlen(kName), kId, kExtra, strlen(kExtra)); - TRACE_EVENT_END_ETW(kName, kId, kExtra); + TRACE_EVENT_END(kName, kId, kExtra); ExpectEvent(kTraceEventClass32, kTraceEventTypeEnd, kName, strlen(kName), kId, kExtra, strlen(kExtra)); - TRACE_EVENT_INSTANT_ETW(kName, kId, kExtra); + TRACE_EVENT_INSTANT(kName, kId, kExtra); ExpectEvent(kTraceEventClass32, kTraceEventTypeInstant, kName, strlen(kName), diff --git a/chrome/app/client_util.cc b/chrome/app/client_util.cc index 55f3d8c..8eaf0bf 100644 --- a/chrome/app/client_util.cc +++ b/chrome/app/client_util.cc @@ -130,9 +130,9 @@ HMODULE LoadChromeWithDirectory(std::wstring* dir) { key.Close(); } if (pre_read) { - TRACE_EVENT_BEGIN_ETW("PreReadImage", 0, ""); + TRACE_EVENT_BEGIN("PreReadImage", 0, ""); file_util::PreReadImage(dir->c_str(), pre_read_size, pre_read_step_size); - TRACE_EVENT_END_ETW("PreReadImage", 0, ""); + TRACE_EVENT_END("PreReadImage", 0, ""); } } #endif // NDEBUG diff --git a/chrome/browser/automation/automation_provider.cc b/chrome/browser/automation/automation_provider.cc index 7f57e31..64eef79 100644 --- a/chrome/browser/automation/automation_provider.cc +++ b/chrome/browser/automation/automation_provider.cc @@ -111,7 +111,7 @@ AutomationProvider::AutomationProvider(Profile* profile) is_connected_(false), initial_tab_loads_complete_(false), network_library_initialized_(true) { - TRACE_EVENT_BEGIN_ETW("AutomationProvider::AutomationProvider", 0, ""); + TRACE_EVENT_BEGIN("AutomationProvider::AutomationProvider", 0, ""); DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); @@ -126,7 +126,7 @@ AutomationProvider::AutomationProvider(Profile* profile) new ExtensionTestResultNotificationObserver(this)); g_browser_process->AddRefModule(); - TRACE_EVENT_END_ETW("AutomationProvider::AutomationProvider", 0, ""); + TRACE_EVENT_END("AutomationProvider::AutomationProvider", 0, ""); } AutomationProvider::~AutomationProvider() { @@ -137,7 +137,7 @@ AutomationProvider::~AutomationProvider() { } bool AutomationProvider::InitializeChannel(const std::string& channel_id) { - TRACE_EVENT_BEGIN_ETW("AutomationProvider::InitializeChannel", 0, ""); + TRACE_EVENT_BEGIN("AutomationProvider::InitializeChannel", 0, ""); channel_id_ = channel_id; std::string effective_channel_id = channel_id; @@ -176,7 +176,7 @@ bool AutomationProvider::InitializeChannel(const std::string& channel_id) { delete observer; #endif - TRACE_EVENT_END_ETW("AutomationProvider::InitializeChannel", 0, ""); + TRACE_EVENT_END("AutomationProvider::InitializeChannel", 0, ""); return true; } diff --git a/chrome/browser/automation/automation_provider_win.cc b/chrome/browser/automation/automation_provider_win.cc index 0a11a49..c764004 100644 --- a/chrome/browser/automation/automation_provider_win.cc +++ b/chrome/browser/automation/automation_provider_win.cc @@ -233,7 +233,7 @@ void AutomationProvider::CreateExternalTab( const ExternalTabSettings& settings, gfx::NativeWindow* tab_container_window, gfx::NativeWindow* tab_window, int* tab_handle, int* session_id) { - TRACE_EVENT_BEGIN_ETW("AutomationProvider::CreateExternalTab", 0, ""); + TRACE_EVENT_BEGIN("AutomationProvider::CreateExternalTab", 0, ""); *tab_handle = 0; *tab_container_window = NULL; @@ -263,7 +263,7 @@ void AutomationProvider::CreateExternalTab( external_tab_container->Uninitialize(); } - TRACE_EVENT_END_ETW("AutomationProvider::CreateExternalTab", 0, ""); + TRACE_EVENT_END("AutomationProvider::CreateExternalTab", 0, ""); } bool AutomationProvider::AddExternalTab(ExternalTabContainer* external_tab) { @@ -374,7 +374,7 @@ void AutomationProvider::ConnectExternalTab( gfx::NativeWindow* tab_window, int* tab_handle, int* session_id) { - TRACE_EVENT_BEGIN_ETW("AutomationProvider::ConnectExternalTab", 0, ""); + TRACE_EVENT_BEGIN("AutomationProvider::ConnectExternalTab", 0, ""); *tab_handle = 0; *tab_container_window = NULL; @@ -401,7 +401,7 @@ void AutomationProvider::ConnectExternalTab( external_tab_container->Uninitialize(); } - TRACE_EVENT_END_ETW("AutomationProvider::ConnectExternalTab", 0, ""); + TRACE_EVENT_END("AutomationProvider::ConnectExternalTab", 0, ""); } void AutomationProvider::OnBrowserMoved(int tab_handle) { diff --git a/chrome/browser/browser_main.cc b/chrome/browser/browser_main.cc index df7664f..6224df9 100644 --- a/chrome/browser/browser_main.cc +++ b/chrome/browser/browser_main.cc @@ -631,7 +631,7 @@ void HandleTestParameters(const CommandLine& command_line) { } void RunUIMessageLoop(BrowserProcess* browser_process) { - TRACE_EVENT_BEGIN_ETW("BrowserMain:MESSAGE_LOOP", 0, ""); + TRACE_EVENT_BEGIN("BrowserMain:MESSAGE_LOOP", 0, ""); // This should be invoked as close to the start of the browser's // UI thread message loop as possible to get a stable measurement // across versions. @@ -654,7 +654,7 @@ void RunUIMessageLoop(BrowserProcess* browser_process) { true); #endif - TRACE_EVENT_END_ETW("BrowserMain:MESSAGE_LOOP", 0, ""); + TRACE_EVENT_END("BrowserMain:MESSAGE_LOOP", 0, ""); } void AddFirstRunNewTabs(BrowserInit* browser_init, @@ -1145,7 +1145,7 @@ bool IsMetricsReportingEnabled(const PrefService* local_state) { // Main routine for running as the Browser process. int BrowserMain(const MainFunctionParams& parameters) { - TRACE_EVENT_BEGIN_ETW("BrowserMain", 0, ""); + TRACE_EVENT_BEGIN("BrowserMain", 0, ""); // If we're running tests (ui_task is non-null). if (parameters.ui_task) @@ -1928,6 +1928,6 @@ int BrowserMain(const MainFunctionParams& parameters) { false); chromeos::BootTimesLoader::Get()->WriteLogoutTimes(); #endif - TRACE_EVENT_END_ETW("BrowserMain", 0, 0); + TRACE_EVENT_END("BrowserMain", 0, 0); return result_code; } diff --git a/chrome/browser/external_tab_container_win.cc b/chrome/browser/external_tab_container_win.cc index 9e5e83d..b8625fe 100644 --- a/chrome/browser/external_tab_container_win.cc +++ b/chrome/browser/external_tab_container_win.cc @@ -730,8 +730,8 @@ void ExternalTabContainer::Observe(NotificationType type, const LoadNotificationDetails* load = Details<LoadNotificationDetails>(details).ptr(); if (load != NULL && PageTransition::IsMainFrame(load->origin())) { - TRACE_EVENT_END_ETW("ExternalTabContainer::Navigate", 0, - load->url().spec()); + TRACE_EVENT_END("ExternalTabContainer::Navigate", 0, + load->url().spec()); automation_->Send(new AutomationMsg_TabLoaded(tab_handle_, load->url())); } @@ -980,7 +980,7 @@ void ExternalTabContainer::Navigate(const GURL& url, const GURL& referrer) { return; } - TRACE_EVENT_BEGIN_ETW("ExternalTabContainer::Navigate", 0, url.spec()); + TRACE_EVENT_BEGIN("ExternalTabContainer::Navigate", 0, url.spec()); tab_contents_->controller().LoadURL(url, referrer, PageTransition::START_PAGE); diff --git a/chrome/chrome_browser.gypi b/chrome/chrome_browser.gypi index 25407e5..9ace239 100644 --- a/chrome/chrome_browser.gypi +++ b/chrome/chrome_browser.gypi @@ -31,6 +31,7 @@ '../build/temp_gyp/googleurl.gyp:googleurl', '../content/content.gyp:content_browser', '../crypto/crypto.gyp:crypto', + '../gpu/gpu.gyp:gpu_common', '../media/media.gyp:media', '../ppapi/ppapi.gyp:ppapi_proxy', # For PpapiMsg_LoadPlugin '../printing/printing.gyp:printing', diff --git a/chrome/common/sandbox_policy.cc b/chrome/common/sandbox_policy.cc index 7399a51..2e11e0b 100644 --- a/chrome/common/sandbox_policy.cc +++ b/chrome/common/sandbox_policy.cc @@ -601,7 +601,7 @@ base::ProcessHandle StartProcessWithAccess(CommandLine* cmd_line, return 0; } - TRACE_EVENT_BEGIN_ETW("StartProcessWithAccess", 0, type_str); + TRACE_EVENT_BEGIN("StartProcessWithAccess", 0, type_str); // To decide if the process is going to be sandboxed we have two cases. // First case: all process types except the nacl broker, and the plugin @@ -708,7 +708,7 @@ base::ProcessHandle StartProcessWithAccess(CommandLine* cmd_line, return 0; } - TRACE_EVENT_BEGIN_ETW("StartProcessWithAccess::LAUNCHPROCESS", 0, 0); + TRACE_EVENT_BEGIN("StartProcessWithAccess::LAUNCHPROCESS", 0, 0); result = g_broker_services->SpawnTarget( cmd_line->GetProgram().value().c_str(), @@ -716,7 +716,7 @@ base::ProcessHandle StartProcessWithAccess(CommandLine* cmd_line, policy, &target); policy->Release(); - TRACE_EVENT_END_ETW("StartProcessWithAccess::LAUNCHPROCESS", 0, 0); + TRACE_EVENT_END("StartProcessWithAccess::LAUNCHPROCESS", 0, 0); if (sandbox::SBOX_ALL_OK != result) return 0; diff --git a/chrome_frame/chrome_active_document.cc b/chrome_frame/chrome_active_document.cc index 0a9d3a9..98c4d76 100644 --- a/chrome_frame/chrome_active_document.cc +++ b/chrome_frame/chrome_active_document.cc @@ -66,7 +66,7 @@ ChromeActiveDocument::ChromeActiveDocument() is_automation_client_reused_(false), popup_allowed_(false), accelerator_table_(NULL) { - TRACE_EVENT_BEGIN_ETW("chromeframe.createactivedocument", this, ""); + TRACE_EVENT_BEGIN("chromeframe.createactivedocument", this, ""); url_fetcher_->set_frame_busting(false); memset(navigation_info_.get(), 0, sizeof(NavigationInfo)); @@ -133,7 +133,7 @@ ChromeActiveDocument::~ChromeActiveDocument() { // ChromeFramePlugin BaseActiveX::Uninitialize(); - TRACE_EVENT_END_ETW("chromeframe.createactivedocument", this, ""); + TRACE_EVENT_END("chromeframe.createactivedocument", this, ""); } // Override DoVerb diff --git a/chrome_frame/chrome_frame_activex.cc b/chrome_frame/chrome_frame_activex.cc index 425cc2f..62bae43 100644 --- a/chrome_frame/chrome_frame_activex.cc +++ b/chrome_frame/chrome_frame_activex.cc @@ -148,7 +148,7 @@ void GetMiniContextMenuData(UINT cmd, ChromeFrameActivex::ChromeFrameActivex() : chrome_wndproc_hook_(NULL) { - TRACE_EVENT_BEGIN_ETW("chromeframe.createactivex", this, ""); + TRACE_EVENT_BEGIN("chromeframe.createactivex", this, ""); } HRESULT ChromeFrameActivex::FinalConstruct() { @@ -177,7 +177,7 @@ ChromeFrameActivex::~ChromeFrameActivex() { // ChromeFramePlugin::Uninitialize() Base::Uninitialize(); - TRACE_EVENT_END_ETW("chromeframe.createactivex", this, ""); + TRACE_EVENT_END("chromeframe.createactivex", this, ""); } LRESULT ChromeFrameActivex::OnCreate(UINT message, WPARAM wparam, LPARAM lparam, diff --git a/chrome_frame/chrome_frame_automation.cc b/chrome_frame/chrome_frame_automation.cc index f0ccbe4..6024972 100644 --- a/chrome_frame/chrome_frame_automation.cc +++ b/chrome_frame/chrome_frame_automation.cc @@ -129,7 +129,7 @@ ChromeFrameAutomationProxyImpl::ChromeFrameAutomationProxyImpl( AutomationProxyCacheEntry* entry, std::string channel_id, int launch_timeout) : AutomationProxy(launch_timeout, false), proxy_entry_(entry) { - TRACE_EVENT_BEGIN_ETW("chromeframe.automationproxy", this, ""); + TRACE_EVENT_BEGIN("chromeframe.automationproxy", this, ""); InitializeChannel(channel_id, false); @@ -142,7 +142,7 @@ ChromeFrameAutomationProxyImpl::ChromeFrameAutomationProxyImpl( } ChromeFrameAutomationProxyImpl::~ChromeFrameAutomationProxyImpl() { - TRACE_EVENT_END_ETW("chromeframe.automationproxy", this, ""); + TRACE_EVENT_END("chromeframe.automationproxy", this, ""); } void ChromeFrameAutomationProxyImpl::SendAsAsync( @@ -354,7 +354,7 @@ void AutomationProxyCacheEntry::CreateProxy(ChromeFrameLaunchParams* params, AUTOMATION_CREATE_TAB_FAILED + 1); } - TRACE_EVENT_END_ETW("chromeframe.createproxy", this, ""); + TRACE_EVENT_END("chromeframe.createproxy", this, ""); // Finally set the proxy. proxy_.reset(proxy); @@ -467,7 +467,7 @@ ProxyFactory::~ProxyFactory() { void ProxyFactory::GetAutomationServer( LaunchDelegate* delegate, ChromeFrameLaunchParams* params, void** automation_server_id) { - TRACE_EVENT_BEGIN_ETW("chromeframe.createproxy", this, ""); + TRACE_EVENT_BEGIN("chromeframe.createproxy", this, ""); scoped_refptr<AutomationProxyCacheEntry> entry; // Find already existing launcher thread for given profile diff --git a/content/browser/gpu_process_host.cc b/content/browser/gpu_process_host.cc index da7b812..df4d9a6 100644 --- a/content/browser/gpu_process_host.cc +++ b/content/browser/gpu_process_host.cc @@ -5,7 +5,6 @@ #include "content/browser/gpu_process_host.h" #include "base/command_line.h" -#include "base/debug/trace_event.h" #include "base/memory/ref_counted.h" #include "base/metrics/histogram.h" #include "base/process_util.h" @@ -19,6 +18,7 @@ #include "content/browser/renderer_host/render_widget_host.h" #include "content/browser/renderer_host/render_widget_host_view.h" #include "content/common/gpu/gpu_messages.h" +#include "gpu/common/gpu_trace_event.h" #include "ipc/ipc_channel_handle.h" #include "ipc/ipc_switches.h" #include "media/base/media_switches.h" @@ -286,7 +286,7 @@ void GpuProcessHost::EstablishGpuChannel( int renderer_id, EstablishChannelCallback *callback) { DCHECK(CalledOnValidThread()); - TRACE_EVENT0("gpu", "GpuProcessHostUIShim::EstablishGpuChannel"); + GPU_TRACE_EVENT0("gpu", "GpuProcessHostUIShim::EstablishGpuChannel"); linked_ptr<EstablishChannelCallback> wrapped_callback(callback); // If GPU features are already blacklisted, no need to establish the channel. diff --git a/content/browser/gpu_process_host_ui_shim.cc b/content/browser/gpu_process_host_ui_shim.cc index f429aa8..e2dc11d 100644 --- a/content/browser/gpu_process_host_ui_shim.cc +++ b/content/browser/gpu_process_host_ui_shim.cc @@ -6,7 +6,6 @@ #include "base/command_line.h" #include "base/id_map.h" -#include "base/debug/trace_event.h" #include "base/process_util.h" #include "chrome/browser/browser_process.h" #include "content/browser/browser_thread.h" @@ -17,6 +16,7 @@ #include "content/browser/renderer_host/render_widget_host_view.h" #include "content/common/content_switches.h" #include "content/common/gpu/gpu_messages.h" +#include "gpu/common/gpu_trace_event.h" #if defined(OS_LINUX) // These two #includes need to come after gpu_messages.h. diff --git a/content/browser/renderer_host/render_widget_host.cc b/content/browser/renderer_host/render_widget_host.cc index 7250dde..339b310 100644 --- a/content/browser/renderer_host/render_widget_host.cc +++ b/content/browser/renderer_host/render_widget_host.cc @@ -6,7 +6,6 @@ #include "base/auto_reset.h" #include "base/command_line.h" -#include "base/debug/trace_event.h" #include "base/message_loop.h" #include "base/metrics/histogram.h" #include "chrome/browser/accessibility/browser_accessibility_state.h" @@ -23,6 +22,7 @@ #include "content/common/notification_service.h" #include "content/common/result_codes.h" #include "content/common/view_messages.h" +#include "gpu/common/gpu_trace_event.h" #include "third_party/WebKit/Source/WebKit/chromium/public/WebCompositionUnderline.h" #include "ui/base/keycodes/keyboard_codes.h" #include "webkit/glue/webcursor.h" @@ -837,7 +837,7 @@ void RenderWidgetHost::OnMsgPaintAtSizeAck(int tag, const gfx::Size& size) { void RenderWidgetHost::OnMsgUpdateRect( const ViewHostMsg_UpdateRect_Params& params) { - TRACE_EVENT0("renderer_host", "RenderWidgetHost::OnMsgUpdateRect"); + GPU_TRACE_EVENT0("renderer_host", "RenderWidgetHost::OnMsgUpdateRect"); TimeTicks paint_start = TimeTicks::Now(); NotificationService::current()->Notify( diff --git a/content/browser/trace_controller.cc b/content/browser/trace_controller.cc index 24e8086..5bf2efa 100644 --- a/content/browser/trace_controller.cc +++ b/content/browser/trace_controller.cc @@ -4,12 +4,11 @@ #include "content/browser/trace_controller.h" -#include "base/bind.h" -#include "base/debug/trace_event.h" #include "base/task.h" #include "content/browser/browser_message_filter.h" #include "content/browser/trace_message_filter.h" #include "content/common/child_process_messages.h" +#include "gpu/common/gpu_trace_event.h" TraceController::TraceController() : @@ -18,14 +17,12 @@ TraceController::TraceController() : pending_bpf_ack_count_(0), maximum_bpf_(0.0f), is_tracing_(false) { - base::debug::TraceLog::GetInstance()->SetOutputCallback( - base::Bind(&TraceController::OnTraceDataCollected, - base::Unretained(this))); + gpu::TraceLog::GetInstance()->SetOutputCallback( + NewCallback(this, &TraceController::OnTraceDataCollected)); } TraceController::~TraceController() { - base::debug::TraceLog::GetInstance()->SetOutputCallback( - base::debug::TraceLog::OutputCallback()); + gpu::TraceLog::GetInstance()->SetOutputCallback(NULL); } //static @@ -44,7 +41,7 @@ bool TraceController::BeginTracing(TraceSubscriber* subscriber) { // Enable tracing is_tracing_ = true; - base::debug::TraceLog::GetInstance()->SetEnabled(true); + gpu::TraceLog::GetInstance()->SetEnabled(true); // Notify all child processes. for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it) { @@ -95,7 +92,7 @@ bool TraceController::GetTraceBufferPercentFullAsync( // Handle special case of zero child processes. if (pending_bpf_ack_count_ == 1) { // Ack asynchronously now, because we don't have any children to wait for. - float bpf = base::debug::TraceLog::GetInstance()->GetBufferPercentFull(); + float bpf = gpu::TraceLog::GetInstance()->GetBufferPercentFull(); BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, NewRunnableMethod(this, &TraceController::OnTraceBufferPercentFullReply, @@ -164,7 +161,7 @@ void TraceController::OnEndTracingAck() { // called with the last of the local trace data. Since we are on the UI // thread, the call to OnTraceDataCollected will be synchronous, so we can // immediately call OnEndTracingComplete below. - base::debug::TraceLog::GetInstance()->SetEnabled(false); + gpu::TraceLog::GetInstance()->SetEnabled(false); // Trigger callback if one is set. if (subscriber_) { @@ -182,21 +179,17 @@ void TraceController::OnEndTracingAck() { } } -void TraceController::OnTraceDataCollected( - const scoped_refptr<base::debug::TraceLog::RefCountedString>& - json_events_str_ptr) { +void TraceController::OnTraceDataCollected(const std::string& data) { // OnTraceDataCollected may be called from any browser thread, either by the // local event trace system or from child processes via TraceMessageFilter. if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) { BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, - NewRunnableMethod(this, - &TraceController::OnTraceDataCollected, - json_events_str_ptr)); + NewRunnableMethod(this, &TraceController::OnTraceDataCollected, data)); return; } if (subscriber_) - subscriber_->OnTraceDataCollected(json_events_str_ptr->data); + subscriber_->OnTraceDataCollected(data); } void TraceController::OnTraceBufferFull() { @@ -236,7 +229,7 @@ void TraceController::OnTraceBufferPercentFullReply(float percent_full) { if (pending_bpf_ack_count_ == 1) { // The last ack represents local trace, so we need to ack it now. Note that // this code only executes if there were child processes. - float bpf = base::debug::TraceLog::GetInstance()->GetBufferPercentFull(); + float bpf = gpu::TraceLog::GetInstance()->GetBufferPercentFull(); BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, NewRunnableMethod(this, &TraceController::OnTraceBufferPercentFullReply, diff --git a/content/browser/trace_controller.h b/content/browser/trace_controller.h index 33e14c6..4308e82 100644 --- a/content/browser/trace_controller.h +++ b/content/browser/trace_controller.h @@ -8,7 +8,6 @@ #include <set> #include <string> -#include "base/debug/trace_event.h" #include "base/memory/ref_counted.h" #include "base/memory/singleton.h" #include "base/task.h" @@ -111,9 +110,7 @@ class TraceController { void AddFilter(TraceMessageFilter* filter); void RemoveFilter(TraceMessageFilter* filter); void OnEndTracingAck(); - void OnTraceDataCollected( - const scoped_refptr<base::debug::TraceLog::RefCountedString>& - json_events_str_ptr); + void OnTraceDataCollected(const std::string& data); void OnTraceBufferFull(); void OnTraceBufferPercentFullReply(float percent_full); diff --git a/content/browser/trace_message_filter.cc b/content/browser/trace_message_filter.cc index a1bd1d0..e23fc26 100644 --- a/content/browser/trace_message_filter.cc +++ b/content/browser/trace_message_filter.cc @@ -82,8 +82,7 @@ void TraceMessageFilter::OnEndTracingAck() { } void TraceMessageFilter::OnTraceDataCollected(const std::string& data) { - TraceController::GetInstance()->OnTraceDataCollected( - make_scoped_refptr(new base::debug::TraceLog::RefCountedString(data))); + TraceController::GetInstance()->OnTraceDataCollected(data); } void TraceMessageFilter::OnTraceBufferFull() { diff --git a/content/common/child_trace_message_filter.cc b/content/common/child_trace_message_filter.cc index 8dfa10b..ccc2b03 100644 --- a/content/common/child_trace_message_filter.cc +++ b/content/common/child_trace_message_filter.cc @@ -4,29 +4,26 @@ #include "content/common/child_trace_message_filter.h" -#include "base/bind.h" -#include "base/debug/trace_event.h" #include "base/message_loop.h" #include "content/common/child_process.h" #include "content/common/child_process_messages.h" +#include "gpu/common/gpu_trace_event.h" ChildTraceMessageFilter::ChildTraceMessageFilter() : channel_(NULL) { } ChildTraceMessageFilter::~ChildTraceMessageFilter() { - base::debug::TraceLog::GetInstance()->SetOutputCallback( - base::debug::TraceLog::OutputCallback()); - base::debug::TraceLog::GetInstance()->SetBufferFullCallback( - base::debug::TraceLog::BufferFullCallback()); + gpu::TraceLog::GetInstance()->SetOutputCallback(NULL); + gpu::TraceLog::GetInstance()->SetBufferFullCallback(NULL); } void ChildTraceMessageFilter::OnFilterAdded(IPC::Channel* channel) { channel_ = channel; - base::debug::TraceLog::GetInstance()->SetOutputCallback( - base::Bind(&ChildTraceMessageFilter::OnTraceDataCollected, this)); - base::debug::TraceLog::GetInstance()->SetBufferFullCallback( - base::Bind(&ChildTraceMessageFilter::OnTraceBufferFull, this)); + gpu::TraceLog::GetInstance()->SetOutputCallback( + NewCallback(this, &ChildTraceMessageFilter::OnTraceDataCollected)); + gpu::TraceLog::GetInstance()->SetBufferFullCallback( + NewCallback(this, &ChildTraceMessageFilter::OnTraceBufferFull)); } bool ChildTraceMessageFilter::OnMessageReceived(const IPC::Message& message) { @@ -42,7 +39,7 @@ bool ChildTraceMessageFilter::OnMessageReceived(const IPC::Message& message) { } void ChildTraceMessageFilter::OnBeginTracing() { - base::debug::TraceLog::GetInstance()->SetEnabled(true); + gpu::TraceLog::GetInstance()->SetEnabled(true); } void ChildTraceMessageFilter::OnEndTracing() { @@ -51,29 +48,26 @@ void ChildTraceMessageFilter::OnEndTracing() { // EndTracingAck below. // We are already on the IO thread, so it is guaranteed that // OnTraceDataCollected is not deferred. - base::debug::TraceLog::GetInstance()->SetEnabled(false); + gpu::TraceLog::GetInstance()->SetEnabled(false); channel_->Send(new ChildProcessHostMsg_EndTracingAck); } void ChildTraceMessageFilter::OnGetTraceBufferPercentFull() { - float bpf = base::debug::TraceLog::GetInstance()->GetBufferPercentFull(); + float bpf = gpu::TraceLog::GetInstance()->GetBufferPercentFull(); channel_->Send(new ChildProcessHostMsg_TraceBufferPercentFullReply(bpf)); } -void ChildTraceMessageFilter::OnTraceDataCollected( - const scoped_refptr<base::debug::TraceLog::RefCountedString>& - json_events_str_ptr) { +void ChildTraceMessageFilter::OnTraceDataCollected(const std::string& data) { if (MessageLoop::current() != ChildProcess::current()->io_message_loop()) { ChildProcess::current()->io_message_loop()->PostTask(FROM_HERE, NewRunnableMethod(this, &ChildTraceMessageFilter::OnTraceDataCollected, - json_events_str_ptr)); + data)); return; } - channel_->Send(new ChildProcessHostMsg_TraceDataCollected( - json_events_str_ptr->data)); + channel_->Send(new ChildProcessHostMsg_TraceDataCollected(data)); } void ChildTraceMessageFilter::OnTraceBufferFull() { diff --git a/content/common/child_trace_message_filter.h b/content/common/child_trace_message_filter.h index 0a377b9..ae74ff5e 100644 --- a/content/common/child_trace_message_filter.h +++ b/content/common/child_trace_message_filter.h @@ -7,7 +7,6 @@ #include <string> -#include "base/debug/trace_event.h" #include "base/process.h" #include "ipc/ipc_channel_proxy.h" @@ -28,9 +27,7 @@ class ChildTraceMessageFilter : public IPC::ChannelProxy::MessageFilter { void OnGetTraceBufferPercentFull(); // Callback from trace subsystem. - void OnTraceDataCollected( - const scoped_refptr<base::debug::TraceLog::RefCountedString>& - json_events_str_ptr); + void OnTraceDataCollected(const std::string& data); void OnTraceBufferFull(); IPC::Channel* channel_; diff --git a/content/common/gpu/gpu_command_buffer_stub.cc b/content/common/gpu/gpu_command_buffer_stub.cc index ebe0fb1..39400c0 100644 --- a/content/common/gpu/gpu_command_buffer_stub.cc +++ b/content/common/gpu/gpu_command_buffer_stub.cc @@ -5,7 +5,6 @@ #if defined(ENABLE_GPU) #include "base/bind.h" -#include "base/debug/trace_event.h" #include "base/process_util.h" #include "base/shared_memory.h" #include "build/build_config.h" @@ -16,6 +15,7 @@ #include "content/common/gpu/gpu_messages.h" #include "content/common/gpu/gpu_watchdog.h" #include "gpu/command_buffer/common/constants.h" +#include "gpu/common/gpu_trace_event.h" #include "ui/gfx/gl/gl_context.h" #include "ui/gfx/gl/gl_surface.h" @@ -184,7 +184,7 @@ void GpuCommandBufferStub::OnGetState(gpu::CommandBuffer::State* state) { void GpuCommandBufferStub::OnFlush(int32 put_offset, int32 last_known_get, gpu::CommandBuffer::State* state) { - TRACE_EVENT0("gpu", "GpuCommandBufferStub::OnFlush"); + GPU_TRACE_EVENT0("gpu", "GpuCommandBufferStub::OnFlush"); *state = command_buffer_->FlushSync(put_offset, last_known_get); if (state->error == gpu::error::kLostContext && gfx::GLContext::LosesAllContextsOnContextLost()) @@ -192,7 +192,7 @@ void GpuCommandBufferStub::OnFlush(int32 put_offset, } void GpuCommandBufferStub::OnAsyncFlush(int32 put_offset) { - TRACE_EVENT0("gpu", "GpuCommandBufferStub::OnAsyncFlush"); + GPU_TRACE_EVENT0("gpu", "GpuCommandBufferStub::OnAsyncFlush"); command_buffer_->Flush(put_offset); // TODO(piman): Do this everytime the scheduler finishes processing a batch of // commands. @@ -257,7 +257,7 @@ void GpuCommandBufferStub::OnResizeOffscreenFrameBuffer(const gfx::Size& size) { } void GpuCommandBufferStub::OnSwapBuffers() { - TRACE_EVENT0("gpu", "GpuCommandBufferStub::OnSwapBuffers"); + GPU_TRACE_EVENT0("gpu", "GpuCommandBufferStub::OnSwapBuffers"); Send(new GpuCommandBufferMsg_SwapBuffers(route_id_)); } diff --git a/content/renderer/command_buffer_proxy.cc b/content/renderer/command_buffer_proxy.cc index e50f0e4..6a1c06c 100644 --- a/content/renderer/command_buffer_proxy.cc +++ b/content/renderer/command_buffer_proxy.cc @@ -4,7 +4,6 @@ #include "content/renderer/command_buffer_proxy.h" -#include "base/debug/trace_event.h" #include "base/logging.h" #include "base/process_util.h" #include "base/shared_memory.h" @@ -15,6 +14,7 @@ #include "content/renderer/plugin_channel_host.h" #include "content/renderer/render_thread.h" #include "gpu/command_buffer/common/cmd_buffer_common.h" +#include "gpu/common/gpu_trace_event.h" #include "ui/gfx/size.h" using gpu::Buffer; @@ -158,7 +158,7 @@ void CommandBufferProxy::Flush(int32 put_offset) { gpu::CommandBuffer::State CommandBufferProxy::FlushSync(int32 put_offset, int32 last_known_get) { - TRACE_EVENT0("gpu", "CommandBufferProxy::FlushSync"); + GPU_TRACE_EVENT0("gpu", "CommandBufferProxy::FlushSync"); if (last_known_get == last_state_.get_offset) { // Send will flag state with lost context if IPC fails. if (last_state_.error == gpu::error::kNoError) { diff --git a/content/renderer/render_thread.cc b/content/renderer/render_thread.cc index c9a7052..9471a99 100644 --- a/content/renderer/render_thread.cc +++ b/content/renderer/render_thread.cc @@ -137,7 +137,7 @@ RenderThread::RenderThread(const std::string& channel_name) } void RenderThread::Init() { - TRACE_EVENT_BEGIN_ETW("RenderThread::Init", 0, ""); + TRACE_EVENT_BEGIN("RenderThread::Init", 0, ""); #if defined(OS_MACOSX) // On Mac, the select popups are rendered by the browser. @@ -169,7 +169,7 @@ void RenderThread::Init() { content::GetContentClient()->renderer()->RenderThreadStarted(); - TRACE_EVENT_END_ETW("RenderThread::Init", 0, ""); + TRACE_EVENT_END("RenderThread::Init", 0, ""); } RenderThread::~RenderThread() { diff --git a/content/renderer/render_widget.cc b/content/renderer/render_widget.cc index 2597ad6..6b190b3 100644 --- a/content/renderer/render_widget.cc +++ b/content/renderer/render_widget.cc @@ -5,7 +5,6 @@ #include "content/renderer/render_widget.h" #include "base/command_line.h" -#include "base/debug/trace_event.h" #include "base/logging.h" #include "base/memory/scoped_ptr.h" #include "base/message_loop.h" @@ -16,6 +15,7 @@ #include "content/renderer/render_process.h" #include "content/renderer/render_thread.h" #include "content/renderer/renderer_webkitclient_impl.h" +#include "gpu/common/gpu_trace_event.h" #include "ipc/ipc_sync_message.h" #include "skia/ext/platform_canvas.h" #include "third_party/skia/include/core/SkShader.h" @@ -305,7 +305,7 @@ void RenderWidget::OnRequestMoveAck() { } void RenderWidget::OnUpdateRectAck() { - TRACE_EVENT0("renderer", "RenderWidget::OnUpdateRectAck"); + GPU_TRACE_EVENT0("renderer", "RenderWidget::OnUpdateRectAck"); DCHECK(update_reply_pending()); update_reply_pending_ = false; @@ -553,7 +553,7 @@ void RenderWidget::CallDoDeferredUpdate() { } void RenderWidget::DoDeferredUpdate() { - TRACE_EVENT0("renderer", "RenderWidget::DoDeferredUpdate"); + GPU_TRACE_EVENT0("renderer", "RenderWidget::DoDeferredUpdate"); if (!webwidget_ || update_reply_pending()) return; diff --git a/content/renderer/renderer_gl_context.cc b/content/renderer/renderer_gl_context.cc index b0a28be..8d559c4 100644 --- a/content/renderer/renderer_gl_context.cc +++ b/content/renderer/renderer_gl_context.cc @@ -4,7 +4,6 @@ #include "content/renderer/renderer_gl_context.h" -#include "base/debug/trace_event.h" #include "base/lazy_instance.h" #include "base/memory/ref_counted.h" #include "base/memory/scoped_ptr.h" @@ -28,6 +27,7 @@ #include "gpu/command_buffer/client/gles2_implementation.h" #include "gpu/command_buffer/client/gles2_lib.h" #include "gpu/command_buffer/common/constants.h" +#include "gpu/common/gpu_trace_event.h" #include "gpu/GLES2/gles2_command_buffer.h" #endif // ENABLE_GPU @@ -293,7 +293,7 @@ bool RendererGLContext::MakeCurrent(RendererGLContext* context) { } bool RendererGLContext::SwapBuffers() { - TRACE_EVENT0("gpu", "RendererGLContext::SwapBuffers"); + GPU_TRACE_EVENT0("gpu", "RendererGLContext::SwapBuffers"); // Don't request latest error status from service. Just use the locally cached // information from the last flush. if (command_buffer_->GetLastState().error != gpu::error::kNoError) @@ -376,7 +376,7 @@ bool RendererGLContext::Initialize(bool onscreen, const int32* attrib_list, const GURL& active_url) { DCHECK(size.width() >= 0 && size.height() >= 0); - TRACE_EVENT2("gpu", "RendererGLContext::Initialize", + GPU_TRACE_EVENT2("gpu", "RendererGLContext::Initialize", "on_screen", onscreen, "num_pixels", size.GetArea()); if (channel_->state() != GpuChannelHost::kConnected) diff --git a/content/renderer/renderer_main.cc b/content/renderer/renderer_main.cc index 36c73ba..440ef77 100644 --- a/content/renderer/renderer_main.cc +++ b/content/renderer/renderer_main.cc @@ -129,7 +129,7 @@ class RendererMessageLoopObserver : public MessageLoop::TaskObserver { // mainline routine for running as the Renderer process int RendererMain(const MainFunctionParams& parameters) { - TRACE_EVENT_BEGIN_ETW("RendererMain", 0, ""); + TRACE_EVENT_BEGIN("RendererMain", 0, ""); const CommandLine& parsed_command_line = parameters.command_line_; base::mac::ScopedNSAutoreleasePool* pool = parameters.autorelease_pool_; @@ -231,12 +231,12 @@ int RendererMain(const MainFunctionParams& parameters) { if (run_loop) { if (pool) pool->Recycle(); - TRACE_EVENT_BEGIN_ETW("RendererMain.START_MSG_LOOP", 0, 0); + TRACE_EVENT_BEGIN("RendererMain.START_MSG_LOOP", 0, 0); MessageLoop::current()->Run(); - TRACE_EVENT_END_ETW("RendererMain.START_MSG_LOOP", 0, 0); + TRACE_EVENT_END("RendererMain.START_MSG_LOOP", 0, 0); } } platform.PlatformUninitialize(); - TRACE_EVENT_END_ETW("RendererMain", 0, ""); + TRACE_EVENT_END("RendererMain", 0, ""); return 0; } diff --git a/gpu/command_buffer/client/cmd_buffer_helper.cc b/gpu/command_buffer/client/cmd_buffer_helper.cc index f31afa3..1054055 100644 --- a/gpu/command_buffer/client/cmd_buffer_helper.cc +++ b/gpu/command_buffer/client/cmd_buffer_helper.cc @@ -6,7 +6,7 @@ #include "../client/cmd_buffer_helper.h" #include "../common/command_buffer.h" -#include "../common/trace_event.h" +#include "gpu/common/gpu_trace_event.h" namespace gpu { @@ -62,7 +62,7 @@ void CommandBufferHelper::Flush() { // Calls Flush() and then waits until the buffer is empty. Break early if the // error is set. bool CommandBufferHelper::Finish() { - TRACE_EVENT0("gpu", "CommandBufferHelper::Finish"); + GPU_TRACE_EVENT0("gpu", "CommandBufferHelper::Finish"); do { // Do not loop forever if the flush fails, meaning the command buffer reader // has shutdown. @@ -84,7 +84,7 @@ int32 CommandBufferHelper::InsertToken() { cmd::SetToken& cmd = GetCmdSpace<cmd::SetToken>(); cmd.Init(token_); if (token_ == 0) { - TRACE_EVENT0("gpu", "CommandBufferHelper::InsertToken(wrapped)"); + GPU_TRACE_EVENT0("gpu", "CommandBufferHelper::InsertToken(wrapped)"); // we wrapped Finish(); GPU_DCHECK_EQ(token_, last_token_read_); @@ -95,7 +95,7 @@ int32 CommandBufferHelper::InsertToken() { // Waits until the current token value is greater or equal to the value passed // in argument. void CommandBufferHelper::WaitForToken(int32 token) { - TRACE_EVENT0("gpu", "CommandBufferHelper::WaitForToken"); + GPU_TRACE_EVENT0("gpu", "CommandBufferHelper::WaitForToken"); // Return immediately if corresponding InsertToken failed. if (token < 0) return; @@ -131,7 +131,7 @@ void CommandBufferHelper::WaitForAvailableEntries(int32 count) { // put will wrap to 0 after we add the jump). GPU_DCHECK_LE(1, put_); if (get_ > put_ || get_ == 0) { - TRACE_EVENT0("gpu", "CommandBufferHelper::WaitForAvailableEntries"); + GPU_TRACE_EVENT0("gpu", "CommandBufferHelper::WaitForAvailableEntries"); while (get_ > put_ || get_ == 0) { // Do not loop forever if the flush fails, meaning the command buffer // reader has shutdown. @@ -144,7 +144,7 @@ void CommandBufferHelper::WaitForAvailableEntries(int32 count) { put_ = 0; } if (AvailableEntries() < count) { - TRACE_EVENT0("gpu", "CommandBufferHelper::WaitForAvailableEntries1"); + GPU_TRACE_EVENT0("gpu", "CommandBufferHelper::WaitForAvailableEntries1"); while (AvailableEntries() < count) { // Do not loop forever if the flush fails, meaning the command buffer // reader has shutdown. diff --git a/gpu/command_buffer/client/gles2_implementation.cc b/gpu/command_buffer/client/gles2_implementation.cc index ed3aefd..5ea5523 100644 --- a/gpu/command_buffer/client/gles2_implementation.cc +++ b/gpu/command_buffer/client/gles2_implementation.cc @@ -9,7 +9,7 @@ #include "../client/mapped_memory.h" #include "../common/gles2_cmd_utils.h" #include "../common/id_allocator.h" -#include "../common/trace_event.h" +#include "gpu/common/gpu_trace_event.h" #if defined(__native_client__) && !defined(GLES2_SUPPORT_CLIENT_SIDE_ARRAYS) #define GLES2_SUPPORT_CLIENT_SIDE_ARRAYS @@ -491,7 +491,7 @@ GLES2Implementation::~GLES2Implementation() { } void GLES2Implementation::WaitForCmd() { - TRACE_EVENT0("gpu", "GLES2::WaitForCmd"); + GPU_TRACE_EVENT0("gpu", "GLES2::WaitForCmd"); helper_->CommandBufferHelper::Finish(); } @@ -500,7 +500,7 @@ GLenum GLES2Implementation::GetError() { } GLenum GLES2Implementation::GetGLError() { - TRACE_EVENT0("gpu", "GLES2::GetGLError"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetGLError"); // Check the GL error first, then our wrapped error. typedef gles2::GetError::Result Result; Result* result = GetResultAs<Result*>(); @@ -533,7 +533,7 @@ void GLES2Implementation::SetGLError(GLenum error, const char* msg) { void GLES2Implementation::GetBucketContents(uint32 bucket_id, std::vector<int8>* data) { - TRACE_EVENT0("gpu", "GLES2::GetBucketContents"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetBucketContents"); GPU_DCHECK(data); typedef cmd::GetBucketSize::Result Result; Result* result = GetResultAs<Result*>(); @@ -674,7 +674,7 @@ void GLES2Implementation::Flush() { } void GLES2Implementation::Finish() { - TRACE_EVENT0("gpu", "GLES2::Finish"); + GPU_TRACE_EVENT0("gpu", "GLES2::Finish"); // Insert the cmd to call glFinish helper_->Finish(); // Finish our command buffer @@ -714,7 +714,7 @@ void GLES2Implementation::CopyTextureToParentTextureCHROMIUM( void GLES2Implementation::GenSharedIdsCHROMIUM( GLuint namespace_id, GLuint id_offset, GLsizei n, GLuint* ids) { - TRACE_EVENT0("gpu", "GLES2::GenSharedIdsCHROMIUM"); + GPU_TRACE_EVENT0("gpu", "GLES2::GenSharedIdsCHROMIUM"); GLint* id_buffer = transfer_buffer_.AllocTyped<GLint>(n); helper_->GenSharedIdsCHROMIUM(namespace_id, id_offset, n, transfer_buffer_id_, @@ -726,7 +726,7 @@ void GLES2Implementation::GenSharedIdsCHROMIUM( void GLES2Implementation::DeleteSharedIdsCHROMIUM( GLuint namespace_id, GLsizei n, const GLuint* ids) { - TRACE_EVENT0("gpu", "GLES2::DeleteSharedIdsCHROMIUM"); + GPU_TRACE_EVENT0("gpu", "GLES2::DeleteSharedIdsCHROMIUM"); GLint* id_buffer = transfer_buffer_.AllocTyped<GLint>(n); memcpy(id_buffer, ids, sizeof(*ids) * n); helper_->DeleteSharedIdsCHROMIUM(namespace_id, n, @@ -738,7 +738,7 @@ void GLES2Implementation::DeleteSharedIdsCHROMIUM( void GLES2Implementation::RegisterSharedIdsCHROMIUM( GLuint namespace_id, GLsizei n, const GLuint* ids) { - TRACE_EVENT0("gpu", "GLES2::RegisterSharedIdsCHROMIUM"); + GPU_TRACE_EVENT0("gpu", "GLES2::RegisterSharedIdsCHROMIUM"); GLint* id_buffer = transfer_buffer_.AllocTyped<GLint>(n); memcpy(id_buffer, ids, sizeof(*ids) * n); helper_->RegisterSharedIdsCHROMIUM(namespace_id, n, @@ -764,7 +764,7 @@ void GLES2Implementation::GetVertexAttribPointerv( } #endif // defined(GLES2_SUPPORT_CLIENT_SIDE_ARRAYS) - TRACE_EVENT0("gpu", "GLES2::GetVertexAttribPointerv"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetVertexAttribPointerv"); typedef gles2::GetVertexAttribPointerv::Result Result; Result* result = GetResultAs<Result*>(); result->SetNumResults(0); @@ -776,7 +776,7 @@ void GLES2Implementation::GetVertexAttribPointerv( GLint GLES2Implementation::GetAttribLocation( GLuint program, const char* name) { - TRACE_EVENT0("gpu", "GLES2::GetAttribLocation"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetAttribLocation"); typedef GetAttribLocationBucket::Result Result; Result* result = GetResultAs<Result*>(); *result = -1; @@ -790,7 +790,7 @@ GLint GLES2Implementation::GetAttribLocation( GLint GLES2Implementation::GetUniformLocation( GLuint program, const char* name) { - TRACE_EVENT0("gpu", "GLES2::GetUniformLocation"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetUniformLocation"); typedef GetUniformLocationBucket::Result Result; Result* result = GetResultAs<Result*>(); *result = -1; @@ -1101,7 +1101,7 @@ void GLES2Implementation::GetActiveAttrib( SetGLError(GL_INVALID_VALUE, "glGetActiveAttrib: bufsize < 0"); return; } - TRACE_EVENT0("gpu", "GLES2::GetActiveAttrib"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetActiveAttrib"); // Clear the bucket so if we the command fails nothing will be in it. helper_->SetBucketSize(kResultBucketId, 0); typedef gles2::GetActiveAttrib::Result Result; @@ -1142,7 +1142,7 @@ void GLES2Implementation::GetActiveUniform( SetGLError(GL_INVALID_VALUE, "glGetActiveUniform: bufsize < 0"); return; } - TRACE_EVENT0("gpu", "GLES2::GetActiveUniform"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetActiveUniform"); // Clear the bucket so if we the command fails nothing will be in it. helper_->SetBucketSize(kResultBucketId, 0); typedef gles2::GetActiveUniform::Result Result; @@ -1182,7 +1182,7 @@ void GLES2Implementation::GetAttachedShaders( SetGLError(GL_INVALID_VALUE, "glGetAttachedShaders: maxcount < 0"); return; } - TRACE_EVENT0("gpu", "GLES2::GetAttachedShaders"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetAttachedShaders"); typedef gles2::GetAttachedShaders::Result Result; uint32 size = Result::ComputeSize(maxcount); Result* result = transfer_buffer_.AllocTyped<Result>(size); @@ -1203,7 +1203,7 @@ void GLES2Implementation::GetAttachedShaders( void GLES2Implementation::GetShaderPrecisionFormat( GLenum shadertype, GLenum precisiontype, GLint* range, GLint* precision) { - TRACE_EVENT0("gpu", "GLES2::GetShaderPrecisionFormat"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetShaderPrecisionFormat"); typedef gles2::GetShaderPrecisionFormat::Result Result; Result* result = static_cast<Result*>(result_buffer_); result->success = false; @@ -1255,7 +1255,7 @@ const GLubyte* GLES2Implementation::GetString(GLenum name) { void GLES2Implementation::GetUniformfv( GLuint program, GLint location, GLfloat* params) { - TRACE_EVENT0("gpu", "GLES2::GetUniformfv"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetUniformfv"); typedef gles2::GetUniformfv::Result Result; Result* result = static_cast<Result*>(result_buffer_); result->SetNumResults(0); @@ -1267,7 +1267,7 @@ void GLES2Implementation::GetUniformfv( void GLES2Implementation::GetUniformiv( GLuint program, GLint location, GLint* params) { - TRACE_EVENT0("gpu", "GLES2::GetUniformiv"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetUniformiv"); typedef gles2::GetUniformiv::Result Result; Result* result = static_cast<Result*>(result_buffer_); result->SetNumResults(0); @@ -1294,7 +1294,7 @@ void GLES2Implementation::ReadPixels( // and that when we copy the results to the user's buffer we need to not // write those padding bytes but leave them as they are. - TRACE_EVENT0("gpu", "GLES2::ReadPixels"); + GPU_TRACE_EVENT0("gpu", "GLES2::ReadPixels"); typedef gles2::ReadPixels::Result Result; Result* result = static_cast<Result*>(result_buffer_); int8* dest = reinterpret_cast<int8*>(pixels); @@ -1534,7 +1534,7 @@ void GLES2Implementation::GetVertexAttribfv( return; } #endif - TRACE_EVENT0("gpu", "GLES2::GetVertexAttribfv"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetVertexAttribfv"); typedef GetVertexAttribfv::Result Result; Result* result = GetResultAs<Result*>(); result->SetNumResults(0); @@ -1553,7 +1553,7 @@ void GLES2Implementation::GetVertexAttribiv( return; } #endif - TRACE_EVENT0("gpu", "GLES2::GetVertexAttribiv"); + GPU_TRACE_EVENT0("gpu", "GLES2::GetVertexAttribiv"); typedef GetVertexAttribiv::Result Result; Result* result = GetResultAs<Result*>(); result->SetNumResults(0); @@ -1565,7 +1565,7 @@ void GLES2Implementation::GetVertexAttribiv( GLboolean GLES2Implementation::CommandBufferEnableCHROMIUM( const char* feature) { - TRACE_EVENT0("gpu", "GLES2::CommandBufferEnableCHROMIUM"); + GPU_TRACE_EVENT0("gpu", "GLES2::CommandBufferEnableCHROMIUM"); typedef CommandBufferEnableCHROMIUM::Result Result; Result* result = GetResultAs<Result*>(); *result = 0; diff --git a/gpu/command_buffer/common/trace_event.h b/gpu/command_buffer/common/trace_event.h deleted file mode 100644 index 9327063..0000000 --- a/gpu/command_buffer/common/trace_event.h +++ /dev/null @@ -1,30 +0,0 @@ -// 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. - -#ifndef GPU_COMMAND_BUFFER_COMMON_TRACE_EVENT_H_ -#define GPU_COMMAND_BUFFER_COMMON_TRACE_EVENT_H_ -#pragma once - -#if !defined(__native_client__) - -#include "base/debug/trace_event.h" - -#else - -#define TRACE_EVENT0(x0, x1) { } -#define TRACE_EVENT1(x0, x1, x2, x3) { } -#define TRACE_EVENT2(x0, x1, x2, x3, x4, x5) { } -#define TRACE_EVENT_INSTANT0(x0, x1) { } -#define TRACE_EVENT_INSTANT1(x0, x1, x2, x3) { } -#define TRACE_EVENT_INSTANT2(x0, x1, x2, x3, x4, x5) { } -#define TRACE_BEGIN0(x0, x1) { } -#define TRACE_BEGIN1(x0, x1, x2, x3) { } -#define TRACE_BEGIN2(x0, x1, x2, x3, x4, x5) { } -#define TRACE_END0(x0, x1) { } -#define TRACE_END1(x0, x1, x2, x3) { } -#define TRACE_END2(x0, x1, x2, x3, x4, x5) { } - -#endif // __native_client__ - -#endif // GPU_COMMAND_BUFFER_COMMON_TRACE_EVENT_H_ diff --git a/gpu/command_buffer/service/gles2_cmd_decoder.cc b/gpu/command_buffer/service/gles2_cmd_decoder.cc index ccaf5c3..13e73c1 100644 --- a/gpu/command_buffer/service/gles2_cmd_decoder.cc +++ b/gpu/command_buffer/service/gles2_cmd_decoder.cc @@ -22,7 +22,6 @@ #include "gpu/command_buffer/common/gles2_cmd_format.h" #include "gpu/command_buffer/common/gles2_cmd_utils.h" #include "gpu/command_buffer/common/id_allocator.h" -#include "gpu/command_buffer/common/trace_event.h" #include "gpu/command_buffer/service/buffer_manager.h" #include "gpu/command_buffer/service/cmd_buffer_engine.h" #include "gpu/command_buffer/service/context_group.h" @@ -35,6 +34,7 @@ #include "gpu/command_buffer/service/shader_manager.h" #include "gpu/command_buffer/service/shader_translator.h" #include "gpu/command_buffer/service/texture_manager.h" +#include "gpu/common/gpu_trace_event.h" #include "gpu/GLES2/gles2_command_buffer.h" #include "ui/gfx/gl/gl_context.h" #include "ui/gfx/gl/gl_implementation.h" @@ -5576,7 +5576,7 @@ error::Error GLES2DecoderImpl::DoTexImage2D( error::Error GLES2DecoderImpl::HandleTexImage2D( uint32 immediate_data_size, const gles2::TexImage2D& c) { - TRACE_EVENT0("gpu", "GLES2DecoderImpl::HandleTexImage2D"); + GPU_TRACE_EVENT0("gpu", "GLES2DecoderImpl::HandleTexImage2D"); tex_image_2d_failed_ = true; GLenum target = static_cast<GLenum>(c.target); GLint level = static_cast<GLint>(c.level); @@ -5890,7 +5890,7 @@ void GLES2DecoderImpl::DoTexSubImage2D( error::Error GLES2DecoderImpl::HandleTexSubImage2D( uint32 immediate_data_size, const gles2::TexSubImage2D& c) { - TRACE_EVENT0("gpu", "GLES2DecoderImpl::HandleTexSubImage2D"); + GPU_TRACE_EVENT0("gpu", "GLES2DecoderImpl::HandleTexSubImage2D"); GLboolean internal = static_cast<GLboolean>(c.internal); if (internal == GL_TRUE && tex_image_2d_failed_) return error::kNoError; @@ -6314,7 +6314,7 @@ error::Error GLES2DecoderImpl::HandleShaderBinary( error::Error GLES2DecoderImpl::HandleSwapBuffers( uint32 immediate_data_size, const gles2::SwapBuffers& c) { - TRACE_EVENT0("gpu", "GLES2DecoderImpl::HandleSwapBuffers"); + GPU_TRACE_EVENT0("gpu", "GLES2DecoderImpl::HandleSwapBuffers"); // If offscreen then don't actually SwapBuffers to the display. Just copy // the rendered frame to another frame buffer. if (offscreen_target_frame_buffer_.get()) { @@ -6360,7 +6360,7 @@ error::Error GLES2DecoderImpl::HandleSwapBuffers( return error::kNoError; } } else { - TRACE_EVENT0("gpu", "GLContext::SwapBuffers"); + GPU_TRACE_EVENT0("gpu", "GLContext::SwapBuffers"); if (!context_->SwapBuffers()) { LOG(ERROR) << "Context lost because SwapBuffers failed."; return error::kLostContext; @@ -6376,7 +6376,7 @@ error::Error GLES2DecoderImpl::HandleSwapBuffers( error::Error GLES2DecoderImpl::HandleSetLatchCHROMIUM( uint32 immediate_data_size, const gles2::SetLatchCHROMIUM& c) { - TRACE_EVENT0("gpu", "SetLatch"); + GPU_TRACE_EVENT0("gpu", "SetLatch"); // Ensure the side effects of previous commands are visible to other contexts. // There is no need to do this for ANGLE because it uses a // single D3D device for all contexts. @@ -6403,7 +6403,7 @@ error::Error GLES2DecoderImpl::HandleSetLatchCHROMIUM( error::Error GLES2DecoderImpl::HandleWaitLatchCHROMIUM( uint32 immediate_data_size, const gles2::WaitLatchCHROMIUM& c) { - TRACE_EVENT0("gpu", "WaitLatch"); + GPU_TRACE_EVENT0("gpu", "WaitLatch"); int32 shm_id = gpu::kLatchSharedMemoryId; uint32 latch_id = c.latch_id; uint32 shm_offset = 0; diff --git a/gpu/command_buffer/service/gpu_scheduler.cc b/gpu/command_buffer/service/gpu_scheduler.cc index 6ee11b0..c1b7aaa 100644 --- a/gpu/command_buffer/service/gpu_scheduler.cc +++ b/gpu/command_buffer/service/gpu_scheduler.cc @@ -6,8 +6,8 @@ #include "base/callback.h" #include "base/compiler_specific.h" -#include "base/debug/trace_event.h" #include "base/message_loop.h" +#include "gpu/common/gpu_trace_event.h" #include "ui/gfx/gl/gl_context.h" #include "ui/gfx/gl/gl_bindings.h" @@ -128,7 +128,7 @@ void GpuScheduler::PutChanged(bool sync) { } void GpuScheduler::ProcessCommands() { - TRACE_EVENT0("gpu", "GpuScheduler:ProcessCommands"); + GPU_TRACE_EVENT0("gpu", "GpuScheduler:ProcessCommands"); CommandBuffer::State state = command_buffer_->GetState(); if (state.error != error::kNoError) return; diff --git a/gpu/common/gpu_trace_event.cc b/gpu/common/gpu_trace_event.cc new file mode 100644 index 0000000..b92ce6d --- /dev/null +++ b/gpu/common/gpu_trace_event.cc @@ -0,0 +1,330 @@ +// 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 "gpu/common/gpu_trace_event.h" + +#include "base/format_macros.h" +#include "base/process_util.h" +#include "base/stringprintf.h" +#include "base/utf_string_conversions.h" +#include "base/time.h" + +#define USE_UNRELIABLE_NOW + +using namespace base; + +namespace gpu { + +// Controls the number of trace events we will buffer in-memory +// before throwing them away. +#define TRACE_EVENT_BUFFER_SIZE 500000 +#define TRACE_EVENT_BATCH_SIZE 1000 + +#define TRACE_EVENT_MAX_CATEGORIES 42 + +static TraceCategory g_categories[TRACE_EVENT_MAX_CATEGORIES]; +static int g_category_index = 0; + +//////////////////////////////////////////////////////////////////////////////// +// +// TraceLog::Category +// +//////////////////////////////////////////////////////////////////////////////// +TraceCategory::TraceCategory() + : name_(NULL) { + base::subtle::NoBarrier_Store(&enabled_, + static_cast<base::subtle::Atomic32>(0)); +} + +TraceCategory::~TraceCategory() { + base::subtle::NoBarrier_Store(&enabled_, + static_cast<base::subtle::Atomic32>(0)); +} + +//////////////////////////////////////////////////////////////////////////////// +// +// TraceValue +// +//////////////////////////////////////////////////////////////////////////////// + +void TraceValue::Destroy() { + if (type_ == TRACE_TYPE_STRING) { + free(value_.as_string); + value_.as_string = NULL; + } + type_ = TRACE_TYPE_UNDEFINED; + value_.as_uint = 0ull; +} + +TraceValue& TraceValue::operator=(const TraceValue& rhs) { + DCHECK(sizeof(value_) == sizeof(uint64)); + Destroy(); + type_ = rhs.type_; + if (rhs.type_ == TRACE_TYPE_STRING) { + value_.as_string = base::strdup(rhs.value_.as_string); + } else { + // Copy all 64 bits for all other types. + value_.as_uint = rhs.value_.as_uint; + } + return *this; +} + +bool TraceValue::operator==(const TraceValue& rhs) const { + if (type_ != rhs.type()) + return false; + if (rhs.type_ == TRACE_TYPE_STRING) { + return (strcmp(value_.as_string, rhs.value_.as_string) == 0); + } else { + // Compare all 64 bits for all other types. Unused bits are set to zero + // by the constructors of types that may be less than 64 bits. + return (value_.as_uint == rhs.value_.as_uint); + } +} + +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, sizeof(temp_string), "%llu", + static_cast<unsigned long long>(as_uint())); + *out += temp_string; + break; + case TRACE_TYPE_INT: + base::snprintf(temp_string, sizeof(temp_string), "%lld", + static_cast<long long>(as_int())); + *out += temp_string; + break; + case TRACE_TYPE_DOUBLE: + base::snprintf(temp_string, sizeof(temp_string), "%f", as_double()); + *out += temp_string; + break; + case TRACE_TYPE_POINTER: + base::snprintf(temp_string, sizeof(temp_string), "%p", as_pointer()); + *out += temp_string; + break; + case TRACE_TYPE_STRING: + 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] = '\''; + break; + default: + break; + } +} + +//////////////////////////////////////////////////////////////////////////////// +// +// TraceEvent +// +//////////////////////////////////////////////////////////////////////////////// + +namespace { +const char* GetPhaseStr(TraceEventPhase phase) { + if (phase == GPU_TRACE_EVENT_PHASE_BEGIN) { + return "B"; + } else if (phase == GPU_TRACE_EVENT_PHASE_INSTANT) { + return "I"; + } else if (phase == GPU_TRACE_EVENT_PHASE_END) { + return "E"; + } else { + DCHECK(false); + return "?"; + } +} +} + +TraceEvent::TraceEvent() + : processId(0), + threadId(0), + phase(GPU_TRACE_EVENT_PHASE_BEGIN), + category(NULL), + name(NULL) { + memset(&argNames, 0, sizeof(argNames)); +} + +TraceEvent::~TraceEvent() { +} + + +void TraceEvent::AppendAsJSON(std::string* out, + const std::vector<TraceEvent>& events, + size_t start, + size_t count) { + *out += "["; + for (size_t i = 0; i < count && start + i < events.size(); ++i) { + if (i > 0) + *out += ","; + events[i + start].AppendAsJSON(out); + } + *out += "]"; +} + +void TraceEvent::AppendAsJSON(std::string* out) const { + int nargs = 0; + for (int i = 0; i < TRACE_MAX_NUM_ARGS; ++i) { + if (argNames[i] == NULL) + break; + nargs += 1; + } + + const char* phaseStr = GetPhaseStr(phase); + int64 time_int64 = timestamp.ToInternalValue(); + StringAppendF(out, + "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%lld," + "\"ph\":\"%s\",\"name\":\"%s\",\"args\":{", + category->name(), + static_cast<int>(processId), + static_cast<int>(threadId), + static_cast<long long>(time_int64), + phaseStr, + name); + for (int i = 0; i < nargs; ++i) { + if (i > 0) + *out += ","; + *out += "\""; + *out += argNames[i]; + *out += "\":\""; + argValues[i].AppendAsJSON(out); + *out += "\""; + } + *out += "}}"; +} + +//////////////////////////////////////////////////////////////////////////////// +// +// TraceLog +// +//////////////////////////////////////////////////////////////////////////////// + +// static +TraceLog* TraceLog::GetInstance() { + return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get(); +} + +TraceLog::TraceLog() + : enabled_(false) +{ + logged_events_.reserve(1024); +} + +TraceLog::~TraceLog() { +} + +TraceCategory* TraceLog::GetCategory(const char* name) { + AutoLock lock(lock_); + for (int i = 0; i < g_category_index; i++) { + if (strcmp(g_categories[i].name(), name) == 0) + return &g_categories[i]; + } + CHECK(g_category_index < TRACE_EVENT_MAX_CATEGORIES) << + "must increase TRACE_EVENT_MAX_CATEGORIES"; + int new_index = g_category_index++; + g_categories[new_index].set(name, enabled_); + return &g_categories[new_index]; +} + +void TraceLog::SetEnabled(bool enabled) { + AutoLock lock(lock_); + if (enabled == enabled_) + return; + if (enabled) { + // Enable all categories. + enabled_ = true; + for (int i = 0; i < g_category_index; i++) { + base::subtle::NoBarrier_Store(&g_categories[i].enabled_, + static_cast<base::subtle::Atomic32>(1)); + } + } else { + // Disable all categories. + for (int i = 0; i < g_category_index; i++) { + base::subtle::NoBarrier_Store(&g_categories[i].enabled_, + static_cast<base::subtle::Atomic32>(0)); + } + enabled_ = false; + FlushWithLockAlreadyHeld(); + } +} + +float TraceLog::GetBufferPercentFull() const { + return (float)((double)logged_events_.size()/(double)TRACE_EVENT_BUFFER_SIZE); +} + +void TraceLog::SetOutputCallback(TraceLog::OutputCallback* cb) { + AutoLock lock(lock_); + if (enabled_) { + FlushWithLockAlreadyHeld(); + } + output_callback_.reset(cb); +} + +void TraceLog::SetBufferFullCallback(TraceLog::BufferFullCallback* cb) { + AutoLock lock(lock_); + buffer_full_callback_.reset(cb); +} + +void TraceLog::AddRemotelyCollectedData(const std::string& json_events) { + AutoLock lock(lock_); + if (output_callback_.get()) + output_callback_->Run(json_events); +} + +void TraceLog::Flush() { + AutoLock lock(lock_); + FlushWithLockAlreadyHeld(); +} + +void TraceLog::FlushWithLockAlreadyHeld() { + if (output_callback_.get() && logged_events_.size()) { + for (size_t i = 0; i < logged_events_.size(); i += TRACE_EVENT_BATCH_SIZE) { + std::string json_events; + TraceEvent::AppendAsJSON(&json_events, logged_events_, + i, TRACE_EVENT_BATCH_SIZE); + output_callback_->Run(json_events); + } + } + logged_events_.erase(logged_events_.begin(), logged_events_.end()); +} + +void TraceLog::AddTraceEvent(TraceEventPhase phase, + const char* file, int line, + TraceCategory* category, + const char* name, + const char* arg1name, TraceValue arg1val, + const char* arg2name, TraceValue arg2val) { + DCHECK(file && name); +#ifdef USE_UNRELIABLE_NOW + TimeTicks now = TimeTicks::HighResNow(); +#else + TimeTicks now = TimeTicks::Now(); +#endif + //static_cast<unsigned long>(base::GetCurrentProcId()), + AutoLock lock(lock_); + if (logged_events_.size() >= TRACE_EVENT_BUFFER_SIZE) + return; + logged_events_.push_back(TraceEvent()); + TraceEvent& event = logged_events_.back(); + event.processId = static_cast<unsigned long>(base::GetCurrentProcId()); + event.threadId = PlatformThread::CurrentId(); + event.timestamp = now; + event.phase = phase; + event.category = category; + event.name = name; + event.argNames[0] = arg1name; + event.argValues[0] = arg1val; + event.argNames[1] = arg2name; + event.argValues[1] = arg2val; + COMPILE_ASSERT(TRACE_MAX_NUM_ARGS == 2, TraceEvent_arc_count_out_of_sync); + if (logged_events_.size() == TRACE_EVENT_BUFFER_SIZE && + buffer_full_callback_.get()) + buffer_full_callback_->Run(); +} + +} // namespace gpu diff --git a/gpu/common/gpu_trace_event.h b/gpu/common/gpu_trace_event.h new file mode 100644 index 0000000..581b66e --- /dev/null +++ b/gpu/common/gpu_trace_event.h @@ -0,0 +1,439 @@ +// 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: +// GPU_TRACE_EVENT_INSTANT0("MY_SUBSYSTEM", "SomeImportantEvent") +// +// Events can be INSTANT, or can be pairs of BEGIN and END: +// GPU_TRACE_EVENT_BEGIN0("MY_SUBSYSTEM", "SomethingCostly") +// doSomethingCostly() +// GPU_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() { +// GPU_TRACE_EVENT0("MY_SUBSYSTEM", "doSomethingCostly"); +// ... +// } +// +// Additional parameters can be associated with an event: +// void doSomethingCostly2(int howMuch) { +// GPU_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 GPU_TRACE_EVENT_H_ +#define GPU_TRACE_EVENT_H_ +#pragma once + +#if defined(__native_client__) + +// Native Client needs to avoid pulling in base/ headers, +// so stub out the tracing code at compile time. +#define GPU_TRACE_EVENT0(x0, x1) { } +#define GPU_TRACE_EVENT1(x0, x1, x2, x3) { } +#define GPU_TRACE_EVENT2(x0, x1, x2, x3, x4, x5) { } +#define GPU_TRACE_EVENT_INSTANT0(x0, x1) { } +#define GPU_TRACE_EVENT_INSTANT1(x0, x1, x2, x3) { } +#define GPU_TRACE_EVENT_INSTANT2(x0, x1, x2, x3, x4, x5) { } +#define GPU_TRACE_BEGIN0(x0, x1) { } +#define GPU_TRACE_BEGIN1(x0, x1, x2, x3) { } +#define GPU_TRACE_BEGIN2(x0, x1, x2, x3, x4, x5) { } +#define GPU_TRACE_END0(x0, x1) { } +#define GPU_TRACE_END1(x0, x1, x2, x3) { } +#define GPU_TRACE_END2(x0, x1, x2, x3, x4, x5) { } + +#else + +#include "build/build_config.h" + +#include <string> + +#include "base/memory/scoped_ptr.h" +#include "base/atomicops.h" +#include "base/memory/scoped_vector.h" +#include "base/memory/singleton.h" +#include "base/time.h" +#include "base/timer.h" +#include "base/callback.h" +#include "base/string_util.h" +#include <vector> + + +// 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 GPU_TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b) a##b +#define GPU_TRACE_EVENT_UNIQUE_IDENTIFIER2(a,b) \ + GPU_TRACE_EVENT_UNIQUE_IDENTIFIER3(a,b) +#define GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(name_prefix) \ + GPU_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. +#define GPU_TRACE_EVENT0(category, name) \ + GPU_TRACE_EVENT1(category, name, NULL, 0) +#define GPU_TRACE_EVENT1(category, name, arg1name, arg1val) \ + GPU_TRACE_EVENT2(category, name, arg1name, arg1val, NULL, 0) +#define GPU_TRACE_EVENT2(category, name, arg1name, arg1val, arg2name, arg2val) \ + static gpu::TraceCategory* \ + GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \ + gpu::TraceLog::GetInstance()->GetCategory(category); \ + if (base::subtle::Acquire_Load(\ + &(GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic))->enabled_)) { \ + gpu::TraceLog::GetInstance()->AddTraceEvent( \ + gpu::GPU_TRACE_EVENT_PHASE_BEGIN, \ + __FILE__, __LINE__, \ + GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ + name, \ + arg1name, arg1val, \ + arg2name, arg2val); \ + } \ + gpu::internal::TraceEndOnScopeClose __profileScope ## __LINE ( \ + __FILE__, __LINE__, \ + GPU_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. +#define GPU_TRACE_EVENT_INSTANT0(category, name) \ + GPU_TRACE_EVENT_INSTANT1(category, name, NULL, 0) +#define GPU_TRACE_EVENT_INSTANT1(category, name, arg1name, arg1val) \ + GPU_TRACE_EVENT_INSTANT2(category, name, arg1name, arg1val, NULL, 0) +#define GPU_TRACE_EVENT_INSTANT2(category, name, arg1name, arg1val, \ + arg2name, arg2val) \ + static gpu::TraceCategory* \ + GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \ + gpu::TraceLog::GetInstance()->GetCategory(category); \ + if (base::subtle::Acquire_Load( \ + &(GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic))->enabled_)) { \ + gpu::TraceLog::GetInstance()->AddTraceEvent( \ + gpu::GPU_TRACE_EVENT_PHASE_INSTANT, \ + __FILE__, __LINE__, \ + GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ + name, \ + arg1name, arg1val, \ + arg2name, arg2val); \ + } + +// 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. +#define GPU_TRACE_EVENT_BEGIN0(category, name) \ + GPU_TRACE_EVENT_BEGIN1(category, name, NULL, 0) +#define GPU_TRACE_EVENT_BEGIN1(category, name, arg1name, arg1val) \ + GPU_TRACE_EVENT_BEGIN2(category, name, arg1name, arg1val, NULL, 0) +#define GPU_TRACE_EVENT_BEGIN2(category, name, arg1name, arg1val, \ + arg2name, arg2val) \ + static gpu::TraceCategory* \ + GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \ + gpu::TraceLog::GetInstance()->GetCategory(category); \ + if (base::subtle::Acquire_Load( \ + &(GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic))->enabled_)) { \ + gpu::TraceLog::GetInstance()->AddTraceEvent( \ + gpu::GPU_TRACE_EVENT_PHASE_BEGIN, \ + __FILE__, __LINE__, \ + GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ + name, \ + arg1name, arg1val, \ + arg2name, arg2val); \ + } + +// Records a single END event for "name" immediately. If the category +// is not enabled, then this does nothing. +#define GPU_TRACE_EVENT_END0(category, name) \ + static gpu::TraceCategory* \ + GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic) = \ + gpu::TraceLog::GetInstance()->GetCategory(category); \ + if (base::subtle::Acquire_Load( \ + &(GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic))->enabled_)) { \ + gpu::TraceLog::GetInstance()->AddTraceEvent( \ + gpu::GPU_TRACE_EVENT_PHASE_END, \ + __FILE__, __LINE__, \ + GPU_TRACE_EVENT_UNIQUE_IDENTIFIER(catstatic), \ + name, \ + NULL, 0, \ + NULL, 0); \ + } + + +namespace gpu { + +// Categories allow enabling/disabling of streams of trace events +// Don't manipulate the category object directly, as this may lead +// to threading issues. Use the TraceLog methods instead. +class TraceCategory { + public: + TraceCategory(); + ~TraceCategory(); + + void set(const char* name, bool enabled) { + name_ = name; + base::subtle::NoBarrier_Store(&enabled_, + static_cast<base::subtle::Atomic32>(enabled)); + } + + const char* name() const { return name_; } + + // NEVER read these directly, let the macros do it for you + volatile base::subtle::Atomic32 enabled_; + protected: + const char* name_; +}; + +#define TRACE_MAX_NUM_ARGS 2 + +enum TraceEventPhase { + GPU_TRACE_EVENT_PHASE_BEGIN, + GPU_TRACE_EVENT_PHASE_END, + GPU_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 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_uint = 0ull; // zero all bits + 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_uint = 0ull; // zero all bits + value_.as_pointer = rhs; + } + explicit TraceValue(const char* rhs) : type_(TRACE_TYPE_STRING) { + value_.as_uint = 0ull; // zero all bits + value_.as_string = base::strdup(rhs); + } + TraceValue(const TraceValue& rhs) : type_(TRACE_TYPE_UNDEFINED) { + operator=(rhs); + } + ~TraceValue() { + Destroy(); + } + + TraceValue& operator=(const TraceValue& rhs); + bool operator==(const TraceValue& rhs) const; + bool operator!=(const TraceValue& rhs) const { + return !operator==(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; + } + + private: + union Value { + bool as_bool; + uint64 as_uint; + int64 as_int; + double as_double; + const void* as_pointer; + char* as_string; + }; + + Type type_; + Value value_; +}; + +// Output records are "Events" and can be obtained via the +// OutputCallback whenever the logging system decides to flush. This +// can happen at any time, on any thread, or you can programatically +// force it to happen. +struct TraceEvent { + static void AppendAsJSON(std::string* out, + const std::vector<TraceEvent>& events, + size_t start, + size_t count); + TraceEvent(); + ~TraceEvent(); + void AppendAsJSON(std::string* out) const; + + + unsigned long processId; + unsigned long threadId; + base::TimeTicks timestamp; + TraceEventPhase phase; + TraceCategory* category; + const char* name; + const char* argNames[TRACE_MAX_NUM_ARGS]; + TraceValue argValues[TRACE_MAX_NUM_ARGS]; +}; + + +class TraceLog { + public: + static TraceLog* GetInstance(); + + // Global enable of tracing. Currently enables all categories or not. + // TODO(nduca) Replaced with an Enable/DisableCategory() that + // implicitly controls the global logging state. + void SetEnabled(bool 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. + typedef Callback1<const std::string& /* json_events */>::Type OutputCallback; + void SetOutputCallback(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. + typedef Callback0::Type BufferFullCallback; + void SetBufferFullCallback(BufferFullCallback* cb); + + // Forwards data collected by a child process to the registered + // output callback. + void AddRemotelyCollectedData(const std::string& json_events); + + // Flushes all logged data to the callback. + void Flush(); + + // Called by GPU_TRACE_EVENT* macros, don't call this directly. + TraceCategory* GetCategory(const char* name); + + // Called by GPU_TRACE_EVENT* macros, don't call this directly. + void AddTraceEvent(TraceEventPhase phase, + const char* file, int line, + TraceCategory* category, + const char* name, + const char* arg1name, TraceValue arg1val, + const char* arg2name, TraceValue arg2val); + + private: + // This allows constructor and destructor to be private and usable only + // by the Singleton class. + friend struct StaticMemorySingletonTraits<TraceLog>; + + TraceLog(); + ~TraceLog(); + void FlushWithLockAlreadyHeld(); + + // TODO(nduca): switch to per-thread trace buffers to reduce thread + // synchronization. + base::Lock lock_; + bool enabled_; + scoped_ptr<OutputCallback> output_callback_; + scoped_ptr<BufferFullCallback> buffer_full_callback_; + std::vector<TraceEvent> logged_events_; + + DISALLOW_COPY_AND_ASSIGN(TraceLog); +}; + +namespace internal { + +// Used by GPU_TRACE_EVENTx macro. Do not use directly. +class TraceEndOnScopeClose { + public: + TraceEndOnScopeClose(const char* file, int line, + TraceCategory* category, + const char* name) + : file_(file) + , line_(line) + , category_(category) + , name_(name) { } + + ~TraceEndOnScopeClose() { + if (base::subtle::Acquire_Load(&category_->enabled_)) + gpu::TraceLog::GetInstance()->AddTraceEvent( + gpu::GPU_TRACE_EVENT_PHASE_END, + file_, line_, + category_, + name_, + NULL, 0, NULL, 0); + } + + private: + const char* file_; + int line_; + TraceCategory* category_; + const char* name_; +}; + +} // namespace internal + +} // namespace gpu +#endif // __native_client__ +#endif // GPU_TRACE_EVENT_H_ diff --git a/gpu/gpu.gyp b/gpu/gpu.gyp index 33cd4d4..265ec80 100644 --- a/gpu/gpu.gyp +++ b/gpu/gpu.gyp @@ -25,6 +25,21 @@ }, 'targets': [ { + 'target_name': 'gpu_common', + 'type': 'static_library', + 'dependencies': [ + '../base/base.gyp:base', + '../base/third_party/dynamic_annotations/dynamic_annotations.gyp:dynamic_annotations', + ], + 'include_dirs': [ + '..', + ], + 'sources': [ + 'common/gpu_trace_event.cc', + 'common/gpu_trace_event.h', + ], + }, + { 'target_name': 'command_buffer_common', 'type': 'static_library', 'include_dirs': [ @@ -152,6 +167,7 @@ }, 'dependencies': [ 'command_buffer_common', + 'gpu_common', ], 'sources': [ 'command_buffer/client/cmd_buffer_helper.cc', @@ -177,6 +193,7 @@ }, 'dependencies': [ 'command_buffer_common', + 'gpu_common', '../base/base.gyp:base', '../ui/gfx/gl/gl.gyp:gl', '../ui/gfx/surface/surface.gyp:surface', @@ -247,6 +264,7 @@ 'command_buffer_client', 'command_buffer_common', 'command_buffer_service', + 'gpu_common', 'gpu_unittest_utils', 'gles2_implementation_client_side_arrays', 'gles2_cmd_helper', @@ -265,15 +283,26 @@ 'command_buffer/common/gles2_cmd_format_test_autogen.h', 'command_buffer/common/gles2_cmd_id_test.cc', 'command_buffer/common/gles2_cmd_id_test_autogen.h', + 'command_buffer/common/gles2_cmd_format_test.cc', + 'command_buffer/common/gles2_cmd_format_test_autogen.h', + 'command_buffer/common/gles2_cmd_id_test.cc', + 'command_buffer/common/gles2_cmd_id_test_autogen.h', + 'command_buffer/common/gles2_cmd_format_test.cc', + 'command_buffer/common/gles2_cmd_format_test_autogen.h', + 'command_buffer/common/gles2_cmd_id_test.cc', + 'command_buffer/common/gles2_cmd_id_test_autogen.h', 'command_buffer/common/id_allocator_test.cc', - 'command_buffer/common/trace_event.h', 'command_buffer/common/unittest_main.cc', 'command_buffer/service/buffer_manager_unittest.cc', + 'command_buffer/service/context_group_unittest.cc', + 'command_buffer/service/cmd_parser_test.cc', 'command_buffer/service/cmd_parser_test.cc', 'command_buffer/service/common_decoder_unittest.cc', - 'command_buffer/service/context_group_unittest.cc', 'command_buffer/service/feature_info_unittest.cc', 'command_buffer/service/framebuffer_manager_unittest.cc', + 'command_buffer/service/gpu_scheduler_unittest.cc', + 'command_buffer/service/gles2_cmd_decoder_unittest_base.h', + 'command_buffer/service/gles2_cmd_decoder_unittest_base.cc', 'command_buffer/service/gles2_cmd_decoder_unittest.cc', 'command_buffer/service/gles2_cmd_decoder_unittest_1.cc', 'command_buffer/service/gles2_cmd_decoder_unittest_1_autogen.h', @@ -281,9 +310,6 @@ 'command_buffer/service/gles2_cmd_decoder_unittest_2_autogen.h', 'command_buffer/service/gles2_cmd_decoder_unittest_3.cc', 'command_buffer/service/gles2_cmd_decoder_unittest_3_autogen.h', - 'command_buffer/service/gles2_cmd_decoder_unittest_base.cc', - 'command_buffer/service/gles2_cmd_decoder_unittest_base.h', - 'command_buffer/service/gpu_scheduler_unittest.cc', 'command_buffer/service/id_manager_unittest.cc', 'command_buffer/service/mocks.cc', 'command_buffer/service/mocks.h', @@ -291,8 +317,8 @@ 'command_buffer/service/renderbuffer_manager_unittest.cc', 'command_buffer/service/shader_manager_unittest.cc', 'command_buffer/service/shader_translator_unittest.cc', - 'command_buffer/service/test_helper.cc', 'command_buffer/service/test_helper.h', + 'command_buffer/service/test_helper.cc', 'command_buffer/service/texture_manager_unittest.cc', ], }, diff --git a/ppapi/proxy/host_dispatcher.cc b/ppapi/proxy/host_dispatcher.cc index c3acc5e..1482096 100644 --- a/ppapi/proxy/host_dispatcher.cc +++ b/ppapi/proxy/host_dispatcher.cc @@ -6,8 +6,8 @@ #include <map> -#include "base/debug/trace_event.h" #include "base/logging.h" +#include "gpu/common/gpu_trace_event.h" #include "ppapi/c/private/ppb_proxy_private.h" #include "ppapi/c/dev/ppb_var_deprecated.h" #include "ppapi/proxy/host_var_serialization_rules.h" @@ -129,9 +129,9 @@ bool HostDispatcher::IsPlugin() const { } bool HostDispatcher::Send(IPC::Message* msg) { - TRACE_EVENT2("ppapi proxy", "HostDispatcher::Send", - "Class", IPC_MESSAGE_ID_CLASS(msg->type()), - "Line", IPC_MESSAGE_ID_LINE(msg->type())); + GPU_TRACE_EVENT2("ppapi proxy", "HostDispatcher::Send", + "Class", IPC_MESSAGE_ID_CLASS(msg->type()), + "Line", IPC_MESSAGE_ID_LINE(msg->type())); // Normal sync messages are set to unblock, which would normally cause the // plugin to be reentered to process them. We only want to do this when we // know the plugin is in a state to accept reentrancy. Since the plugin side @@ -143,9 +143,9 @@ bool HostDispatcher::Send(IPC::Message* msg) { } bool HostDispatcher::OnMessageReceived(const IPC::Message& msg) { - TRACE_EVENT2("ppapi proxy", "HostDispatcher::OnMessageReceived", - "Class", IPC_MESSAGE_ID_CLASS(msg.type()), - "Line", IPC_MESSAGE_ID_LINE(msg.type())); + GPU_TRACE_EVENT2("ppapi proxy", "HostDispatcher::OnMessageReceived", + "Class", IPC_MESSAGE_ID_CLASS(msg.type()), + "Line", IPC_MESSAGE_ID_LINE(msg.type())); // We only want to allow reentrancy when the most recent message from the // plugin was a scripting message. We save the old state of the flag on the // stack in case we're (we are the host) being reentered ourselves. The flag diff --git a/ppapi/proxy/plugin_dispatcher.cc b/ppapi/proxy/plugin_dispatcher.cc index 4c3d287..26a35e3 100644 --- a/ppapi/proxy/plugin_dispatcher.cc +++ b/ppapi/proxy/plugin_dispatcher.cc @@ -10,7 +10,7 @@ #include "base/logging.h" #include "ipc/ipc_message.h" #include "ipc/ipc_sync_channel.h" -#include "base/debug/trace_event.h" +#include "gpu/common/gpu_trace_event.h" #include "ppapi/c/pp_errors.h" #include "ppapi/proxy/interface_proxy.h" #include "ppapi/proxy/plugin_message_filter.h" @@ -86,9 +86,9 @@ bool PluginDispatcher::IsPlugin() const { } bool PluginDispatcher::Send(IPC::Message* msg) { - TRACE_EVENT2("ppapi proxy", "PluginDispatcher::Send", - "Class", IPC_MESSAGE_ID_CLASS(msg->type()), - "Line", IPC_MESSAGE_ID_LINE(msg->type())); + GPU_TRACE_EVENT2("ppapi proxy", "PluginDispatcher::Send", + "Class", IPC_MESSAGE_ID_CLASS(msg->type()), + "Line", IPC_MESSAGE_ID_LINE(msg->type())); // We always want plugin->renderer messages to arrive in-order. If some sync // and some async messages are send in response to a synchronous // renderer->plugin call, the sync reply will be processed before the async @@ -101,9 +101,9 @@ bool PluginDispatcher::Send(IPC::Message* msg) { } bool PluginDispatcher::OnMessageReceived(const IPC::Message& msg) { - TRACE_EVENT2("ppapi proxy", "PluginDispatcher::OnMessageReceived", - "Class", IPC_MESSAGE_ID_CLASS(msg.type()), - "Line", IPC_MESSAGE_ID_LINE(msg.type())); + GPU_TRACE_EVENT2("ppapi proxy", "PluginDispatcher::OnMessageReceived", + "Class", IPC_MESSAGE_ID_CLASS(msg.type()), + "Line", IPC_MESSAGE_ID_LINE(msg.type())); // Handle common control messages. if (Dispatcher::OnMessageReceived(msg)) return true; diff --git a/webkit/glue/webkit_glue.gypi b/webkit/glue/webkit_glue.gypi index a949168..1e1bfec 100644 --- a/webkit/glue/webkit_glue.gypi +++ b/webkit/glue/webkit_glue.gypi @@ -107,6 +107,7 @@ 'dependencies': [ '<(DEPTH)/app/app.gyp:app_base', '<(DEPTH)/base/base.gyp:base_i18n', + '<(DEPTH)/gpu/gpu.gyp:gpu_common', '<(DEPTH)/gpu/gpu.gyp:gles2_implementation', '<(DEPTH)/net/net.gyp:net', '<(DEPTH)/ppapi/ppapi.gyp:ppapi_shared_impl', diff --git a/webkit/glue/webkitclient_impl.cc b/webkit/glue/webkitclient_impl.cc index 4244bc3f..882cb42 100644 --- a/webkit/glue/webkitclient_impl.cc +++ b/webkit/glue/webkitclient_impl.cc @@ -25,6 +25,7 @@ #include "base/synchronization/lock.h" #include "base/time.h" #include "base/utf_string_conversions.h" +#include "gpu/common/gpu_trace_event.h" #include "grit/webkit_chromium_resources.h" #include "grit/webkit_resources.h" #include "grit/webkit_strings.h" @@ -283,12 +284,16 @@ void WebKitClientImpl::histogramEnumeration( void WebKitClientImpl::traceEventBegin(const char* name, void* id, const char* extra) { - TRACE_EVENT_BEGIN_ETW(name, id, extra); + TRACE_EVENT_BEGIN(name, id, extra); + GPU_TRACE_EVENT_BEGIN2("webkit", name, + "id", id, + "extra", extra ? extra : ""); } void WebKitClientImpl::traceEventEnd(const char* name, void* id, const char* extra) { - TRACE_EVENT_END_ETW(name, id, extra); + TRACE_EVENT_END(name, id, extra); + GPU_TRACE_EVENT_END0("webkit", name); } namespace { diff --git a/webkit/tools/test_shell/test_shell_main.cc b/webkit/tools/test_shell/test_shell_main.cc index e107b6a..49ed62b 100644 --- a/webkit/tools/test_shell/test_shell_main.cc +++ b/webkit/tools/test_shell/test_shell_main.cc @@ -158,6 +158,9 @@ int main(int argc, char* argv[]) { platform.SuppressErrorReporting(); } + if (parsed_command_line.HasSwitch(test_shell::kEnableTracing)) + base::debug::TraceLog::StartTracing(); + net::HttpCache::Mode cache_mode = net::HttpCache::NORMAL; // This is a special mode where JS helps the browser implement diff --git a/webkit/tools/test_shell/test_shell_switches.cc b/webkit/tools/test_shell/test_shell_switches.cc index fd88861..713aaed 100644 --- a/webkit/tools/test_shell/test_shell_switches.cc +++ b/webkit/tools/test_shell/test_shell_switches.cc @@ -1,4 +1,4 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2006-2008 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. @@ -65,6 +65,9 @@ const char kDebugMemoryInUse[] = "debug-memory-in-use"; // Enable cookies on the file:// scheme. --layout-tests also enables this. const char kEnableFileCookies[] = "enable-file-cookies"; +// Enable tracing events (see base/debug/trace_event.h) +const char kEnableTracing[] = "enable-tracing"; + // Allow scripts to close windows in all cases. const char kAllowScriptsToCloseWindows[] = "allow-scripts-to-close-windows"; diff --git a/webkit/tools/test_shell/test_shell_switches.h b/webkit/tools/test_shell/test_shell_switches.h index 884b66625..dd4d451 100644 --- a/webkit/tools/test_shell/test_shell_switches.h +++ b/webkit/tools/test_shell/test_shell_switches.h @@ -1,4 +1,4 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2006-2008 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. @@ -27,6 +27,7 @@ extern const char kDumpStatsTable[]; extern const char kCacheDir[]; extern const char kDebugMemoryInUse[]; extern const char kEnableFileCookies[]; +extern const char kEnableTracing[]; extern const char kAllowScriptsToCloseWindows[]; extern const char kCheckLayoutTestSystemDeps[]; extern const char kGDB[]; diff --git a/webkit/tools/test_shell/test_shell_win.cc b/webkit/tools/test_shell/test_shell_win.cc index 8245b6e..6b4d00f7 100644 --- a/webkit/tools/test_shell/test_shell_win.cc +++ b/webkit/tools/test_shell/test_shell_win.cc @@ -479,7 +479,7 @@ void TestShell::LoadURLForFrame(const GURL& url, if (!url.is_valid()) return; - TRACE_EVENT_BEGIN_ETW("url.load", this, url.spec()); + TRACE_EVENT_BEGIN("url.load", this, url.spec()); if (IsSVGTestURL(url)) { SizeToSVG(); diff --git a/webkit/tools/test_shell/test_webview_delegate.cc b/webkit/tools/test_shell/test_webview_delegate.cc index 4fe60e8..745b2d0 100644 --- a/webkit/tools/test_shell/test_webview_delegate.cc +++ b/webkit/tools/test_shell/test_webview_delegate.cc @@ -819,7 +819,7 @@ void TestWebViewDelegate::didFailLoad( } void TestWebViewDelegate::didFinishLoad(WebFrame* frame) { - TRACE_EVENT_END_ETW("frame.load", this, frame->url().spec()); + TRACE_EVENT_END("frame.load", this, frame->url().spec()); UpdateAddressBar(frame->view()); LocationChangeDone(frame); } @@ -877,7 +877,7 @@ void TestWebViewDelegate::willSendRequest( header != clear_headers_.end(); ++header) request.clearHTTPHeaderField(WebString::fromUTF8(*header)); - TRACE_EVENT_BEGIN_ETW("url.load", identifier, request_url); + TRACE_EVENT_BEGIN("url.load", identifier, request_url); // Set the new substituted URL. request.setURL(GURL(TestShell::RewriteLocalUrl(request_url))); } @@ -888,7 +888,7 @@ void TestWebViewDelegate::didReceiveResponse( void TestWebViewDelegate::didFinishResourceLoad( WebFrame* frame, unsigned identifier) { - TRACE_EVENT_END_ETW("url.load", identifier, ""); + TRACE_EVENT_END("url.load", identifier, ""); resource_identifier_map_.erase(identifier); } |