base/debug/trace_event_win_unittest.cc

   1 // Copyright (c) 2011 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "base/debug/trace_event.h"
   6
   7 #include <strstream>
   8
   9 #include "base/at_exit.h"
  10 #include "base/basictypes.h"
  11 #include "base/file_util.h"
  12 #include "base/debug/trace_event.h"
  13 #include "base/debug/trace_event_win.h"
  14 #include "base/win/event_trace_consumer.h"
  15 #include "base/win/event_trace_controller.h"
  16 #include "base/win/event_trace_provider.h"
  17 #include "base/win/windows_version.h"
  18 #include "testing/gmock/include/gmock/gmock.h"
  19 #include "testing/gtest/include/gtest/gtest.h"
  20 #include <initguid.h>  // NOLINT - must be last include.
  21
  22 namespace base {
  23 namespace debug {
  24
  25 namespace {
  26
  27 using testing::_;
  28 using testing::AnyNumber;
  29 using testing::InSequence;
  30 using testing::Ge;
  31 using testing::Le;
  32 using testing::NotNull;
  33
  34 using base::win::EtwEventType;
  35 using base::win::EtwTraceConsumerBase;
  36 using base::win::EtwTraceController;
  37 using base::win::EtwTraceProperties;
  38
  39 // Data for unittests traces.
  40 const char kEmpty[] = "";
  41 const char kName[] = "unittest.trace_name";
  42 const char kExtra[] = "UnittestDummyExtraString";
  43 const void* kId = kName;
  44
  45 const wchar_t kTestSessionName[] = L"TraceEvent unittest session";
  46
  47 MATCHER_P(BufferStartsWith, str, "Buffer starts with") {
  48   return memcmp(arg, str.c_str(), str.length()) == 0;
  49 }
  50
  51 // Duplicated from <evntrace.h> to fix link problems.
  52 DEFINE_GUID( /* 68fdd900-4a3e-11d1-84f4-0000f80464e3 */
  53     kEventTraceGuid,
  54     0x68fdd900,
  55     0x4a3e,
  56     0x11d1,
  57     0x84, 0xf4, 0x00, 0x00, 0xf8, 0x04, 0x64, 0xe3);
  58
  59 class TestEventConsumer: public EtwTraceConsumerBase<TestEventConsumer> {
  60  public:
  61   TestEventConsumer() {
  62     EXPECT_TRUE(current_ == NULL);
  63     current_ = this;
  64   }
  65
  66   ~TestEventConsumer() {
  67     EXPECT_TRUE(current_ == this);
  68     current_ = NULL;
  69   }
  70
  71   MOCK_METHOD4(Event, void(REFGUID event_class,
  72                       EtwEventType event_type,
  73                       size_t buf_len,
  74                       const void* buf));
  75
  76   static void ProcessEvent(EVENT_TRACE* event) {
  77     ASSERT_TRUE(current_ != NULL);
  78     current_->Event(event->Header.Guid,
  79                     event->Header.Class.Type,
  80                     event->MofLength,
  81                     event->MofData);
  82   }
  83
  84  private:
  85   static TestEventConsumer* current_;
  86 };
  87
  88 TestEventConsumer* TestEventConsumer::current_ = NULL;
  89
  90 class TraceEventWinTest: public testing::Test {
  91  public:
  92   TraceEventWinTest() {
  93   }
  94
  95   void SetUp() {
  96     bool is_xp = win::GetVersion() < base::win::VERSION_VISTA;
  97
  98     if (is_xp) {
  99       // Tear down any dangling session from an earlier failing test.
 100       EtwTraceProperties ignore;
 101       EtwTraceController::Stop(kTestSessionName, &ignore);
 102     }
 103
 104     // Resurrect and initialize the TraceLog singleton instance.
 105     // On Vista and better, we need the provider registered before we
 106     // start the private, in-proc session, but on XP we need the global
 107     // session created and the provider enabled before we register our
 108     // provider.
 109     TraceEventETWProvider* tracelog = NULL;
 110     if (!is_xp) {
 111       TraceEventETWProvider::Resurrect();
 112       tracelog = TraceEventETWProvider::GetInstance();
 113       ASSERT_TRUE(tracelog != NULL);
 114       ASSERT_FALSE(tracelog->IsTracing());
 115     }
 116
 117     // Create the log file.
 118     ASSERT_TRUE(file_util::CreateTemporaryFile(&log_file_));
 119
 120     // Create a private log session on the file.
 121     EtwTraceProperties prop;
 122     ASSERT_HRESULT_SUCCEEDED(prop.SetLoggerFileName(log_file_.value().c_str()));
 123     EVENT_TRACE_PROPERTIES& p = *prop.get();
 124     p.Wnode.ClientContext = 1;  // QPC timer accuracy.
 125     p.LogFileMode = EVENT_TRACE_FILE_MODE_SEQUENTIAL;   // Sequential log.
 126
 127     // On Vista and later, we create a private in-process log session, because
 128     // otherwise we'd need administrator privileges. Unfortunately we can't
 129     // do the same on XP and better, because the semantics of a private
 130     // logger session are different, and the IN_PROC flag is not supported.
 131     if (!is_xp) {
 132       p.LogFileMode |= EVENT_TRACE_PRIVATE_IN_PROC |  // In-proc for non-admin.
 133           EVENT_TRACE_PRIVATE_LOGGER_MODE;  // Process-private log.
 134     }
 135
 136     p.MaximumFileSize = 100;  // 100M file size.
 137     p.FlushTimer = 1;  // 1 second flush lag.
 138     ASSERT_HRESULT_SUCCEEDED(controller_.Start(kTestSessionName, &prop));
 139
 140     // Enable the TraceLog provider GUID.
 141     ASSERT_HRESULT_SUCCEEDED(
 142         controller_.EnableProvider(kChromeTraceProviderName,
 143                                    TRACE_LEVEL_INFORMATION,
 144                                    0));
 145
 146     if (is_xp) {
 147       TraceEventETWProvider::Resurrect();
 148       tracelog = TraceEventETWProvider::GetInstance();
 149     }
 150     ASSERT_TRUE(tracelog != NULL);
 151     EXPECT_TRUE(tracelog->IsTracing());
 152   }
 153
 154   void TearDown() {
 155     EtwTraceProperties prop;
 156     if (controller_.session() != 0)
 157       EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop));
 158
 159     if (!log_file_.value().empty())
 160       file_util::Delete(log_file_, false);
 161   }
 162
 163   void ExpectEvent(REFGUID guid,
 164                    EtwEventType type,
 165                    const char* name,
 166                    size_t name_len,
 167                    const void* id,
 168                    const char* extra,
 169                    size_t extra_len) {
 170     // Build the trace event buffer we expect will result from this.
 171     std::stringbuf str;
 172     str.sputn(name, name_len + 1);
 173     str.sputn(reinterpret_cast<const char*>(&id), sizeof(id));
 174     str.sputn(extra, extra_len + 1);
 175
 176     // And set up the expectation for the event callback.
 177     EXPECT_CALL(consumer_, Event(guid,
 178                                  type,
 179                                  testing::Ge(str.str().length()),
 180                                  BufferStartsWith(str.str())));
 181   }
 182
 183   void ExpectPlayLog() {
 184     // Ignore EventTraceGuid events.
 185     EXPECT_CALL(consumer_, Event(kEventTraceGuid, _, _, _))
 186         .Times(AnyNumber());
 187   }
 188
 189   void PlayLog() {
 190     EtwTraceProperties prop;
 191     EXPECT_HRESULT_SUCCEEDED(controller_.Flush(&prop));
 192     EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop));
 193     ASSERT_HRESULT_SUCCEEDED(
 194         consumer_.OpenFileSession(log_file_.value().c_str()));
 195
 196     ASSERT_HRESULT_SUCCEEDED(consumer_.Consume());
 197   }
 198
 199  private:
 200   // We want our singleton torn down after each test.
 201   ShadowingAtExitManager at_exit_manager_;
 202   EtwTraceController controller_;
 203   FilePath log_file_;
 204   TestEventConsumer consumer_;
 205 };
 206
 207 }  // namespace
 208
 209
 210 TEST_F(TraceEventWinTest, TraceLog) {
 211   ExpectPlayLog();
 212
 213   // The events should arrive in the same sequence as the expects.
 214   InSequence in_sequence;
 215
 216   // Full argument version, passing lengths explicitly.
 217   TraceEventETWProvider::Trace(kName,
 218                         strlen(kName),
 219                         TRACE_EVENT_PHASE_BEGIN,
 220                         kId,
 221                         kExtra,
 222                         strlen(kExtra));
 223
 224   ExpectEvent(kTraceEventClass32,
 225               kTraceEventTypeBegin,
 226               kName, strlen(kName),
 227               kId,
 228               kExtra, strlen(kExtra));
 229
 230   // Const char* version.
 231   TraceEventETWProvider::Trace(static_cast<const char*>(kName),
 232                         TRACE_EVENT_PHASE_END,
 233                         kId,
 234                         static_cast<const char*>(kExtra));
 235
 236   ExpectEvent(kTraceEventClass32,
 237               kTraceEventTypeEnd,
 238               kName, strlen(kName),
 239               kId,
 240               kExtra, strlen(kExtra));
 241
 242   // std::string extra version.
 243   TraceEventETWProvider::Trace(static_cast<const char*>(kName),
 244                         TRACE_EVENT_PHASE_INSTANT,
 245                         kId,
 246                         std::string(kExtra));
 247
 248   ExpectEvent(kTraceEventClass32,
 249               kTraceEventTypeInstant,
 250               kName, strlen(kName),
 251               kId,
 252               kExtra, strlen(kExtra));
 253
 254
 255   // Test for sanity on NULL inputs.
 256   TraceEventETWProvider::Trace(NULL,
 257                         0,
 258                         TRACE_EVENT_PHASE_BEGIN,
 259                         kId,
 260                         NULL,
 261                         0);
 262
 263   ExpectEvent(kTraceEventClass32,
 264               kTraceEventTypeBegin,
 265               kEmpty, 0,
 266               kId,
 267               kEmpty, 0);
 268
 269   TraceEventETWProvider::Trace(NULL,
 270                         -1,
 271                         TRACE_EVENT_PHASE_END,
 272                         kId,
 273                         NULL,
 274                         -1);
 275
 276   ExpectEvent(kTraceEventClass32,
 277               kTraceEventTypeEnd,
 278               kEmpty, 0,
 279               kId,
 280               kEmpty, 0);
 281
 282   PlayLog();
 283 }
 284
 285 TEST_F(TraceEventWinTest, Macros) {
 286   ExpectPlayLog();
 287
 288   // The events should arrive in the same sequence as the expects.
 289   InSequence in_sequence;
 290
 291   TRACE_EVENT_BEGIN_ETW(kName, kId, kExtra);
 292   ExpectEvent(kTraceEventClass32,
 293               kTraceEventTypeBegin,
 294               kName, strlen(kName),
 295               kId,
 296               kExtra, strlen(kExtra));
 297
 298   TRACE_EVENT_END_ETW(kName, kId, kExtra);
 299   ExpectEvent(kTraceEventClass32,
 300               kTraceEventTypeEnd,
 301               kName, strlen(kName),
 302               kId,
 303               kExtra, strlen(kExtra));
 304
 305   TRACE_EVENT_INSTANT_ETW(kName, kId, kExtra);
 306   ExpectEvent(kTraceEventClass32,
 307               kTraceEventTypeInstant,
 308               kName, strlen(kName),
 309               kId,
 310               kExtra, strlen(kExtra));
 311
 312   PlayLog();
 313 }
 314
 315 }  // namespace debug
 316 }  // namespace base