chrome/test/chromedriver/performance_logger_unittest.cc

   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
  20 namespace {
  21
  22 struct 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
  34 class 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
  88 struct 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
 101 class 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
 116 void 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
 123 scoped_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
 142 void 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", &params));
 158   EXPECT_TRUE(params->Equals(&expected_params));
 159 }
 160
 161 void 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
 168 void 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
 175 void ExpectEnableDomains(FakeDevToolsClient& client) {
 176   ExpectCommand(client, "Network.enable");
 177   ExpectCommand(client, "Page.enable");
 178   ExpectCommand(client, "Timeline.start");
 179 }
 180
 181 }  // namespace
 182
 183 TEST(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
 202 TEST(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
 229 TEST(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
 249 namespace {
 250
 251 class 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
 277 TEST(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
 308 TEST(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
 338 TEST(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
 359 TEST(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 }