Logging API in chromedriver2.

chrome/test/chromedriver/chrome/devtools_event_logger_unittest.cc

Index: chrome/test/chromedriver/chrome/devtools_event_logger_unittest.cc
===================================================================
--- chrome/test/chromedriver/chrome/devtools_event_logger_unittest.cc	(revision 0)
+++ chrome/test/chromedriver/chrome/devtools_event_logger_unittest.cc	(revision 0)
@@ -0,0 +1,296 @@
+// Copyright (c) 2013 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "base/format_macros.h"
+#include "base/json/json_reader.h"
+#include "base/json/json_writer.h"
+#include "base/json/string_escape.h"
+#include "base/stringprintf.h"
+#include "base/time.h"
+#include "base/values.h"
+#include "chrome/test/chromedriver/chrome/devtools_event_logger.h"
+#include "chrome/test/chromedriver/chrome/stub_devtools_client.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace {
+
+class FakeDevToolsClient : public StubDevToolsClient {
+ public:
+  explicit FakeDevToolsClient(const std::string& id) : id_(id) {}
+  virtual ~FakeDevToolsClient() {}
+
+  std::string PopSentCommand() {
+    std::string command;
+    if (!sent_command_queue_.empty()) {
+      command = sent_command_queue_.front();
+      sent_command_queue_.pop_front();
+    }
+    return command;
+  }
+
+  void TriggerEvent(const std::string& method) {
+    base::DictionaryValue empty_params;
+    listener_->OnEvent(this, method, empty_params);
+  }
+
+  // Overridden from DevToolsClient:
+  virtual Status ConnectIfNecessary() OVERRIDE {
+    return listener_->OnConnected(this);
+  }
+
+  virtual Status SendCommandAndGetResult(
+      const std::string& method,
+      const base::DictionaryValue& params,
+      scoped_ptr<base::DictionaryValue>* result) OVERRIDE {
+    sent_command_queue_.push_back(method);
+    return Status(kOk);
+  }
+
+  virtual void AddListener(DevToolsEventListener* listener) OVERRIDE {
+    listener_ = listener;
+  }
+
+  const std::string& GetId() OVERRIDE {
+    return id_;
+  }
+
+ private:
+  const std::string id_;
+  std::list<std::string> sent_command_queue_;
+  DevToolsEventListener* listener_;
+};
+
+scoped_ptr<DictionaryValue> ParseDictionary(const std::string& json) {
+  std::string error;
+  scoped_ptr<Value> value(base::JSONReader::ReadAndReturnError(
+      json, base::JSON_PARSE_RFC, NULL, &error));
+  if (NULL == value) {
+    SCOPED_TRACE(json.c_str());
+    SCOPED_TRACE(error.c_str());
+    ADD_FAILURE();
+    return scoped_ptr<DictionaryValue>(NULL);
+  }
+  DictionaryValue* dict = 0;
+  if (!value->GetAsDictionary(&dict)) {
+    SCOPED_TRACE("JSON object is not a dictionary");
+    ADD_FAILURE();
+    return scoped_ptr<DictionaryValue>(NULL);
+  }
+  return scoped_ptr<DictionaryValue>(dict->DeepCopy());
+}
+
+void ValidateLogEntry(base::ListValue *entries,
+                      int index,
+                      const char* expect_webview,
+                      const char* expect_method,
+                      const char* expect_level) {
+  const base::DictionaryValue *entry;
+  ASSERT_TRUE(entries->GetDictionary(index, &entry));
+  std::string message_json;
+  ASSERT_TRUE(entry->GetString("message", &message_json));
+  scoped_ptr<base::DictionaryValue> message(ParseDictionary(message_json));
+
+  std::string level;
+  EXPECT_TRUE(entry->GetString("level", &level));
+  EXPECT_STREQ(expect_level, level.c_str());
+  double timestamp = 0;
+  EXPECT_TRUE(entry->GetDouble("timestamp", &timestamp));
+  EXPECT_LT(0, timestamp);
+  std::string webview;
+  EXPECT_TRUE(message->GetString("webview", &webview));
+  EXPECT_STREQ(expect_webview, webview.c_str());
+  std::string method;
+  EXPECT_TRUE(message->GetString("message.method", &method));
+  EXPECT_STREQ(expect_method, method.c_str());
+  DictionaryValue* params;
+  EXPECT_TRUE(message->GetDictionary("message.params", &params));
+  EXPECT_EQ(0u, params->size());
+}
+
+}  // namespace
+
+TEST(DevToolsEventLogger, OneClientMultiDomains) {
+  FakeDevToolsClient client("webview-1");
+  std::vector<std::string> domains;
+  domains.push_back("Page");
+  domains.push_back("Network");
+  domains.push_back("Timeline");
+  DevToolsEventLogger logger("mylog", domains, "INFO");
+
+  logger.AddDevToolsClient(&client);
+  EXPECT_STREQ("Network.enable", client.PopSentCommand().c_str());
+  EXPECT_STREQ("Timeline.start", client.PopSentCommand().c_str());
+  EXPECT_STREQ("", client.PopSentCommand().c_str());
+  client.TriggerEvent("Network.gaga");
+  client.TriggerEvent("Page.ulala");
+  client.TriggerEvent("Console.bad");  // Ignore -- different domain.
+
+  scoped_ptr<base::ListValue> entries(logger.GetAndClearLogEntries());
+
+  ASSERT_EQ(2u, entries->GetSize());
+  ValidateLogEntry(entries.get(), 0, "webview-1", "Network.gaga", "INFO");
+  ValidateLogEntry(entries.get(), 1, "webview-1", "Page.ulala", "INFO");
+
+  // Repeat get returns nothing.
+  scoped_ptr<base::ListValue> no_entries(logger.GetAndClearLogEntries());
+  EXPECT_EQ(0u, no_entries->GetSize());
+
+  EXPECT_STREQ("", client.PopSentCommand().c_str());  // No more commands sent.
+}
+
+TEST(DevToolsEventLogger, MultiClientsOneDomain) {
+  FakeDevToolsClient client1("webview-1");
+  FakeDevToolsClient client2("webview-2");
+  std::vector<std::string> domains;
+  domains.push_back("Console");
+  DevToolsEventLogger logger("mylog", domains, "INFO");
+
+  logger.AddDevToolsClient(&client1);
+  logger.AddDevToolsClient(&client2);
+  EXPECT_STREQ("Console.enable", client1.PopSentCommand().c_str());
+  EXPECT_STREQ("", client1.PopSentCommand().c_str());
+  EXPECT_STREQ("Console.enable", client2.PopSentCommand().c_str());
+  EXPECT_STREQ("", client2.PopSentCommand().c_str());
+  // OnConnected sends the enable command only to that client, not others.
+  client1.ConnectIfNecessary();
+  EXPECT_STREQ("Console.enable", client1.PopSentCommand().c_str());
+  EXPECT_STREQ("", client1.PopSentCommand().c_str());
+  EXPECT_STREQ("", client2.PopSentCommand().c_str());
+
+  client1.TriggerEvent("Console.gaga1");
+  client2.TriggerEvent("Console.gaga2");
+
+  scoped_ptr<base::ListValue> entries(logger.GetAndClearLogEntries());
+
+  ASSERT_EQ(2u, entries->GetSize());
+  ValidateLogEntry(entries.get(), 0, "webview-1", "Console.gaga1", "INFO");
+  ValidateLogEntry(entries.get(), 1, "webview-2", "Console.gaga2", "INFO");
+}
+
+// Benchmark potential implementations of OnEvent:
+// * JSON by hand: create the entry JSON string by hand.
+// * JSON writer: create DictionaryValues and use JSONWriter.
+// * Store a DictionaryValue and delay JSON serialization for the entry.
+// Make sure params are nontrivial, so the cost or DeepCopy() weighs in.
+//
+// End result -- it doesn't matter, the difference is single 1/1000's of a ms,
+// i.e. total single milliseconds over a thousand events processed.
+// For example, on a Macbook Air:
+//
+// JSON by hand took 0.0410 ms.
+// JSON by writer took 0.0403 ms.
+// Entry as Dictionary, message by hand took 0.0405 ms.
+// Entry as Dictionary, message via writer took 0.0404 ms.
+namespace {
+
+const int kBenchmarkIterations = 10000;  // Make 100000 for better precision.
+
+void JsonByHand(DevToolsClient* client,
+                const std::string& method,
+                const base::DictionaryValue& params) {
+  std::string log_message_json = "{\"message\":{\"method\":";
+  base::JsonDoubleQuote(method, /*put_in_quotes=*/true, &log_message_json);
+  log_message_json += ",\"params\":";
+  std::string params_json;
+  base::JSONWriter::Write(&params, &params_json);
+  log_message_json += params_json;
+  log_message_json += "},\"webview\":";
+  base::JsonDoubleQuote(
+      client->GetId(), /*put_in_quotes=*/true, &log_message_json);
+  log_message_json += "}";
+
+  std::string log_entry_json;
+  base::SStringPrintf(
+      &log_entry_json, "{\"level\":%d,\"timestamp\":%" PRId64 ",\"message\":",
+      2, (int64_t)1234567890.0);
+  base::JsonDoubleQuote(
+      log_message_json, /*put_in_quotes=*/true, &log_entry_json);
+  log_entry_json += "}";
+}
+
+void JsonByWriter(DevToolsClient* client,
+                  const std::string& method,
+                  const base::DictionaryValue& params) {
+  base::DictionaryValue log_message_dict;
+  log_message_dict.SetString("webview", client->GetId());
+  log_message_dict.SetString("message.method", method);
+  log_message_dict.Set("message.params", params.DeepCopy());
+  std::string log_message_json;
+  base::JSONWriter::Write(&log_message_dict, &log_message_json);
+
+  base::DictionaryValue log_entry_dict;
+  log_entry_dict.SetDouble("timestamp", (int64_t)1234567890.0);
+  log_entry_dict.SetInteger("level", 2);
+  log_entry_dict.SetString("message", log_message_json);
+  std::string log_entry_json;
+  base::JSONWriter::Write(&log_entry_dict, &log_entry_json);
+}
+
+void EntryDictMessageByHand(DevToolsClient* client,
+                            const std::string& method,
+                            const base::DictionaryValue& params) {
+  std::string log_message_json = "{\"message\":{\"method\":";
+  base::JsonDoubleQuote(method, /*put_in_quotes=*/true, &log_message_json);
+  log_message_json += ",\"params\":";
+  std::string params_json;
+  base::JSONWriter::Write(&params, &params_json);
+  log_message_json += params_json;
+  log_message_json += "},\"webview\":";
+  base::JsonDoubleQuote(
+      client->GetId(), /*put_in_quotes=*/true, &log_message_json);
+  log_message_json += "}";
+
+  base::DictionaryValue log_entry_dict;
+  log_entry_dict.SetDouble("timestamp", (int64_t)1234567890.0);
+  log_entry_dict.SetInteger("level", 2);
+  log_entry_dict.SetString("message", log_message_json);
+}
+
+void EntryDictMessageWriter(DevToolsClient* client,
+                            const std::string& method,
+                            const base::DictionaryValue& params) {
+  base::DictionaryValue log_message_dict;
+  log_message_dict.SetString("webview", client->GetId());
+  log_message_dict.SetString("message.method", method);
+  log_message_dict.Set("message.params", params.DeepCopy());
+  std::string log_message_json;
+  base::JSONWriter::Write(&log_message_dict, &log_message_json);
+
+  base::DictionaryValue log_entry_dict;
+  log_entry_dict.SetDouble("timestamp", (int64_t)1234567890.0);
+  log_entry_dict.SetInteger("level", 2);
+  log_entry_dict.SetString("message", log_message_json);
+}
+
+double RunBenchmark(void (*EventFunc)(DevToolsClient*,
+                                      const std::string& method,
+                                      const base::DictionaryValue& params)) {
+  DictionaryValue params;
+  params.SetString("dict1.str", "gaga");
+  params.SetInteger("dict2.int", 123);
+  params.SetBoolean("dict2.bool", true);
+  const std::string method = "Network:gaga";
+  FakeDevToolsClient client("webview-1");
+
+  base::TimeTicks start = base::TimeTicks::HighResNow();
+  for (int i = 0; i < kBenchmarkIterations; ++i) {
+    JsonByHand(&client, method, params);
+  }
+  return ((base::TimeTicks::HighResNow() - start).InMillisecondsF()) /
+      kBenchmarkIterations;
+}
+}
+
+TEST(DevToolsEventLogger, BenchmarkEventFunctions) {

[kkania, 2013/04/18 17:34:39]

remove all this benchmarking code

[klm, 2013/04/18 19:11:31]

Done.

+  DictionaryValue params;
+  const std::string method = "Network:gaga";
+  FakeDevToolsClient client("webview-1");
+
+  printf("JSON by hand took %.4f ms.\n", RunBenchmark(&JsonByHand));
+  printf("JSON by writer took %.4f ms.\n", RunBenchmark(&JsonByWriter));
+  printf("Entry as Dictionary, message by hand took %.4f ms.\n",
+         RunBenchmark(&EntryDictMessageByHand));
+  printf("Entry as Dictionary, message via writer took %.4f ms.\n",
+         RunBenchmark(&EntryDictMessageWriter));
+}