[ChromeDriver] Implementing tracing support

chrome/test/chromedriver/performance_logger.cc

 // Copyright 2014 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 "chrome/test/chromedriver/performance_logger.h"
+
 #include <string>
 #include <vector>
 
-#include "chrome/test/chromedriver/performance_logger.h"
-
+#include "base/bind.h"
 #include "base/json/json_writer.h"
 #include "base/strings/string_util.h"
 #include "base/values.h"
+#include "chrome/test/chromedriver/chrome/chrome.h"
 #include "chrome/test/chromedriver/chrome/devtools_client.h"
 #include "chrome/test/chromedriver/chrome/devtools_client_impl.h"
 #include "chrome/test/chromedriver/chrome/log.h"
 #include "chrome/test/chromedriver/chrome/status.h"
+#include "chrome/test/chromedriver/chrome/version.h"
+#include "chrome/test/chromedriver/session.h"
 
 namespace {
 
 // DevTools event domain prefixes to intercept.
 const char* const kDomains[] = {"Network.", "Page.", "Timeline."};
 
+// Whitelist of WebDriver commands on which to request buffered trace events.
+const char* const kRequestTraceCommands[] = {"GetLog" /* required */,

[stgao, 2014/08/10 02:37:03]

Just an idea: do we want this to be configurable in the performance preference
setting?

But in that case, user needs to figure out the command names by browsing the
source code of chromedriver.

The benefit is we don't have to change the code when we decide to whitelist
another command.

[johnmoore, 2014/08/11 16:00:01]

I don't think we should expose something that complicated to the user. But maybe
we can expose a boolean flag to choose between using this hard-coded whitelist
and just dumping on every WebDriver command? That way if a particular test fills
the buffer consistently, the user could just dump on every command by passing in
a flag.

If we do this, which should be the default (whitelist or every command)?

[stgao, 2014/08/15 17:43:22]

Not sure if we want to do every command, because some commands have no
interaction with the Chrome browser, eg: setTimeout.

Let's go with the whitelist for this CL.
Later if user complains, we could make the needed change.

+    "Navigate"};
+
+bool IsBrowserwideClient(DevToolsClient* client) {
+  return (client->GetId() == DevToolsClientImpl::kBrowserwideDevToolsClientId);
+}
+
+bool IsEnabled(const PerfLoggingPrefs::InspectorDomainStatus& domain_status) {
+    return (domain_status ==
+            PerfLoggingPrefs::InspectorDomainStatus::kDefaultEnabled ||
+            domain_status ==
+            PerfLoggingPrefs::InspectorDomainStatus::kExplicitlyEnabled);
+}
+
+// Returns whether method is in kRequestTraceCommands[] (case-insensitive).
+bool ShouldRequestTraceEvents(const std::string& method) {

[stgao, 2014/08/10 02:37:03]

|method| -> |command|?

[johnmoore, 2014/08/11 16:00:01]

Done.

+  for (size_t i_domain = 0; i_domain < arraysize(kRequestTraceCommands);
+       ++i_domain) {
+    if (base::strcasecmp(method.c_str(), kRequestTraceCommands[i_domain]) == 0)
+      return true;
+  }
+  return false;
+}
+
 // Returns whether the event belongs to one of kDomains.
 bool ShouldLogEvent(const std::string& method) {
   for (size_t i_domain = 0; i_domain < arraysize(kDomains); ++i_domain) {
     if (StartsWithASCII(method, kDomains[i_domain], true /* case_sensitive */))
       return true;
   }
   return false;
 }
 
-bool IsEnabled(const PerfLoggingPrefs::InspectorDomainStatus& domain_status) {
-  return (domain_status ==
-          PerfLoggingPrefs::InspectorDomainStatus::kDefaultEnabled ||
-          domain_status ==
-          PerfLoggingPrefs::InspectorDomainStatus::kExplicitlyEnabled);
-}
-
 }  // namespace
 
-PerformanceLogger::PerformanceLogger(Log* log)
-    : log_(log) {}
+PerformanceLogger::PerformanceLogger(Log* log, const Session* session)
+    : log_(log),
+      session_(session),
+      browser_client_(NULL),
+      trace_buffering_(false) {}
 
-PerformanceLogger::PerformanceLogger(Log* log, const PerfLoggingPrefs& prefs)
+PerformanceLogger::PerformanceLogger(Log* log,
+                                     const Session* session,
+                                     const PerfLoggingPrefs& prefs)
     : log_(log),
