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 19 namespace base { 20 namespace debug { 21 22 namespace { 23 24 using testing::_; 25 using testing::AnyNumber; 26 using testing::InSequence; 27 using testing::Ge; 28 using testing::Le; 29 using testing::NotNull; 30 31 using base::win::EtwEventType; 32 using base::win::EtwTraceConsumerBase; 33 using base::win::EtwTraceController; 34 using base::win::EtwTraceProperties; 35 36 // Data for unittests traces. 37 const char kEmpty[] = ""; 38 const char kName[] = "unittest.trace_name"; 39 const char kExtra[] = "UnittestDummyExtraString"; 40 const void* kId = kName; 41 42 const wchar_t kTestSessionName[] = L"TraceEvent unittest session"; 43 44 MATCHER_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. 49 DEFINE_GUID( /* 68fdd900-4a3e-11d1-84f4-0000f80464e3 */ 50 kEventTraceGuid, 51 0x68fdd900, 52 0x4a3e, 53 0x11d1, 54 0x84, 0xf4, 0x00, 0x00, 0xf8, 0x04, 0x64, 0xe3); 55 56 class 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 85 TestEventConsumer* TestEventConsumer::current_ = NULL; 86 87 class 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 207 TEST_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 282 TEST_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