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