-      prefs_(prefs) {
-  if (!prefs_.trace_categories.empty()) {
-    LOG(WARNING) << "Ignoring trace categories because tracing support not yet "
-                 << "implemented: " << prefs_.trace_categories;
-    prefs_.trace_categories = "";
-  }
-}
+      session_(session),
+      prefs_(prefs),
+      browser_client_(NULL),
+      trace_buffering_(false) {}
 
 bool PerformanceLogger::subscribes_to_browser() {
   return true;
 }
 
 Status PerformanceLogger::OnConnected(DevToolsClient* client) {
-  if (client->GetId() == DevToolsClientImpl::kBrowserwideDevToolsClientId) {
-    // TODO(johnmoore): Implement tracing log.
+  if (IsBrowserwideClient(client)) {
+    browser_client_ = client;
+    if (!prefs_.trace_categories.empty())  {
+      Status status = StartTrace();
+      if (status.IsError())
+        return status;
+    }
     return Status(kOk);
   }
+  return EnableInspectorDomains(client);
+}
+
+Status PerformanceLogger::OnEvent(
+    DevToolsClient* client,
+    const std::string& method,
+    const base::DictionaryValue& params) {
+  if (IsBrowserwideClient(client)) {
+    return HandleTraceEvents(client, method, params);
+  } else {
+    return HandleInspectorEvents(client, method, params);
+  }
+}
+
+Status PerformanceLogger::BeforeCommand(const std::string& command_name) {
+  // Only dump trace buffer after tracing has been started.
+  if (trace_buffering_ && ShouldRequestTraceEvents(command_name)) {
+    Status status = CollectTraceEvents();
+    if (status.IsError())
+      return status;
+  }
+  return Status(kOk);
+}
+
+void PerformanceLogger::AddLogEntry(
+    const std::string& webview,
+    const std::string& method,
+    const base::DictionaryValue& params) {
+  base::DictionaryValue log_message_dict;
+  log_message_dict.SetString("webview", webview);
+  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);
+
+  // TODO(klm): extract timestamp from params?
+  // Look at where it is for Page, Network, Timeline, and trace events.
+  log_->AddEntry(Log::kInfo, log_message_json);
+}
+
+Status PerformanceLogger::EnableInspectorDomains(DevToolsClient* client) {
   std::vector<std::string> enable_commands;
   if (IsEnabled(prefs_.network))
     enable_commands.push_back("Network.enable");
   if (IsEnabled(prefs_.page))
     enable_commands.push_back("Page.enable");
   if (IsEnabled(prefs_.timeline)) {
     // Timeline feed implicitly disabled when trace categories are specified.
     // So even if kDefaultEnabled, don't enable unless empty |trace_categories|.
     if (prefs_.trace_categories.empty() || prefs_.timeline ==
         PerfLoggingPrefs::InspectorDomainStatus::kExplicitlyEnabled)
       enable_commands.push_back("Timeline.start");
   }
   for (std::vector<std::string>::const_iterator it = enable_commands.begin();
        it != enable_commands.end(); ++it) {
     base::DictionaryValue params;  // All the enable commands have empty params.
     Status status = client->SendCommand(*it, params);
     if (status.IsError())
       return status;
   }
   return Status(kOk);
 }
 
