diff options
| -rw-r--r-- | base/base.gyp | 2 | ||||
| -rw-r--r-- | base/base.gypi | 2 | ||||
| -rw-r--r-- | base/trace_event.h | 9 | ||||
| -rw-r--r-- | base/trace_event_win.cc | 114 | ||||
| -rw-r--r-- | base/trace_event_win.h | 145 | ||||
| -rw-r--r-- | base/trace_event_win_unittest.cc | 282 |
6 files changed, 551 insertions, 3 deletions
diff --git a/base/base.gyp b/base/base.gyp index 23201d2..88f8702 100644 --- a/base/base.gyp +++ b/base/base.gyp @@ -140,6 +140,7 @@ 'time_win_unittest.cc', 'timer_unittest.cc', 'tools_sanity_unittest.cc', + 'trace_event_win_unittest.cc', 'tracked_objects_unittest.cc', 'tuple_unittest.cc', 'utf_offset_string_conversions_unittest.cc', @@ -206,6 +207,7 @@ 'scoped_variant_win_unittest.cc', 'system_monitor_unittest.cc', 'time_win_unittest.cc', + 'trace_event_win_unittest.cc', 'win_util_unittest.cc', 'wmi_util_unittest.cc', ], diff --git a/base/base.gypi b/base/base.gypi index b5c3f31..ecec5cd 100644 --- a/base/base.gypi +++ b/base/base.gypi @@ -249,6 +249,7 @@ 'time_win.cc', 'timer.cc', 'timer.h', + 'trace_event_win.cc', 'trace_event.cc', 'trace_event.h', 'tracked.cc', @@ -353,6 +354,7 @@ 'file_descriptor_shuffle.cc', 'message_pump_libevent.cc', 'string16.cc', + 'trace_event.cc', ], },], ], diff --git a/base/trace_event.h b/base/trace_event.h index 46b8a37..7537b97 100644 --- a/base/trace_event.h +++ b/base/trace_event.h @@ -18,8 +18,10 @@ #include "build/build_config.h" #if defined(OS_WIN) -#include <windows.h> -#endif +// On Windows we always pull in an alternative implementation +// which logs to Event Tracing for Windows. +#include "base/trace_event_win.h" +#else // defined(OS_WIN) #include <string> @@ -34,7 +36,7 @@ #define TRACE_EVENT_END(name, id, extra) ((void) 0) #define TRACE_EVENT_INSTANT(name, id, extra) ((void) 0) -#else +#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); @@ -129,5 +131,6 @@ class TraceLog { }; } // namespace base +#endif // defined(OS_WIN) #endif // BASE_TRACE_EVENT_H_ diff --git a/base/trace_event_win.cc b/base/trace_event_win.cc new file mode 100644 index 0000000..eae6782 --- /dev/null +++ b/base/trace_event_win.cc @@ -0,0 +1,114 @@ +// Copyright (c) 2009 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/trace_event_win.h" + +#include "base/atomicops.h" +#include "base/logging_win.h" +#include "base/singleton.h" +#include <initguid.h> // NOLINT + +namespace base { + +// {3DADA31D-19EF-4dc1-B345-037927193422} +const GUID kChromeTraceProviderName = { + 0x3dada31d, 0x19ef, 0x4dc1, 0xb3, 0x45, 0x3, 0x79, 0x27, 0x19, 0x34, 0x22 }; + +// {B967AE67-BB22-49d7-9406-55D91EE1D560} +const GUID kTraceEventClass32 = { + 0xb967ae67, 0xbb22, 0x49d7, 0x94, 0x6, 0x55, 0xd9, 0x1e, 0xe1, 0xd5, 0x60 }; + +// {97BE602D-2930-4ac3-8046-B6763B631DFE} +const GUID kTraceEventClass64 = { + 0x97be602d, 0x2930, 0x4ac3, 0x80, 0x46, 0xb6, 0x76, 0x3b, 0x63, 0x1d, 0xfe}; + + +TraceLog::TraceLog() : EtwTraceProvider(base::kChromeTraceProviderName) { + Register(); +} + +TraceLog* TraceLog::Get() { + return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog>>::get(); +} + +bool TraceLog::StartTracing() { + return true; +} + +void TraceLog::TraceEvent(const char* name, + size_t name_len, + base::TraceLog::EventType type, + const void* id, + const char* extra, + size_t extra_len) { + // Make sure we don't touch NULL. + if (name == NULL) + name = ""; + if (extra == NULL) + extra = ""; + + EtwEventType etw_type = 0; + switch (type) { + case base::TraceLog::EVENT_BEGIN: + etw_type = base::kTraceEventTypeBegin; + break; + case base::TraceLog::EVENT_END: + etw_type = base::kTraceEventTypeEnd; + break; + + case base::TraceLog::EVENT_INSTANT: + etw_type = base::kTraceEventTypeInstant; + break; + + default: + NOTREACHED() << "Unknown event type"; + etw_type = base::kTraceEventTypeInstant; + break; + } + + EtwMofEvent<5> event(base::kTraceEventClass32, + etw_type, + TRACE_LEVEL_INFORMATION); + event.SetField(0, name_len + 1, name); + event.SetField(1, sizeof(id), &id); + event.SetField(2, extra_len + 1, extra); + + // See whether we're to capture a backtrace. + void* backtrace[32]; + if (enable_flags() & base::CAPTURE_STACK_TRACE) { + DWORD hash = 0; + DWORD depth = CaptureStackBackTrace(0, + arraysize(backtrace), + backtrace, + &hash); + event.SetField(3, sizeof(depth), &depth); + event.SetField(4, sizeof(backtrace[0]) * depth, backtrace); + } + + // Trace the event. + Log(event.get()); +} + +void TraceLog::Trace(const char* name, + size_t name_len, + EventType type, + const void* id, + const char* extra, + size_t extra_len) { + TraceLog* provider = TraceLog::Get(); + if (provider && provider->IsTracing()) { + // Compute the name & extra lengths if not supplied already. + if (name_len == -1) + name_len = (name == NULL) ? 0 : strlen(name); + if (extra_len == -1) + extra_len = (extra == NULL) ? 0 : strlen(extra); + + provider->TraceEvent(name, name_len, type, id, extra, extra_len); + } +} + +void TraceLog::Resurrect() { + StaticMemorySingletonTraits<TraceLog>::Resurrect(); +} + +} // namespace base diff --git a/base/trace_event_win.h b/base/trace_event_win.h new file mode 100644 index 0000000..14f768f --- /dev/null +++ b/base/trace_event_win.h @@ -0,0 +1,145 @@ +// 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. + +// This file contains the Windows-specific declarations for trace_event.h. +#ifndef BASE_TRACE_EVENT_WIN_H_ +#define BASE_TRACE_EVENT_WIN_H_ + +#include <string> +#include "base/event_trace_provider_win.h" + +#define TRACE_EVENT_BEGIN(name, id, extra) \ + base::TraceLog::Trace(name, \ + base::TraceLog::EVENT_BEGIN, \ + reinterpret_cast<const void*>(id), \ + extra); + +#define TRACE_EVENT_END(name, id, extra) \ + base::TraceLog::Trace(name, \ + base::TraceLog::EVENT_END, \ + reinterpret_cast<const void*>(id), \ + extra); + +#define TRACE_EVENT_INSTANT(name, id, extra) \ + base::TraceLog::Trace(name, \ + base::TraceLog::EVENT_INSTANT, \ + reinterpret_cast<const void*>(id), \ + extra); + +// Fwd. +template <typename Type> +struct StaticMemorySingletonTraits; + +namespace base { + +// This EtwTraceProvider subclass implements ETW logging +// for the macros above on Windows. +class TraceLog : public EtwTraceProvider { + public: + enum EventType { + EVENT_BEGIN, + EVENT_END, + EVENT_INSTANT + }; + + // Start logging trace events. + // This is a noop in this implementation. + static bool StartTracing(); + + // Trace begin/end/instant events, this is the bottleneck implementation + // all the others defer to. + // Allowing the use of std::string for name or extra is a convenience, + // whereas passing name or extra as a const char* avoids the construction + // of temporary std::string instances. + // If -1 is passed for name_len or extra_len, the strlen of the string will + // be used for length. + static void Trace(const char* name, + size_t name_len, + 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, + EventType type, + const void* id, + const std::string& extra) { + return Trace(name, -1, type, id, extra.c_str(), extra.length()); + } + + // Allows passing extra as a const char* to avoid constructing temporary + // std::string instances where not needed. + static void Trace(const char* name, + EventType type, + const void* id, + const char* extra) { + return Trace(name, -1, type, id, extra, -1); + } + + // Retrieves the singleton. + // Note that this may return NULL post-AtExit processing. + static TraceLog* Get(); + + // Returns true iff tracing is turned on. + bool IsTracing() { + return enable_level() >= TRACE_LEVEL_INFORMATION; + } + + // Emit a trace of type |type| containing |name|, |id|, and |extra|. + // Note: |name| and |extra| must be NULL, or a zero-terminated string of + // length |name_len| or |extra_len| respectively. + // Note: if name_len or extra_len are -1, the length of the corresponding + // string will be used. + void TraceEvent(const char* name, + size_t name_len, + base::TraceLog::EventType type, + const void* id, + const char* extra, + size_t extra_len); + + // Exposed for unittesting only, allows resurrecting our + // singleton instance post-AtExit processing. + static void Resurrect(); + + private: + // Ensure only the provider can construct us. + friend struct StaticMemorySingletonTraits<TraceLog>; + TraceLog(); + + DISALLOW_COPY_AND_ASSIGN(TraceLog); +}; + +// The ETW trace provider GUID. +extern const GUID kChromeTraceProviderName; + +// The ETW event class GUID for 32 bit events. +extern const GUID kTraceEventClass32; + +// The ETW event class GUID for 64 bit events. +extern const GUID kTraceEventClass64; + +// The ETW event types, IDs 0x00-0x09 are reserved, so start at 0x10. +const EtwEventType kTraceEventTypeBegin = 0x10; +const EtwEventType kTraceEventTypeEnd = 0x11; +const EtwEventType kTraceEventTypeInstant = 0x12; + +// If this flag is set in enable flags +enum TraceEventFlags { + CAPTURE_STACK_TRACE = 0x0001, +}; + +// The event format consists of: +// The "name" string as a zero-terminated ASCII string. +// The id pointer in the machine bitness. +// The "extra" string as a zero-terminated ASCII string. +// Optionally the stack trace, consisting of a DWORD "depth", followed +// by an array of void* (machine bitness) of length "depth". + +// Forward decl. +struct TraceLogSingletonTraits; + +} // namespace base + +#endif // BASE_TRACE_EVENT_WIN_H_ diff --git a/base/trace_event_win_unittest.cc b/base/trace_event_win_unittest.cc new file mode 100644 index 0000000..50769c5 --- /dev/null +++ b/base/trace_event_win_unittest.cc @@ -0,0 +1,282 @@ +// 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/trace_event.h" +#include <strstream> +#include "base/basictypes.h" +#include "base/file_util.h" +#include "base/event_trace_consumer_win.h" +#include "base/event_trace_controller_win.h" +#include "base/win_util.h" +#include "testing/gmock/include/gmock/gmock.h" +#include "testing/gtest/include/gtest/gtest.h" +#include <initguid.h> // NOLINT - must be last include. + +namespace { +using testing::_; +using testing::AnyNumber; +using testing::InSequence; +using testing::Ge; +using testing::Le; +using testing::NotNull; + +// Data for unittests traces. +const char kEmpty[] = ""; +const char kName[] = "unittest.trace_name"; +const char kExtra[] = "UnittestDummyExtraString"; +const void* kId = kName; + +const wchar_t kTestSessionName[] = L"TraceEvent unittest session"; + +MATCHER_P(BufferStartsWith, str, "Buffer starts with") { + return memcmp(arg, str.c_str(), str.length()) == 0; +} + +// Duplicated from <evntrace.h> to fix link problems. +DEFINE_GUID( /* 68fdd900-4a3e-11d1-84f4-0000f80464e3 */ + kEventTraceGuid, + 0x68fdd900, + 0x4a3e, + 0x11d1, + 0x84, 0xf4, 0x00, 0x00, 0xf8, 0x04, 0x64, 0xe3); + +class TestEventConsumer: public EtwTraceConsumerBase<TestEventConsumer> { + public: + TestEventConsumer() { + EXPECT_TRUE(current_ == NULL); + current_ = this; + } + + ~TestEventConsumer() { + EXPECT_TRUE(current_ == this); + current_ = NULL; + } + + MOCK_METHOD4(Event, void(REFGUID event_class, + EtwEventType event_type, + size_t buf_len, + const void* buf)); + + static void ProcessEvent(EVENT_TRACE* event) { + ASSERT_TRUE(current_ != NULL); + current_->Event(event->Header.Guid, + event->Header.Class.Type, + event->MofLength, + event->MofData); + } + + private: + static TestEventConsumer* current_; +}; + +TestEventConsumer* TestEventConsumer::current_ = NULL; + +class TraceEventTest: public testing::Test { + public: + void SetUp() { + bool is_xp = win_util::GetWinVersion() < win_util::WINVERSION_VISTA; + + // Resurrect and initialize the TraceLog singleton instance. + // On Vista and better, we need the provider registered before we + // start the private, in-proc session, but on XP we need the global + // session created and the provider enabled before we register our + // provider. + if (!is_xp) { + base::TraceLog::Resurrect(); + base::TraceLog* tracelog = base::TraceLog::Get(); + ASSERT_TRUE(tracelog != NULL); + } + + // Create the log file. + ASSERT_TRUE(file_util::CreateTemporaryFile(&log_file_)); + + // Create a private log session on the file. + EtwTraceProperties prop; + ASSERT_HRESULT_SUCCEEDED(prop.SetLoggerFileName(log_file_.value().c_str())); + EVENT_TRACE_PROPERTIES& p = *prop.get(); + p.Wnode.ClientContext = 1; // QPC timer accuracy. + p.LogFileMode = EVENT_TRACE_FILE_MODE_SEQUENTIAL; // Sequential log. + + // On Vista and later, we create a private in-process log session, because + // otherwise we'd need administrator privileges. Unfortunately we can't + // do the same on XP and better, because the semantics of a private + // logger session are different, and the IN_PROC flag is not supported. + if (!is_xp) { + p.LogFileMode |= EVENT_TRACE_PRIVATE_IN_PROC | // In-proc for non-admin. + EVENT_TRACE_PRIVATE_LOGGER_MODE; // Process-private log. + } + + p.MaximumFileSize = 100; // 100M file size. + p.FlushTimer = 1; // 1 second flush lag. + ASSERT_HRESULT_SUCCEEDED(controller_.Start(kTestSessionName, &prop)); + + // Enable the TraceLog provider GUID. + ASSERT_HRESULT_SUCCEEDED( + controller_.EnableProvider(base::kChromeTraceProviderName, + TRACE_LEVEL_INFORMATION, + 0)); + + if (is_xp) { + base::TraceLog::Resurrect(); + base::TraceLog* tracelog = base::TraceLog::Get(); + ASSERT_TRUE(tracelog != NULL); + } + } + + void TearDown() { + EtwTraceProperties prop; + if (controller_.session() != 0) + EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop)); + + if (!log_file_.value().empty()) + file_util::Delete(log_file_, false); + } + + void ExpectEvent(REFGUID guid, + EtwEventType type, + const char* name, + size_t name_len, + const void* id, + const char* extra, + size_t extra_len) { + // Build the trace event buffer we expect will result from this. + std::stringbuf str; + str.sputn(name, name_len + 1); + str.sputn(reinterpret_cast<const char*>(&id), sizeof(id)); + str.sputn(extra, extra_len + 1); + + // And set up the expectation for the event callback. + EXPECT_CALL(consumer_, Event(guid, + type, + testing::Ge(str.str().length()), + BufferStartsWith(str.str()))); + } + + void ExpectPlayLog() { + // Ignore EventTraceGuid events. + EXPECT_CALL(consumer_, Event(kEventTraceGuid, _, _, _)) + .Times(AnyNumber()); + } + + void PlayLog() { + EtwTraceProperties prop; + EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop)); + ASSERT_HRESULT_SUCCEEDED( + consumer_.OpenFileSession(log_file_.value().c_str())); + + ASSERT_HRESULT_SUCCEEDED(consumer_.Consume()); + } + + private: + EtwTraceController controller_; + FilePath log_file_; + TestEventConsumer consumer_; +}; + +} // namespace + + +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. + base::TraceLog::Trace(kName, + strlen(kName), + base::TraceLog::EVENT_BEGIN, + kId, + kExtra, + strlen(kExtra)); + + ExpectEvent(base::kTraceEventClass32, + base::kTraceEventTypeBegin, + kName, strlen(kName), + kId, + kExtra, strlen(kExtra)); + + // Const char* version. + base::TraceLog::Trace(static_cast<const char*>(kName), + base::TraceLog::EVENT_END, + kId, + static_cast<const char*>(kExtra)); + + ExpectEvent(base::kTraceEventClass32, + base::kTraceEventTypeEnd, + kName, strlen(kName), + kId, + kExtra, strlen(kExtra)); + + // std::string extra version. + base::TraceLog::Trace(static_cast<const char*>(kName), + base::TraceLog::EVENT_INSTANT, + kId, + std::string(kExtra)); + + ExpectEvent(base::kTraceEventClass32, + base::kTraceEventTypeInstant, + kName, strlen(kName), + kId, + kExtra, strlen(kExtra)); + + + // Test for sanity on NULL inputs. + base::TraceLog::Trace(NULL, + 0, + base::TraceLog::EVENT_BEGIN, + kId, + NULL, + 0); + + ExpectEvent(base::kTraceEventClass32, + base::kTraceEventTypeBegin, + kEmpty, 0, + kId, + kEmpty, 0); + + base::TraceLog::Trace(NULL, + -1, + base::TraceLog::EVENT_END, + kId, + NULL, + -1); + + ExpectEvent(base::kTraceEventClass32, + base::kTraceEventTypeEnd, + kEmpty, 0, + kId, + kEmpty, 0); + + PlayLog(); +} + +TEST_F(TraceEventTest, Macros) { + ExpectPlayLog(); + + // The events should arrive in the same sequence as the expects. + InSequence in_sequence; + + TRACE_EVENT_BEGIN(kName, kId, kExtra); + ExpectEvent(base::kTraceEventClass32, + base::kTraceEventTypeBegin, + kName, strlen(kName), + kId, + kExtra, strlen(kExtra)); + + TRACE_EVENT_END(kName, kId, kExtra); + ExpectEvent(base::kTraceEventClass32, + base::kTraceEventTypeEnd, + kName, strlen(kName), + kId, + kExtra, strlen(kExtra)); + + TRACE_EVENT_INSTANT(kName, kId, kExtra); + ExpectEvent(base::kTraceEventClass32, + base::kTraceEventTypeInstant, + kName, strlen(kName), + kId, + kExtra, strlen(kExtra)); + + PlayLog(); +} |