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