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