src/chrome/test/chromedriver/performance_logger.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 <string>
   8 #include <vector>
   9
  10 #include "base/bind.h"
  11 #include "base/json/json_writer.h"
  12 #include "base/strings/string_util.h"
  13 #include "base/values.h"
  14 #include "chrome/test/chromedriver/chrome/chrome.h"
  15 #include "chrome/test/chromedriver/chrome/devtools_client.h"
  16 #include "chrome/test/chromedriver/chrome/devtools_client_impl.h"
  17 #include "chrome/test/chromedriver/chrome/log.h"
  18 #include "chrome/test/chromedriver/chrome/status.h"
  19 #include "chrome/test/chromedriver/chrome/version.h"
  20 #include "chrome/test/chromedriver/session.h"
  21
  22 namespace {
  23
  24 // DevTools event domain prefixes to intercept.
  25 const char* const kDomains[] = {"Network.", "Page.", "Timeline."};
  26
  27 // Whitelist of WebDriver commands on which to request buffered trace events.
  28 const char* const kRequestTraceCommands[] = {"GetLog" /* required */,
  29     "Navigate"};
  30
  31 bool IsBrowserwideClient(DevToolsClient* client) {
  32   return (client->GetId() == DevToolsClientImpl::kBrowserwideDevToolsClientId);
  33 }
  34
  35 bool IsEnabled(const PerfLoggingPrefs::InspectorDomainStatus& domain_status) {
  36     return (domain_status ==
  37             PerfLoggingPrefs::InspectorDomainStatus::kDefaultEnabled ||
  38             domain_status ==
  39             PerfLoggingPrefs::InspectorDomainStatus::kExplicitlyEnabled);
  40 }
  41
  42 // Returns whether |command| is in kRequestTraceCommands[] (case-insensitive).
  43 bool ShouldRequestTraceEvents(const std::string& command) {
  44   for (size_t i_domain = 0; i_domain < arraysize(kRequestTraceCommands);
  45        ++i_domain) {
  46     if (base::strcasecmp(command.c_str(), kRequestTraceCommands[i_domain]) == 0)
  47       return true;
  48   }
  49   return false;
  50 }
  51
  52 // Returns whether the event belongs to one of kDomains.
  53 bool ShouldLogEvent(const std::string& method) {
  54   for (size_t i_domain = 0; i_domain < arraysize(kDomains); ++i_domain) {
  55     if (StartsWithASCII(method, kDomains[i_domain], true /* case_sensitive */))
  56       return true;
  57   }
  58   return false;
  59 }
  60
  61 }  // namespace
  62
  63 PerformanceLogger::PerformanceLogger(Log* log, const Session* session)
  64     : log_(log),
  65       session_(session),
  66       browser_client_(NULL),
  67       trace_buffering_(false) {}
  68
  69 PerformanceLogger::PerformanceLogger(Log* log,
  70                                      const Session* session,
  71                                      const PerfLoggingPrefs& prefs)
  72     : log_(log),
  73       session_(session),
  74       prefs_(prefs),
  75       browser_client_(NULL),
  76       trace_buffering_(false) {}
  77
  78 bool PerformanceLogger::subscribes_to_browser() {
  79   return true;
  80 }
  81
  82 Status PerformanceLogger::OnConnected(DevToolsClient* client) {
  83   if (IsBrowserwideClient(client)) {
  84     browser_client_ = client;
  85     if (!prefs_.trace_categories.empty())  {
  86       Status status = StartTrace();
  87       if (status.IsError())
  88         return status;
  89     }
  90     return Status(kOk);
  91   }
  92   return EnableInspectorDomains(client);
  93 }
  94
  95 Status PerformanceLogger::OnEvent(
  96     DevToolsClient* client,
  97     const std::string& method,
  98     const base::DictionaryValue& params) {
  99   if (IsBrowserwideClient(client)) {
 100     return HandleTraceEvents(client, method, params);
 101   } else {
 102     return HandleInspectorEvents(client, method, params);
 103   }
 104 }
 105
 106 Status PerformanceLogger::BeforeCommand(const std::string& command_name) {
 107   // Only dump trace buffer after tracing has been started.
 108   if (trace_buffering_ && ShouldRequestTraceEvents(command_name)) {
 109     Status status = CollectTraceEvents();
 110     if (status.IsError())
 111       return status;
 112   }
 113   return Status(kOk);
 114 }
 115
 116 void PerformanceLogger::AddLogEntry(
 117     Log::Level level,
 118     const std::string& webview,
 119     const std::string& method,
 120     const base::DictionaryValue& params) {
 121   base::DictionaryValue log_message_dict;
 122   log_message_dict.SetString("webview", webview);
 123   log_message_dict.SetString("message.method", method);
 124   log_message_dict.Set("message.params", params.DeepCopy());
 125   std::string log_message_json;
 126   base::JSONWriter::Write(&log_message_dict, &log_message_json);
 127
 128   // TODO(klm): extract timestamp from params?
 129   // Look at where it is for Page, Network, Timeline, and trace events.
 130   log_->AddEntry(level, log_message_json);
 131 }
 132
 133 void PerformanceLogger::AddLogEntry(
 134     const std::string& webview,
 135     const std::string& method,
 136     const base::DictionaryValue& params) {
 137   AddLogEntry(Log::kInfo, webview, method, params);
 138 }
 139
 140 Status PerformanceLogger::EnableInspectorDomains(DevToolsClient* client) {
 141   std::vector<std::string> enable_commands;
 142   if (IsEnabled(prefs_.network))
 143     enable_commands.push_back("Network.enable");
 144   if (IsEnabled(prefs_.page))
 145     enable_commands.push_back("Page.enable");
 146   if (IsEnabled(prefs_.timeline)) {
 147     // Timeline feed implicitly disabled when trace categories are specified.
 148     // So even if kDefaultEnabled, don't enable unless empty |trace_categories|.
 149     if (prefs_.trace_categories.empty() || prefs_.timeline ==
 150         PerfLoggingPrefs::InspectorDomainStatus::kExplicitlyEnabled)
 151       enable_commands.push_back("Timeline.start");
 152   }
 153   for (std::vector<std::string>::const_iterator it = enable_commands.begin();
 154        it != enable_commands.end(); ++it) {
 155     base::DictionaryValue params;  // All the enable commands have empty params.
 156     Status status = client->SendCommand(*it, params);
 157     if (status.IsError())
 158       return status;
 159   }
 160   return Status(kOk);
 161 }
 162
 163 Status PerformanceLogger::HandleInspectorEvents(
 164     DevToolsClient* client,
 165     const std::string& method,
 166     const base::DictionaryValue& params) {
 167   if (!ShouldLogEvent(method))
 168     return Status(kOk);
 169
 170   AddLogEntry(client->GetId(), method, params);
 171   return Status(kOk);
 172 }
 173
 174 Status PerformanceLogger::HandleTraceEvents(
 175     DevToolsClient* client,
 176     const std::string& method,
 177     const base::DictionaryValue& params) {
 178   if (method == "Tracing.tracingComplete") {
 179     trace_buffering_ = false;
 180   } else if (method == "Tracing.dataCollected") {
 181     // The Tracing.dataCollected event contains a list of trace events.
 182     // Add each one as an individual log entry of method Tracing.dataCollected.
 183     const base::ListValue* traces;
 184     if (!params.GetList("value", &traces)) {
 185       return Status(kUnknownError,
 186                     "received DevTools trace data in unexpected format");
 187     }
 188     for (base::ListValue::const_iterator it = traces->begin();
 189              it != traces->end();
 190              ++it) {
 191       base::DictionaryValue* event_dict;
 192       if (!(*it)->GetAsDictionary(&event_dict))
 193         return Status(kUnknownError, "trace event must be a dictionary");
 194       AddLogEntry(client->GetId(), "Tracing.dataCollected", *event_dict);
 195     }
 196   } else if (method == "Tracing.bufferUsage") {
 197     // 'value' will be between 0-1 and represents how full the DevTools trace
 198     // buffer is. If the buffer is full, warn the user.
 199     double buffer_usage = 0;
 200     if (!params.GetDouble("value", &buffer_usage)) {
 201       // Tracing.bufferUsage event will occur once per second, and it really
 202       // only serves as a warning, so if we can't reliably tell whether the
 203       // buffer is full, just fail silently instead of spamming the logs.
 204       return Status(kOk);
 205     }
 206     if (buffer_usage >= 0.99999) {
 207       base::DictionaryValue params;
 208       std::string err("Chrome's trace buffer filled while collecting events, "
 209                       "so some trace events may have been lost");
 210       params.SetString("error", err);
 211       // Expose error to client via perf log using same format as other entries.
 212       AddLogEntry(Log::kWarning,
 213                   DevToolsClientImpl::kBrowserwideDevToolsClientId,
 214                   "Tracing.bufferUsage", params);
 215       LOG(WARNING) << err;
 216     }
 217   }
 218   return Status(kOk);
 219 }
 220
 221 bool PerformanceLogger::ShouldReportTracingError() {
 222   // Chromium builds 1967-2000, which correspond to Blink revisions 172887-
 223   // 174227, contain a regression where Tracing.start and Tracing.end commands
 224   // erroneously return error -32601 "no such method". The commands still work.
 225   if (session_->chrome) {
 226     const BrowserInfo* browser_info = session_->chrome->GetBrowserInfo();
 227
 228     bool should_report_error = true;
 229     if (browser_info->browser_name == "chrome") {
 230       should_report_error = !(browser_info->build_no >= 1967 &&
 231           browser_info->build_no <= 2000);
 232     } else {
 233       should_report_error = !(browser_info->blink_revision >= 172887 &&
 234           browser_info->blink_revision <= 174227);
 235     }
 236     return should_report_error;
 237   }
 238
 239   // We're not yet able to tell the Chrome version, so don't report this error.
 240   return false;
 241 }
 242
 243 Status PerformanceLogger::StartTrace() {
 244   if (!browser_client_) {
 245     return Status(kUnknownError, "tried to start tracing, but connection to "
 246                   "browser was not yet established");
 247   }
 248   if (trace_buffering_) {
 249     LOG(WARNING) << "tried to start tracing, but a trace was already started";
 250     return Status(kOk);
 251   }
 252   base::DictionaryValue params;
 253   params.SetString("categories", prefs_.trace_categories);
 254   // Ask DevTools to report buffer usage.
 255   params.SetInteger("bufferUsageReportingInterval",
 256                     prefs_.buffer_usage_reporting_interval);
 257   Status status = browser_client_->SendCommand("Tracing.start", params);
 258   if (status.IsError() && ShouldReportTracingError()) {
 259     LOG(ERROR) << "error when starting trace: " << status.message();
 260     return status;
 261   }
 262   trace_buffering_ = true;
 263   return Status(kOk);
 264 }
 265
 266 Status PerformanceLogger::CollectTraceEvents() {
 267   if (!browser_client_) {
 268     return Status(kUnknownError, "tried to collect trace events, but "
 269                   "connection to browser was not yet established");
 270   }
 271   if (!trace_buffering_) {
 272     return Status(kUnknownError, "tried to collect trace events, but tracing "
 273                   "was not started");
 274   }
 275
 276   Status status = browser_client_->SendCommand("Tracing.end",
 277                                                base::DictionaryValue());
 278   if (status.IsError() && ShouldReportTracingError()) {
 279     LOG(ERROR) << "error when stopping trace: " << status.message();
 280     return status;
 281   }
 282
 283   // Block up to 30 seconds until Tracing.tracingComplete event is received.
 284   status = browser_client_->HandleEventsUntil(
 285       base::Bind(&PerformanceLogger::IsTraceDone, base::Unretained(this)),
 286       base::TimeDelta::FromSeconds(30));
 287   if (status.IsError())
 288     return status;
 289
 290   return StartTrace();
 291 }
 292
 293 Status PerformanceLogger::IsTraceDone(bool* trace_done) const {
 294   *trace_done = !trace_buffering_;
 295   return Status(kOk);
 296 }