1// Copyright 2014 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 "chrome/test/chromedriver/performance_logger.h" 6 7#include "base/compiler_specific.h" 8#include "base/format_macros.h" 9#include "base/json/json_reader.h" 10#include "base/memory/scoped_vector.h" 11#include "base/time/time.h" 12#include "base/values.h" 13#include "chrome/test/chromedriver/chrome/devtools_client_impl.h" 14#include "chrome/test/chromedriver/chrome/log.h" 15#include "chrome/test/chromedriver/chrome/status.h" 16#include "chrome/test/chromedriver/chrome/stub_devtools_client.h" 17#include "chrome/test/chromedriver/session.h" 18#include "testing/gtest/include/gtest/gtest.h" 19 20namespace { 21 22struct DevToolsCommand { 23 DevToolsCommand(const std::string& in_method, 24 base::DictionaryValue* in_params) 25 : method(in_method) { 26 params.reset(in_params); 27 } 28 ~DevToolsCommand() {} 29 30 std::string method; 31 scoped_ptr<base::DictionaryValue> params; 32}; 33 34class FakeDevToolsClient : public StubDevToolsClient { 35 public: 36 explicit FakeDevToolsClient(const std::string& id) 37 : id_(id), listener_(NULL), command_index_(0) {} 38 virtual ~FakeDevToolsClient() {} 39 40 bool PopSentCommand(DevToolsCommand** out_command) { 41 if (sent_commands_.size() > command_index_) { 42 *out_command = sent_commands_.get().at(command_index_++); 43 return true; 44 } 45 return false; 46 } 47 48 Status TriggerEvent(const std::string& method) { 49 base::DictionaryValue empty_params; 50 return listener_->OnEvent(this, method, empty_params); 51 } 52 53 Status TriggerEvent(const std::string& method, 54 const base::DictionaryValue& params) { 55 return listener_->OnEvent(this, method, params); 56 } 57 58 // Overridden from DevToolsClient: 59 virtual Status ConnectIfNecessary() OVERRIDE { 60 return listener_->OnConnected(this); 61 } 62 63 virtual Status SendCommandAndGetResult( 64 const std::string& method, 65 const base::DictionaryValue& params, 66 scoped_ptr<base::DictionaryValue>* result) OVERRIDE { 67 sent_commands_.push_back(new DevToolsCommand(method, 68 params.DeepCopy())); 69 return Status(kOk); 70 } 71 72 virtual void AddListener(DevToolsEventListener* listener) OVERRIDE { 73 CHECK(!listener_); 74 listener_ = listener; 75 } 76 77 virtual const std::string& GetId() OVERRIDE { 78 return id_; 79 } 80 81 private: 82 const std::string id_; // WebView id. 83 ScopedVector<DevToolsCommand> sent_commands_; // Commands that were sent. 84 DevToolsEventListener* listener_; // The fake allows only one event listener. 85 size_t command_index_; 86}; 87 88struct LogEntry { 89 const base::Time timestamp; 90 const Log::Level level; 91 const std::string source; 92 const std::string message; 93 94 LogEntry(const base::Time& timestamp, 95 Log::Level level, 96 const std::string& source, 97 const std::string& message) 98 : timestamp(timestamp), level(level), source(source), message(message) {} 99}; 100 101class FakeLog : public Log { 102 public: 103 virtual void AddEntryTimestamped(const base::Time& timestamp, 104 Level level, 105 const std::string& source, 106 const std::string& message) OVERRIDE; 107 108 const ScopedVector<LogEntry>& GetEntries() { 109 return entries_; 110 } 111 112 private: 113 ScopedVector<LogEntry> entries_; 114}; 115 116void FakeLog::AddEntryTimestamped(const base::Time& timestamp, 117 Level level, 118 const std::string& source, 119 const std::string& message) { 120 entries_.push_back(new LogEntry(timestamp, level, source, message)); 121} 122 123scoped_ptr<base::DictionaryValue> ParseDictionary(const std::string& json) { 124 std::string error; 125 scoped_ptr<base::Value> value(base::JSONReader::ReadAndReturnError( 126 json, base::JSON_PARSE_RFC, NULL, &error)); 127 if (value == NULL) { 128 SCOPED_TRACE(json.c_str()); 129 SCOPED_TRACE(error.c_str()); 130 ADD_FAILURE(); 131 return scoped_ptr<base::DictionaryValue>(); 132 } 133 base::DictionaryValue* dict = NULL; 134 if (!value->GetAsDictionary(&dict)) { 135 SCOPED_TRACE("JSON object is not a dictionary"); 136 ADD_FAILURE(); 137 return scoped_ptr<base::DictionaryValue>(); 138 } 139 return scoped_ptr<base::DictionaryValue>(dict->DeepCopy()); 140} 141 142void ValidateLogEntry(const LogEntry *entry, 143 const std::string& expected_webview, 144 const std::string& expected_method, 145 const base::DictionaryValue& expected_params) { 146 EXPECT_EQ(Log::kInfo, entry->level); 147 EXPECT_LT(0, entry->timestamp.ToTimeT()); 148 149 scoped_ptr<base::DictionaryValue> message(ParseDictionary(entry->message)); 150 std::string webview; 151 EXPECT_TRUE(message->GetString("webview", &webview)); 152 EXPECT_EQ(expected_webview, webview); 153 std::string method; 154 EXPECT_TRUE(message->GetString("message.method", &method)); 155 EXPECT_EQ(expected_method, method); 156 base::DictionaryValue* params; 157 EXPECT_TRUE(message->GetDictionary("message.params", ¶ms)); 158 EXPECT_TRUE(params->Equals(&expected_params)); 159} 160 161void ValidateLogEntry(const LogEntry *entry, 162 const std::string& expected_webview, 163 const std::string& expected_method) { 164 base::DictionaryValue empty_params; 165 ValidateLogEntry(entry, expected_webview, expected_method, empty_params); 166} 167 168void ExpectCommand(FakeDevToolsClient& client, const std::string& method) { 169 DevToolsCommand* cmd; 170 // Use ASSERT so that test fails if no command is returned. 171 ASSERT_TRUE(client.PopSentCommand(&cmd)); 172 EXPECT_EQ(method, cmd->method); 173} 174 175void ExpectEnableDomains(FakeDevToolsClient& client) { 176 ExpectCommand(client, "Network.enable"); 177 ExpectCommand(client, "Page.enable"); 178 ExpectCommand(client, "Timeline.start"); 179} 180 181} // namespace 182 183TEST(PerformanceLogger, OneWebView) { 184 FakeDevToolsClient client("webview-1"); 185 FakeLog log; 186 Session session("test"); 187 PerformanceLogger logger(&log, &session); 188 189 client.AddListener(&logger); 190 logger.OnConnected(&client); 191 ExpectEnableDomains(client); 192 ASSERT_EQ(kOk, client.TriggerEvent("Network.gaga").code()); 193 ASSERT_EQ(kOk, client.TriggerEvent("Page.ulala").code()); 194 // Ignore -- different domain. 195 ASSERT_EQ(kOk, client.TriggerEvent("Console.bad").code()); 196 197 ASSERT_EQ(2u, log.GetEntries().size()); 198 ValidateLogEntry(log.GetEntries()[0], "webview-1", "Network.gaga"); 199 ValidateLogEntry(log.GetEntries()[1], "webview-1", "Page.ulala"); 200} 201 202TEST(PerformanceLogger, TwoWebViews) { 203 FakeDevToolsClient client1("webview-1"); 204 FakeDevToolsClient client2("webview-2"); 205 FakeLog log; 206 Session session("test"); 207 PerformanceLogger logger(&log, &session); 208 209 client1.AddListener(&logger); 210 client2.AddListener(&logger); 211 logger.OnConnected(&client1); 212 logger.OnConnected(&client2); 213 ExpectEnableDomains(client1); 214 ExpectEnableDomains(client2); 215 // OnConnected sends the enable command only to that client, not others. 216 client1.ConnectIfNecessary(); 217 ExpectEnableDomains(client1); 218 DevToolsCommand* cmd; 219 ASSERT_FALSE(client2.PopSentCommand(&cmd)); 220 221 ASSERT_EQ(kOk, client1.TriggerEvent("Page.gaga1").code()); 222 ASSERT_EQ(kOk, client2.TriggerEvent("Timeline.gaga2").code()); 223 224 ASSERT_EQ(2u, log.GetEntries().size()); 225 ValidateLogEntry(log.GetEntries()[0], "webview-1", "Page.gaga1"); 226 ValidateLogEntry(log.GetEntries()[1], "webview-2", "Timeline.gaga2"); 227} 228 229TEST(PerformanceLogger, PerfLoggingPrefs) { 230 FakeDevToolsClient client("webview-1"); 231 FakeLog log; 232 Session session("test"); 233 PerfLoggingPrefs prefs; 234 EXPECT_EQ(PerfLoggingPrefs::InspectorDomainStatus::kDefaultEnabled, 235 prefs.network); 236 prefs.network = PerfLoggingPrefs::InspectorDomainStatus::kExplicitlyDisabled; 237 prefs.trace_categories = "benchmark,blink.console"; 238 PerformanceLogger logger(&log, &session, prefs); 239 240 client.AddListener(&logger); 241 logger.OnConnected(&client); 242 ExpectCommand(client, "Page.enable"); 243 // Do not expect Timeline.enable command since specifying trace categories 244 // implicitly disables Timeline feed. 245 DevToolsCommand* cmd; 246 ASSERT_FALSE(client.PopSentCommand(&cmd)); 247} 248 249namespace { 250 251class FakeBrowserwideClient : public FakeDevToolsClient { 252 public: 253 FakeBrowserwideClient() 254 : FakeDevToolsClient(DevToolsClientImpl::kBrowserwideDevToolsClientId), 255 events_handled_(false) {} 256 virtual ~FakeBrowserwideClient() {} 257 258 bool events_handled() const { 259 return events_handled_; 260 } 261 262 // Overridden from DevToolsClient: 263 virtual Status HandleEventsUntil( 264 const ConditionalFunc& conditional_func, 265 const base::TimeDelta& timeout) OVERRIDE { 266 TriggerEvent("Tracing.tracingComplete"); 267 events_handled_ = true; 268 return Status(kOk); 269 } 270 271 private: 272 bool events_handled_; 273}; 274 275} // namespace 276 277TEST(PerformanceLogger, TracingStartStop) { 278 FakeBrowserwideClient client; 279 FakeLog log; 280 Session session("test"); 281 PerfLoggingPrefs prefs; 282 prefs.trace_categories = "benchmark,blink.console"; 283 PerformanceLogger logger(&log, &session, prefs); 284 285 client.AddListener(&logger); 286 logger.OnConnected(&client); 287 DevToolsCommand* cmd; 288 ASSERT_TRUE(client.PopSentCommand(&cmd)); 289 EXPECT_EQ("Tracing.start", cmd->method); 290 std::string expected_cats; 291 EXPECT_TRUE(cmd->params->GetString("categories", &expected_cats)); 292 EXPECT_EQ("benchmark,blink.console", expected_cats); 293 int expected_interval = 0; 294 EXPECT_TRUE(cmd->params->GetInteger("bufferUsageReportingInterval", 295 &expected_interval)); 296 EXPECT_GT(expected_interval, 0); 297 ASSERT_FALSE(client.PopSentCommand(&cmd)); 298 299 EXPECT_FALSE(client.events_handled()); 300 // Trigger a dump of the DevTools trace buffer. 301 ASSERT_EQ(kOk, logger.BeforeCommand("GetLog").code()); 302 EXPECT_TRUE(client.events_handled()); 303 ExpectCommand(client, "Tracing.end"); 304 ExpectCommand(client, "Tracing.start"); // Tracing should re-start. 305 ASSERT_FALSE(client.PopSentCommand(&cmd)); 306} 307 308TEST(PerformanceLogger, RecordTraceEvents) { 309 FakeBrowserwideClient client; 310 FakeLog log; 311 Session session("test"); 312 PerfLoggingPrefs prefs; 313 prefs.trace_categories = "benchmark,blink.console"; 314 PerformanceLogger logger(&log, &session, prefs); 315 316 client.AddListener(&logger); 317 logger.OnConnected(&client); 318 base::DictionaryValue params; 319 base::ListValue* trace_events = new base::ListValue(); 320 base::DictionaryValue* event1 = new base::DictionaryValue(); 321 event1->SetString("cat", "foo"); 322 trace_events->Append(event1); 323 base::DictionaryValue* event2 = new base::DictionaryValue(); 324 event2->SetString("cat", "bar"); 325 trace_events->Append(event2); 326 params.Set("value", trace_events); 327 ASSERT_EQ(kOk, client.TriggerEvent("Tracing.dataCollected", params).code()); 328 329 ASSERT_EQ(2u, log.GetEntries().size()); 330 ValidateLogEntry(log.GetEntries()[0], 331 DevToolsClientImpl::kBrowserwideDevToolsClientId, 332 "Tracing.dataCollected", *event1); 333 ValidateLogEntry(log.GetEntries()[1], 334 DevToolsClientImpl::kBrowserwideDevToolsClientId, 335 "Tracing.dataCollected", *event2); 336} 337 338TEST(PerformanceLogger, ShouldRequestTraceEvents) { 339 FakeBrowserwideClient client; 340 FakeLog log; 341 Session session("test"); 342 PerfLoggingPrefs prefs; 343 prefs.trace_categories = "benchmark,blink.console"; 344 PerformanceLogger logger(&log, &session, prefs); 345 346 client.AddListener(&logger); 347 logger.OnConnected(&client); 348 EXPECT_FALSE(client.events_handled()); 349 // Trace events should not be dumped for commands not in whitelist. 350 ASSERT_EQ(kOk, logger.BeforeCommand("Blah").code()); 351 EXPECT_FALSE(client.events_handled()); 352 ASSERT_EQ(kOk, logger.BeforeCommand("Foo").code()); 353 EXPECT_FALSE(client.events_handled()); 354 // Trace events should always be dumped for GetLog command. 355 ASSERT_EQ(kOk, logger.BeforeCommand("GetLog").code()); 356 EXPECT_TRUE(client.events_handled()); 357} 358 359TEST(PerformanceLogger, WarnWhenTraceBufferFull) { 360 FakeBrowserwideClient client; 361 FakeLog log; 362 Session session("test"); 363 PerfLoggingPrefs prefs; 364 prefs.trace_categories = "benchmark,blink.console"; 365 PerformanceLogger logger(&log, &session, prefs); 366 367 client.AddListener(&logger); 368 logger.OnConnected(&client); 369 base::DictionaryValue params; 370 params.SetDouble("value", 1.0); 371 ASSERT_EQ(kOk, client.TriggerEvent("Tracing.bufferUsage", params).code()); 372 373 ASSERT_EQ(1u, log.GetEntries().size()); 374 LogEntry* entry = log.GetEntries()[0]; 375 EXPECT_EQ(Log::kWarning, entry->level); 376 EXPECT_LT(0, entry->timestamp.ToTimeT()); 377 scoped_ptr<base::DictionaryValue> message(ParseDictionary(entry->message)); 378 std::string webview; 379 EXPECT_TRUE(message->GetString("webview", &webview)); 380 EXPECT_EQ(DevToolsClientImpl::kBrowserwideDevToolsClientId, webview); 381 std::string method; 382 EXPECT_TRUE(message->GetString("message.method", &method)); 383 EXPECT_EQ("Tracing.bufferUsage", method); 384 base::DictionaryValue* actual_params; 385 EXPECT_TRUE(message->GetDictionary("message.params", &actual_params)); 386 EXPECT_TRUE(actual_params->HasKey("error")); 387} 388