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
22namespace {
23
24// DevTools event domain prefixes to intercept.
25const char* const kDomains[] = {"Network.", "Page.", "Timeline."};
26
27// Whitelist of WebDriver commands on which to request buffered trace events.
28const char* const kRequestTraceCommands[] = {"GetLog" /* required */,
29    "Navigate"};
30
31bool IsBrowserwideClient(DevToolsClient* client) {
32  return (client->GetId() == DevToolsClientImpl::kBrowserwideDevToolsClientId);
33}
34
35bool 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).
43bool 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.
53bool 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
63PerformanceLogger::PerformanceLogger(Log* log, const Session* session)
64    : log_(log),
65      session_(session),
66      browser_client_(NULL),
67      trace_buffering_(false) {}
68
69PerformanceLogger::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
78bool PerformanceLogger::subscribes_to_browser() {
79  return true;
80}
81
82Status 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
95Status 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
106Status 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
116void 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
133void 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
140Status 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
163Status 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
174Status 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
221bool 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
243Status 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
266Status 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
293Status PerformanceLogger::IsTraceDone(bool* trace_done) const {
294  *trace_done = !trace_buffering_;
295  return Status(kOk);
296}
297