Home | History | Annotate | Download | only in debug 
      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
    320