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 <stddef.h>
8
9 #include <memory>
10 #include <utility>
11 #include <vector>
12
13 #include "base/compiler_specific.h"
14 #include "base/format_macros.h"
15 #include "base/json/json_reader.h"
16 #include "base/time/time.h"
17 #include "base/values.h"
18 #include "chrome/test/chromedriver/chrome/devtools_client_impl.h"
19 #include "chrome/test/chromedriver/chrome/log.h"
20 #include "chrome/test/chromedriver/chrome/status.h"
21 #include "chrome/test/chromedriver/chrome/stub_devtools_client.h"
22 #include "chrome/test/chromedriver/session.h"
23 #include "testing/gtest/include/gtest/gtest.h"
24
25 namespace {
26
27 struct DevToolsCommand {
DevToolsCommand__anon748a34fe0111::DevToolsCommand28 DevToolsCommand(const std::string& in_method,
29 base::DictionaryValue* in_params)
30 : method(in_method) {
31 params.reset(in_params);
32 }
~DevToolsCommand__anon748a34fe0111::DevToolsCommand33 ~DevToolsCommand() {}
34
35 std::string method;
36 std::unique_ptr<base::DictionaryValue> params;
37 };
38
39 class FakeDevToolsClient : public StubDevToolsClient {
40 public:
FakeDevToolsClient(const std::string & id)41 explicit FakeDevToolsClient(const std::string& id)
42 : id_(id), listener_(nullptr), command_index_(0) {}
~FakeDevToolsClient()43 ~FakeDevToolsClient() override {}
44
PopSentCommand(DevToolsCommand ** out_command)45 bool PopSentCommand(DevToolsCommand** out_command) {
46 if (sent_commands_.size() > command_index_) {
47 *out_command = sent_commands_[command_index_++].get();
48 return true;
49 }
50 return false;
51 }
52
TriggerEvent(const std::string & method)53 Status TriggerEvent(const std::string& method) {
54 base::DictionaryValue empty_params;
55 return listener_->OnEvent(this, method, empty_params);
56 }
57
TriggerEvent(const std::string & method,const base::DictionaryValue & params)58 Status TriggerEvent(const std::string& method,
59 const base::DictionaryValue& params) {
60 return listener_->OnEvent(this, method, params);
61 }
62
63 // Overridden from DevToolsClient:
ConnectIfNecessary()64 Status ConnectIfNecessary() override { return listener_->OnConnected(this); }
65
SendCommandAndGetResult(const std::string & method,const base::DictionaryValue & params,std::unique_ptr<base::DictionaryValue> * result)66 Status SendCommandAndGetResult(
67 const std::string& method,
68 const base::DictionaryValue& params,
69 std::unique_ptr<base::DictionaryValue>* result) override {
70 sent_commands_.push_back(
71 std::make_unique<DevToolsCommand>(method, params.DeepCopy()));
72 return Status(kOk);
73 }
74
AddListener(DevToolsEventListener * listener)75 void AddListener(DevToolsEventListener* listener) override {
76 CHECK(!listener_);
77 listener_ = listener;
78 }
79
GetId()80 const std::string& GetId() override { return id_; }
81
82 private:
83 const std::string id_; // WebView id.
84 std::vector<std::unique_ptr<DevToolsCommand>>
85 sent_commands_; // Commands that were sent.
86 DevToolsEventListener* listener_; // The fake allows only one event listener.
87 size_t command_index_;
88 };
89
90 struct LogEntry {
91 const base::Time timestamp;
92 const Log::Level level;
93 const std::string source;
94 const std::string message;
95
LogEntry__anon748a34fe0111::LogEntry96 LogEntry(const base::Time& timestamp,
97 Log::Level level,
98 const std::string& source,
99 const std::string& message)
100 : timestamp(timestamp), level(level), source(source), message(message) {}
101 };
102
103 class FakeLog : public Log {
104 public:
105 void AddEntryTimestamped(const base::Time& timestamp,
106 Level level,
107 const std::string& source,
108 const std::string& message) override;
109
110 bool Emptied() const override;
111
GetEntries()112 const std::vector<std::unique_ptr<LogEntry>>& GetEntries() {
113 return entries_;
114 }
115
116 private:
117 std::vector<std::unique_ptr<LogEntry>> entries_;
118 };
119
AddEntryTimestamped(const base::Time & timestamp,Level level,const std::string & source,const std::string & message)120 void FakeLog::AddEntryTimestamped(const base::Time& timestamp,
121 Level level,
122 const std::string& source,
123 const std::string& message) {
124 entries_.push_back(
125 std::make_unique<LogEntry>(timestamp, level, source, message));
126 }
127
Emptied() const128 bool FakeLog::Emptied() const {
129 return true;
130 }
131
ParseDictionary(const std::string & json)132 std::unique_ptr<base::DictionaryValue> ParseDictionary(
133 const std::string& json) {
134 base::JSONReader::ValueWithError parsed_json =
135 base::JSONReader::ReadAndReturnValueWithError(json);
136 if (!parsed_json.value) {
137 SCOPED_TRACE(json.c_str());
138 SCOPED_TRACE(parsed_json.error_message.c_str());
139 ADD_FAILURE();
140 return std::unique_ptr<base::DictionaryValue>();
141 }
142 base::DictionaryValue* dict = nullptr;
143 if (!parsed_json.value->GetAsDictionary(&dict)) {
144 SCOPED_TRACE("JSON object is not a dictionary");
145 ADD_FAILURE();
146 return std::unique_ptr<base::DictionaryValue>();
147 }
148 return std::unique_ptr<base::DictionaryValue>(dict->DeepCopy());
149 }
150
ValidateLogEntry(const LogEntry * entry,const std::string & expected_webview,const std::string & expected_method,const base::DictionaryValue & expected_params)151 void ValidateLogEntry(const LogEntry *entry,
152 const std::string& expected_webview,
153 const std::string& expected_method,
154 const base::DictionaryValue& expected_params) {
155 EXPECT_EQ(Log::kInfo, entry->level);
156 EXPECT_LT(0, entry->timestamp.ToTimeT());
157
158 std::unique_ptr<base::DictionaryValue> message(
159 ParseDictionary(entry->message));
160 std::string webview;
161 EXPECT_TRUE(message->GetString("webview", &webview));
162 EXPECT_EQ(expected_webview, webview);
163 std::string method;
164 EXPECT_TRUE(message->GetString("message.method", &method));
165 EXPECT_EQ(expected_method, method);
166 base::DictionaryValue* params;
167 EXPECT_TRUE(message->GetDictionary("message.params", ¶ms));
168 EXPECT_TRUE(params->Equals(&expected_params));
169 }
170
ValidateLogEntry(const LogEntry * entry,const std::string & expected_webview,const std::string & expected_method)171 void ValidateLogEntry(const LogEntry *entry,
172 const std::string& expected_webview,
173 const std::string& expected_method) {
174 base::DictionaryValue empty_params;
175 ValidateLogEntry(entry, expected_webview, expected_method, empty_params);
176 }
177
ExpectCommand(FakeDevToolsClient * client,const std::string & method)178 void ExpectCommand(FakeDevToolsClient* client, const std::string& method) {
179 DevToolsCommand* cmd;
180 // Use ASSERT so that test fails if no command is returned.
181 ASSERT_TRUE(client->PopSentCommand(&cmd));
182 EXPECT_EQ(method, cmd->method);
183 }
184
ExpectEnableDomains(FakeDevToolsClient * client)185 void ExpectEnableDomains(FakeDevToolsClient* client) {
186 ExpectCommand(client, "Network.enable");
187 ExpectCommand(client, "Page.enable");
188 }
189
190 } // namespace
191
TEST(PerformanceLogger,OneWebView)192 TEST(PerformanceLogger, OneWebView) {
193 FakeDevToolsClient client("webview-1");
194 FakeLog log;
195 Session session("test");
196 PerformanceLogger logger(&log, &session);
197
198 client.AddListener(&logger);
199 logger.OnConnected(&client);
200 ExpectEnableDomains(&client);
201 ASSERT_EQ(kOk, client.TriggerEvent("Network.gaga").code());
202 ASSERT_EQ(kOk, client.TriggerEvent("Page.ulala").code());
203 // Ignore -- different domain.
204 ASSERT_EQ(kOk, client.TriggerEvent("Console.bad").code());
205
206 ASSERT_EQ(2u, log.GetEntries().size());
207 ValidateLogEntry(log.GetEntries()[0].get(), "webview-1", "Network.gaga");
208 ValidateLogEntry(log.GetEntries()[1].get(), "webview-1", "Page.ulala");
209 }
210
TEST(PerformanceLogger,TwoWebViews)211 TEST(PerformanceLogger, TwoWebViews) {
212 FakeDevToolsClient client1("webview-1");
213 FakeDevToolsClient client2("webview-2");
214 FakeLog log;
215 Session session("test");
216 PerformanceLogger logger(&log, &session);
217
218 client1.AddListener(&logger);
219 client2.AddListener(&logger);
220 logger.OnConnected(&client1);
221 logger.OnConnected(&client2);
222 ExpectEnableDomains(&client1);
223 ExpectEnableDomains(&client2);
224 // OnConnected sends the enable command only to that client, not others.
225 client1.ConnectIfNecessary();
226 ExpectEnableDomains(&client1);
227 DevToolsCommand* cmd;
228 ASSERT_FALSE(client2.PopSentCommand(&cmd));
229
230 ASSERT_EQ(kOk, client1.TriggerEvent("Page.gaga1").code());
231 ASSERT_EQ(kOk, client2.TriggerEvent("Network.gaga2").code());
232
233 ASSERT_EQ(2u, log.GetEntries().size());
234 ValidateLogEntry(log.GetEntries()[0].get(), "webview-1", "Page.gaga1");
235 ValidateLogEntry(log.GetEntries()[1].get(), "webview-2", "Network.gaga2");
236 }
237
TEST(PerformanceLogger,PerfLoggingPrefs)238 TEST(PerformanceLogger, PerfLoggingPrefs) {
239 FakeDevToolsClient client("webview-1");
240 FakeLog log;
241 Session session("test");
242 PerfLoggingPrefs prefs;
243 EXPECT_EQ(PerfLoggingPrefs::InspectorDomainStatus::kDefaultEnabled,
244 prefs.network);
245 prefs.network = PerfLoggingPrefs::InspectorDomainStatus::kExplicitlyDisabled;
246 prefs.trace_categories = "benchmark,blink.console";
247 PerformanceLogger logger(&log, &session, prefs);
248
249 client.AddListener(&logger);
250 logger.OnConnected(&client);
251 ExpectCommand(&client, "Page.enable");
252
253 DevToolsCommand* cmd;
254 ASSERT_FALSE(client.PopSentCommand(&cmd));
255 }
256
257 namespace {
258
259 class FakeBrowserwideClient : public FakeDevToolsClient {
260 public:
FakeBrowserwideClient()261 FakeBrowserwideClient()
262 : FakeDevToolsClient(DevToolsClientImpl::kBrowserwideDevToolsClientId),
263 events_handled_(false) {}
~FakeBrowserwideClient()264 ~FakeBrowserwideClient() override {}
265
events_handled() const266 bool events_handled() const {
267 return events_handled_;
268 }
269
270 // Overridden from DevToolsClient:
HandleEventsUntil(const ConditionalFunc & conditional_func,const Timeout & timeout)271 Status HandleEventsUntil(const ConditionalFunc& conditional_func,
272 const Timeout& timeout) override {
273 TriggerEvent("Tracing.tracingComplete");
274 events_handled_ = true;
275 return Status(kOk);
276 }
277
278 private:
279 bool events_handled_;
280 };
281
282 } // namespace
283
TEST(PerformanceLogger,TracingStartStop)284 TEST(PerformanceLogger, TracingStartStop) {
285 FakeBrowserwideClient client;
286 FakeLog log;
287 Session session("test");
288 PerfLoggingPrefs prefs;
289 prefs.trace_categories = "benchmark,blink.console";
290 PerformanceLogger logger(&log, &session, prefs);
291
292 client.AddListener(&logger);
293 logger.OnConnected(&client);
294 DevToolsCommand* cmd;
295 ASSERT_TRUE(client.PopSentCommand(&cmd));
296 EXPECT_EQ("Tracing.start", cmd->method);
297 base::ListValue* categories;
298 EXPECT_TRUE(cmd->params->GetList("traceConfig.includedCategories",
299 &categories));
300 EXPECT_EQ(2u, categories->GetSize());
301 std::string category;
302 EXPECT_TRUE(categories->GetString(0, &category));
303 EXPECT_EQ("benchmark", category);
304 EXPECT_TRUE(categories->GetString(1, &category));
305 EXPECT_EQ("blink.console", category);
306 int expected_interval = 0;
307 EXPECT_TRUE(cmd->params->GetInteger("bufferUsageReportingInterval",
308 &expected_interval));
309 EXPECT_GT(expected_interval, 0);
310 ASSERT_FALSE(client.PopSentCommand(&cmd));
311
312 EXPECT_FALSE(client.events_handled());
313 // Trigger a dump of the DevTools trace buffer.
314 ASSERT_EQ(kOk, logger.BeforeCommand("GetLog").code());
315 EXPECT_TRUE(client.events_handled());
316 ExpectCommand(&client, "Tracing.end");
317 ExpectCommand(&client, "Tracing.start"); // Tracing should re-start.
318 ASSERT_FALSE(client.PopSentCommand(&cmd));
319 }
320
TEST(PerformanceLogger,RecordTraceEvents)321 TEST(PerformanceLogger, RecordTraceEvents) {
322 FakeBrowserwideClient client;
323 FakeLog log;
324 Session session("test");
325 PerfLoggingPrefs prefs;
326 prefs.trace_categories = "benchmark,blink.console";
327 PerformanceLogger logger(&log, &session, prefs);
328
329 client.AddListener(&logger);
330 logger.OnConnected(&client);
331 base::DictionaryValue params;
332 auto trace_events = std::make_unique<base::ListValue>();
333 auto event1 = std::make_unique<base::DictionaryValue>();
334 event1->SetString("cat", "foo");
335 trace_events->Append(event1->Clone());
336 auto event2 = std::make_unique<base::DictionaryValue>();
337 event2->SetString("cat", "bar");
338 trace_events->Append(event2->Clone());
339 params.Set("value", std::move(trace_events));
340 ASSERT_EQ(kOk, client.TriggerEvent("Tracing.dataCollected", params).code());
341
342 ASSERT_EQ(2u, log.GetEntries().size());
343 ValidateLogEntry(log.GetEntries()[0].get(),
344 DevToolsClientImpl::kBrowserwideDevToolsClientId,
345 "Tracing.dataCollected", *event1);
346 ValidateLogEntry(log.GetEntries()[1].get(),
347 DevToolsClientImpl::kBrowserwideDevToolsClientId,
348 "Tracing.dataCollected", *event2);
349 }
350
TEST(PerformanceLogger,ShouldRequestTraceEvents)351 TEST(PerformanceLogger, ShouldRequestTraceEvents) {
352 FakeBrowserwideClient client;
353 FakeLog log;
354 Session session("test");
355 PerfLoggingPrefs prefs;
356 prefs.trace_categories = "benchmark,blink.console";
357 PerformanceLogger logger(&log, &session, prefs);
358
359 client.AddListener(&logger);
360 logger.OnConnected(&client);
361 EXPECT_FALSE(client.events_handled());
362 // Trace events should not be dumped for commands not in whitelist.
363 ASSERT_EQ(kOk, logger.BeforeCommand("Blah").code());
364 EXPECT_FALSE(client.events_handled());
365 ASSERT_EQ(kOk, logger.BeforeCommand("Foo").code());
366 EXPECT_FALSE(client.events_handled());
367 // Trace events should always be dumped for GetLog command.
368 ASSERT_EQ(kOk, logger.BeforeCommand("GetLog").code());
369 EXPECT_TRUE(client.events_handled());
370 }
371
TEST(PerformanceLogger,WarnWhenTraceBufferFull)372 TEST(PerformanceLogger, WarnWhenTraceBufferFull) {
373 FakeBrowserwideClient client;
374 FakeLog log;
375 Session session("test");
376 PerfLoggingPrefs prefs;
377 prefs.trace_categories = "benchmark,blink.console";
378 PerformanceLogger logger(&log, &session, prefs);
379
380 client.AddListener(&logger);
381 logger.OnConnected(&client);
382 base::DictionaryValue params;
383 params.SetDouble("percentFull", 1.0);
384 ASSERT_EQ(kOk, client.TriggerEvent("Tracing.bufferUsage", params).code());
385
386 ASSERT_EQ(1u, log.GetEntries().size());
387 LogEntry* entry = log.GetEntries()[0].get();
388 EXPECT_EQ(Log::kWarning, entry->level);
389 EXPECT_LT(0, entry->timestamp.ToTimeT());
390 std::unique_ptr<base::DictionaryValue> message(
391 ParseDictionary(entry->message));
392 std::string webview;
393 EXPECT_TRUE(message->GetString("webview", &webview));
394 EXPECT_EQ(DevToolsClientImpl::kBrowserwideDevToolsClientId, webview);
395 std::string method;
396 EXPECT_TRUE(message->GetString("message.method", &method));
397 EXPECT_EQ("Tracing.bufferUsage", method);
398 base::DictionaryValue* actual_params;
399 EXPECT_TRUE(message->GetDictionary("message.params", &actual_params));
400 EXPECT_TRUE(actual_params->HasKey("error"));
401 }
402