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::DeprecatedReadAndReturnError(
 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 }
 175
 176 }  // namespace
 177
 178 TEST(PerformanceLogger, OneWebView) {
 179   FakeDevToolsClient client("webview-1");
 180   FakeLog log;
 181   Session session("test");
 182   PerformanceLogger logger(&log, &session);
 183
 184   client.AddListener(&logger);
 185   logger.OnConnected(&client);
 186   ExpectEnableDomains(client);
 187   ASSERT_EQ(kOk, client.TriggerEvent("Network.gaga").code());
 188   ASSERT_EQ(kOk, client.TriggerEvent("Page.ulala").code());
 189   // Ignore -- different domain.
 190   ASSERT_EQ(kOk, client.TriggerEvent("Console.bad").code());
 191
 192   ASSERT_EQ(2u, log.GetEntries().size());
 193   ValidateLogEntry(log.GetEntries()[0], "webview-1", "Network.gaga");
 194   ValidateLogEntry(log.GetEntries()[1], "webview-1", "Page.ulala");
 195 }
 196
 197 TEST(PerformanceLogger, TwoWebViews) {
 198   FakeDevToolsClient client1("webview-1");
 199   FakeDevToolsClient client2("webview-2");
 200   FakeLog log;
 201   Session session("test");
 202   PerformanceLogger logger(&log, &session);
 203
 204   client1.AddListener(&logger);
 205   client2.AddListener(&logger);
 206   logger.OnConnected(&client1);
 207   logger.OnConnected(&client2);
 208   ExpectEnableDomains(client1);
 209   ExpectEnableDomains(client2);
 210   // OnConnected sends the enable command only to that client, not others.
 211   client1.ConnectIfNecessary();
 212   ExpectEnableDomains(client1);
 213   DevToolsCommand* cmd;
 214   ASSERT_FALSE(client2.PopSentCommand(&cmd));
 215
 216   ASSERT_EQ(kOk, client1.TriggerEvent("Page.gaga1").code());
 217   ASSERT_EQ(kOk, client2.TriggerEvent("Network.gaga2").code());
 218
 219   ASSERT_EQ(2u, log.GetEntries().size());
 220   ValidateLogEntry(log.GetEntries()[0], "webview-1", "Page.gaga1");
 221   ValidateLogEntry(log.GetEntries()[1], "webview-2", "Network.gaga2");
 222 }
 223
 224 TEST(PerformanceLogger, PerfLoggingPrefs) {
 225   FakeDevToolsClient client("webview-1");
 226   FakeLog log;
 227   Session session("test");
 228   PerfLoggingPrefs prefs;
 229   EXPECT_EQ(PerfLoggingPrefs::InspectorDomainStatus::kDefaultEnabled,
 230             prefs.network);
 231   prefs.network = PerfLoggingPrefs::InspectorDomainStatus::kExplicitlyDisabled;
 232   prefs.trace_categories = "benchmark,blink.console";
 233   PerformanceLogger logger(&log, &session, prefs);
 234
 235   client.AddListener(&logger);
 236   logger.OnConnected(&client);
 237   ExpectCommand(client, "Page.enable");
 238   // Do not expect Timeline.enable command since specifying trace categories
 239   // implicitly disables Timeline feed.
 240   DevToolsCommand* cmd;
 241   ASSERT_FALSE(client.PopSentCommand(&cmd));
 242 }
 243
 244 namespace {
 245
 246 class FakeBrowserwideClient : public FakeDevToolsClient {
 247  public:
 248   FakeBrowserwideClient()
 249       : FakeDevToolsClient(DevToolsClientImpl::kBrowserwideDevToolsClientId),
 250         events_handled_(false) {}
 251   ~FakeBrowserwideClient() override {}
 252
 253   bool events_handled() const {
 254     return events_handled_;
 255   }
 256
 257   // Overridden from DevToolsClient:
 258   Status HandleEventsUntil(const ConditionalFunc& conditional_func,
 259                            const base::TimeDelta& timeout) override {
 260     TriggerEvent("Tracing.tracingComplete");
 261     events_handled_ = true;
 262     return Status(kOk);
 263   }
 264
 265  private:
 266   bool events_handled_;
 267 };
 268
 269 }  // namespace
 270
 271 TEST(PerformanceLogger, TracingStartStop) {
 272   FakeBrowserwideClient client;
 273   FakeLog log;
 274   Session session("test");
 275   PerfLoggingPrefs prefs;
 276   prefs.trace_categories = "benchmark,blink.console";
 277   PerformanceLogger logger(&log, &session, prefs);
 278
 279   client.AddListener(&logger);
 280   logger.OnConnected(&client);
 281   DevToolsCommand* cmd;
 282   ASSERT_TRUE(client.PopSentCommand(&cmd));
 283   EXPECT_EQ("Tracing.start", cmd->method);
 284   std::string expected_cats;
 285   EXPECT_TRUE(cmd->params->GetString("categories", &expected_cats));
 286   EXPECT_EQ("benchmark,blink.console", expected_cats);
 287   int expected_interval = 0;
 288   EXPECT_TRUE(cmd->params->GetInteger("bufferUsageReportingInterval",
 289                                       &expected_interval));
 290   EXPECT_GT(expected_interval, 0);
 291   ASSERT_FALSE(client.PopSentCommand(&cmd));
 292
 293   EXPECT_FALSE(client.events_handled());
 294   // Trigger a dump of the DevTools trace buffer.
 295   ASSERT_EQ(kOk, logger.BeforeCommand("GetLog").code());
 296   EXPECT_TRUE(client.events_handled());
 297   ExpectCommand(client, "Tracing.end");
 298   ExpectCommand(client, "Tracing.start");  // Tracing should re-start.
 299   ASSERT_FALSE(client.PopSentCommand(&cmd));
 300 }
 301
 302 TEST(PerformanceLogger, RecordTraceEvents) {
 303   FakeBrowserwideClient client;
 304   FakeLog log;
 305   Session session("test");
 306   PerfLoggingPrefs prefs;
 307   prefs.trace_categories = "benchmark,blink.console";
 308   PerformanceLogger logger(&log, &session, prefs);
 309
 310   client.AddListener(&logger);
 311   logger.OnConnected(&client);
 312   base::DictionaryValue params;
 313   base::ListValue* trace_events = new base::ListValue();
 314   base::DictionaryValue* event1 = new base::DictionaryValue();
 315   event1->SetString("cat", "foo");
 316   trace_events->Append(event1);
 317   base::DictionaryValue* event2 = new base::DictionaryValue();
 318   event2->SetString("cat", "bar");
 319   trace_events->Append(event2);
 320   params.Set("value", trace_events);
 321   ASSERT_EQ(kOk, client.TriggerEvent("Tracing.dataCollected", params).code());
 322
 323   ASSERT_EQ(2u, log.GetEntries().size());
 324   ValidateLogEntry(log.GetEntries()[0],
 325                    DevToolsClientImpl::kBrowserwideDevToolsClientId,
 326                    "Tracing.dataCollected", *event1);
 327   ValidateLogEntry(log.GetEntries()[1],
 328                    DevToolsClientImpl::kBrowserwideDevToolsClientId,
 329                    "Tracing.dataCollected", *event2);
 330 }
 331
 332 TEST(PerformanceLogger, ShouldRequestTraceEvents) {
 333   FakeBrowserwideClient client;
 334   FakeLog log;
 335   Session session("test");
 336   PerfLoggingPrefs prefs;
 337   prefs.trace_categories = "benchmark,blink.console";
 338   PerformanceLogger logger(&log, &session, prefs);
 339
 340   client.AddListener(&logger);
 341   logger.OnConnected(&client);
 342   EXPECT_FALSE(client.events_handled());
 343   // Trace events should not be dumped for commands not in whitelist.
 344   ASSERT_EQ(kOk, logger.BeforeCommand("Blah").code());
 345   EXPECT_FALSE(client.events_handled());
 346   ASSERT_EQ(kOk, logger.BeforeCommand("Foo").code());
 347   EXPECT_FALSE(client.events_handled());
 348   // Trace events should always be dumped for GetLog command.
 349   ASSERT_EQ(kOk, logger.BeforeCommand("GetLog").code());
 350   EXPECT_TRUE(client.events_handled());
 351 }
 352
 353 TEST(PerformanceLogger, WarnWhenTraceBufferFull) {
 354   FakeBrowserwideClient client;
 355   FakeLog log;
 356   Session session("test");
 357   PerfLoggingPrefs prefs;
 358   prefs.trace_categories = "benchmark,blink.console";
 359   PerformanceLogger logger(&log, &session, prefs);
 360
 361   client.AddListener(&logger);
 362   logger.OnConnected(&client);
 363   base::DictionaryValue params;
 364   params.SetDouble("value", 1.0);
 365   ASSERT_EQ(kOk, client.TriggerEvent("Tracing.bufferUsage", params).code());
 366
 367   ASSERT_EQ(1u, log.GetEntries().size());
 368   LogEntry* entry = log.GetEntries()[0];
 369   EXPECT_EQ(Log::kWarning, entry->level);
 370   EXPECT_LT(0, entry->timestamp.ToTimeT());
 371   scoped_ptr<base::DictionaryValue> message(ParseDictionary(entry->message));
 372   std::string webview;
 373   EXPECT_TRUE(message->GetString("webview", &webview));
 374   EXPECT_EQ(DevToolsClientImpl::kBrowserwideDevToolsClientId, webview);
 375   std::string method;
 376   EXPECT_TRUE(message->GetString("message.method", &method));
 377   EXPECT_EQ("Tracing.bufferUsage", method);
 378   base::DictionaryValue* actual_params;
 379   EXPECT_TRUE(message->GetDictionary("message.params", &actual_params));
 380   EXPECT_TRUE(actual_params->HasKey("error"));
 381 }