-Status PerformanceLogger::OnEvent(
+Status PerformanceLogger::HandleInspectorEvents(
     DevToolsClient* client,
     const std::string& method,
     const base::DictionaryValue& params) {
+

[stgao, 2014/08/10 02:37:04]

This line could be removed.

[johnmoore, 2014/08/11 16:00:02]

Done.

   if (!ShouldLogEvent(method))
     return Status(kOk);
 
-  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;
-  // TODO(klm): extract timestamp from params?
-  // Look at where it is for Page, Network, Timeline events.
-  base::JSONWriter::Write(&log_message_dict, &log_message_json);
-
-  log_->AddEntry(Log::kInfo, log_message_json);
+  AddLogEntry(client->GetId(), method, params);
   return Status(kOk);
 }
 
-// TODO(johnmoore): Use BeforeCommand to implement tracing log.
-Status PerformanceLogger::BeforeCommand(const std::string& command_name) {
+Status PerformanceLogger::HandleTraceEvents(
+    DevToolsClient* client,
+    const std::string& method,
+    const base::DictionaryValue& params) {
+  if (method == "Tracing.tracingComplete") {
+    trace_buffering_ = false;
+  } else if (method == "Tracing.dataCollected") {
+    // The Tracing.dataCollected event contains a list of trace events.
+    // Add each one as an individual log entry of method Tracing.dataCollected.
+    const base::ListValue* traces;
+    if (!params.GetList("value", &traces)) {
+      return Status(kUnknownError,
+                    "Received DevTools trace data in unexpected format");

[stgao, 2014/08/10 02:37:03]

error message usually starts with lowercase unless it is a special name like
"DevTools".

Please also check other error messages in this CL.

[johnmoore, 2014/08/11 16:00:01]

Done.

+    }
+    for (base::ListValue::const_iterator it = traces->begin();
+             it != traces->end();
+             ++it) {
+      base::DictionaryValue* event_dict;
+      if (!(*it)->GetAsDictionary(&event_dict))
+        return Status(kUnknownError, "trace event must be a dictionary");
+      AddLogEntry(client->GetId(), "Tracing.dataCollected", *event_dict);
+    }
+  } else if (method == "Tracing.bufferUsage") {
+    // 'value' will be between 0-1 and represents how full the DevTools trace
+    // buffer is. If the buffer is full, warn the user.
+    double buffer_usage = 0;
+    if (!params.GetDouble("value", &buffer_usage)) {
+      // Tracing.bufferUsage event will occur once per second, and it really
+      // only serves as a warning, so if we can't reliably tell whether the
+      // buffer is full, just fail silently instead of spamming the logs.
+      return Status(kOk);
+    }
+    if (buffer_usage >= 1.0) {

[stgao, 2014/08/10 02:37:04]

Floating point comparison is not accurate.
Maybe use > 0.99999 instead >= 1.0

[johnmoore, 2014/08/11 16:00:01]

Done.

+      LOG(WARNING) << "Chrome's trace buffer filled while collecting events, "

[stgao, 2014/08/10 02:37:04]

This warning is on server side.

Do we want to make it available to the client side?

[johnmoore, 2014/08/11 16:00:01]

Good idea. I've exposed the message to the user by adding it to the performance
log. I was careful to use the same formatting as other log entries (by making it
an entry for the browser webview with method Tracing.bufferUsage), as described
in performance_logger.h. This way clients won't fail when they expect that JSON
format.

+                   << "so some trace events may have been lost";
+    }
+  }
   return Status(kOk);
 }
+
+bool PerformanceLogger::ShouldReportTracingError() {
+  // Chromium builds 1967-2000, which correspond to Blink revisions 172887-
+  // 174227, contain a regression where Tracing.start and Tracing.end commands
+  // erroneously return error -32601 "no such method". The commands still work.
+  if (session_->chrome) {
+    const BrowserInfo* browser_info = session_->chrome->GetBrowserInfo();
+
+    bool should_report_error = true;
+    if (browser_info->browser_name == "chrome") {
+      should_report_error = !(browser_info->build_no >= 1967 &&
+          browser_info->build_no <= 2000);
+    } else {
+      should_report_error = !(browser_info->blink_revision >= 172887 &&
+          browser_info->blink_revision <= 174227);
+    }
+    return should_report_error;
+  }
+  // We're not yet able to tell the Chrome version, so don't report this error.

[stgao, 2014/08/10 02:37:04]

Maybe add an empty line before this one.

[johnmoore, 2014/08/11 16:00:01]

Done.

+  return false;
+}
+
+Status PerformanceLogger::StartTrace() {
+  CHECK(browser_client_);
+  if (trace_buffering_) {
+    LOG(WARNING) << "Ignoring PerformanceLogger::StartTrace because tracing "
+                 << "was already started";
+    return Status(kOk);
+  }
+  base::DictionaryValue params;
+  params.SetString("categories", prefs_.trace_categories);
+  // Ask DevTools to report buffer usage percentage once per second.
+  params.SetInteger("bufferUsageReportingInterval", 1000 /* milliseconds */);

[stgao, 2014/08/10 02:37:03]

Will this be too frequent?

[johnmoore, 2014/08/11 16:00:02]

This is the default value that I've seen used in Chromium (e.g. about://tracing
and //src/content/browser/devtools/devtools_tracing_handler.cc and elsewhere).
It's true that the server and client will then receive an error for every second
that the buffer is full, but maybe that's a good thing: they can then estimate
just how much trace data was lost, if they'd like, by looking at how many errors
there are.

If we raise the default, perhaps we should make this value another perf log
pref, since I'm sure some users will want 1000 ms. I'm happy to do that if you
think it'd be appropriate.

[stgao, 2014/08/15 17:43:22]

Vote for making it configurable in perf log setting, with default to 1000ms.
WDYT?

+  Status status = browser_client_->SendCommand("Tracing.start", params);
+  if (status.IsError() && ShouldReportTracingError()) {
+    LOG(ERROR) << "Error when starting trace: " << status.message();
+    return status;
+  }
+  trace_buffering_ = true;
+  return Status(kOk);
+}
+
+Status PerformanceLogger::CollectTraceEvents() {
+  CHECK(browser_client_);
+  if (!trace_buffering_) {
+    return Status(kUnknownError, "PerformanceLogger::CollectTraceEvents called,"

[stgao, 2014/08/10 02:37:03]

Maybe remove PerformanceLogger::CollectTraceEvents from the error message. It is
implementation detail, we don't have to include it in the error message.

[johnmoore, 2014/08/11 16:00:01]

Done.

+                  " but tracing was not started");
+  }
+  Status status = browser_client_->SendCommand("Tracing.end",
+                                               base::DictionaryValue());
+  if (status.IsError() && ShouldReportTracingError()) {
+    LOG(ERROR) << "Error when stopping trace: " << status.message();
+    return status;
+  }
+  // Block up to 30 seconds until Tracing.tracingComplete event is received.

[stgao, 2014/08/10 02:37:03]

Add an empty line for each logic block.
That will make the code easier to understand.

[johnmoore, 2014/08/11 16:00:01]

Done.

+  status = browser_client_->HandleEventsUntil(
+      base::Bind(&PerformanceLogger::IsTraceDone, base::Unretained(this)),
+      base::TimeDelta::FromSeconds(30));
+  if (status.IsError())
+    return status;
+  return StartTrace();
+}
+
+Status PerformanceLogger::IsTraceDone(bool* trace_done) const {
+  *trace_done = !trace_buffering_;
+  return Status(kOk);
+}