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 (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 } 297
