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/debug/trace_event.h"
  12 #include "base/debug/trace_event_win.h"
  13 #include "base/files/file_util.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(base::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       base::DeleteFile(log_file_, false);
 161
 162     // We want our singleton torn down after each test.
 163     TraceLog::DeleteForTesting();
 164   }
 165
 166   void ExpectEvent(REFGUID guid,
 167                    EtwEventType type,
 168                    const char* name,
 169                    size_t name_len,
 170                    const void* id,
 171                    const char* extra,
 172                    size_t extra_len) {
 173     // Build the trace event buffer we expect will result from this.
 174     std::stringbuf str;
 175     str.sputn(name, name_len + 1);
 176     str.sputn(reinterpret_cast<const char*>(&id), sizeof(id));
 177     str.sputn(extra, extra_len + 1);
 178
 179     // And set up the expectation for the event callback.
 180     EXPECT_CALL(consumer_, Event(guid,
 181                                  type,
 182                                  testing::Ge(str.str().length()),
 183                                  BufferStartsWith(str.str())));
 184   }
 185
 186   void ExpectPlayLog() {
 187     // Ignore EventTraceGuid events.
 188     EXPECT_CALL(consumer_, Event(kEventTraceGuid, _, _, _))
 189         .Times(AnyNumber());
 190   }
 191
 192   void PlayLog() {
 193     EtwTraceProperties prop;
 194     EXPECT_HRESULT_SUCCEEDED(controller_.Flush(&prop));
 195     EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop));
 196     ASSERT_HRESULT_SUCCEEDED(
 197         consumer_.OpenFileSession(log_file_.value().c_str()));
 198
 199     ASSERT_HRESULT_SUCCEEDED(consumer_.Consume());
 200   }
 201
 202  private:
 203   // We want our singleton torn down after each test.
 204   ShadowingAtExitManager at_exit_manager_;
 205   EtwTraceController controller_;
 206   FilePath log_file_;
 207   TestEventConsumer consumer_;
 208 };
 209
 210 }  // namespace
 211
 212
 213 TEST_F(TraceEventWinTest, TraceLog) {
 214   ExpectPlayLog();
 215
 216   // The events should arrive in the same sequence as the expects.
 217   InSequence in_sequence;
 218
 219   // Full argument version, passing lengths explicitly.
 220   TraceEventETWProvider::Trace(kName,
 221                         strlen(kName),
 222                         TRACE_EVENT_PHASE_BEGIN,
 223                         kId,
 224                         kExtra,
 225                         strlen(kExtra));
 226
 227   ExpectEvent(kTraceEventClass32,
 228               kTraceEventTypeBegin,
 229               kName, strlen(kName),
 230               kId,
 231               kExtra, strlen(kExtra));
 232
 233   // Const char* version.
 234   TraceEventETWProvider::Trace(static_cast<const char*>(kName),
 235                         TRACE_EVENT_PHASE_END,
 236                         kId,
 237                         static_cast<const char*>(kExtra));
 238
 239   ExpectEvent(kTraceEventClass32,
 240               kTraceEventTypeEnd,
 241               kName, strlen(kName),
 242               kId,
 243               kExtra, strlen(kExtra));
 244
 245   // std::string extra version.
 246   TraceEventETWProvider::Trace(static_cast<const char*>(kName),
 247                         TRACE_EVENT_PHASE_INSTANT,
 248                         kId,
 249                         std::string(kExtra));
 250
 251   ExpectEvent(kTraceEventClass32,
 252               kTraceEventTypeInstant,
 253               kName, strlen(kName),
 254               kId,
 255               kExtra, strlen(kExtra));
 256
 257
 258   // Test for sanity on NULL inputs.
 259   TraceEventETWProvider::Trace(NULL,
 260                         0,
 261                         TRACE_EVENT_PHASE_BEGIN,
 262                         kId,
 263                         NULL,
 264                         0);
 265
 266   ExpectEvent(kTraceEventClass32,
 267               kTraceEventTypeBegin,
 268               kEmpty, 0,
 269               kId,
 270               kEmpty, 0);
 271
 272   TraceEventETWProvider::Trace(NULL,
 273                         TraceEventETWProvider::kUseStrlen,
 274                         TRACE_EVENT_PHASE_END,
 275                         kId,
 276                         NULL,
 277                         TraceEventETWProvider::kUseStrlen);
 278
 279   ExpectEvent(kTraceEventClass32,
 280               kTraceEventTypeEnd,
 281               kEmpty, 0,
 282               kId,
 283               kEmpty, 0);
 284
 285   PlayLog();
 286 }
 287
 288 TEST_F(TraceEventWinTest, Macros) {
 289   ExpectPlayLog();
 290
 291   // The events should arrive in the same sequence as the expects.
 292   InSequence in_sequence;
 293
 294   TRACE_EVENT_BEGIN_ETW(kName, kId, kExtra);
 295   ExpectEvent(kTraceEventClass32,
 296               kTraceEventTypeBegin,
 297               kName, strlen(kName),
 298               kId,
 299               kExtra, strlen(kExtra));
 300
 301   TRACE_EVENT_END_ETW(kName, kId, kExtra);
 302   ExpectEvent(kTraceEventClass32,
 303               kTraceEventTypeEnd,
 304               kName, strlen(kName),
 305               kId,
 306               kExtra, strlen(kExtra));
 307
 308   TRACE_EVENT_INSTANT_ETW(kName, kId, kExtra);
 309   ExpectEvent(kTraceEventClass32,
 310               kTraceEventTypeInstant,
 311               kName, strlen(kName),
 312               kId,
 313               kExtra, strlen(kExtra));
 314
 315   PlayLog();
 316 }
 317
 318 }  // namespace debug
 319 }  // namespace base