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