1 /*
2 * Copyright (C) 2020 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include <stdarg.h>
18
19 #include <chrono>
20 #include <list>
21 #include <map>
22 #include <random>
23 #include <regex>
24 #include <string>
25 #include <thread>
26 #include <vector>
27
28 #include "perfetto/base/build_config.h"
29 #include "perfetto/base/compiler.h"
30 #include "perfetto/ext/base/ctrl_c_handler.h"
31 #include "perfetto/ext/base/file_utils.h"
32 #include "perfetto/ext/base/scoped_file.h"
33 #include "perfetto/ext/base/subprocess.h"
34 #include "perfetto/ext/base/temp_file.h"
35 #include "perfetto/ext/base/utils.h"
36 #include "perfetto/protozero/proto_utils.h"
37 #include "perfetto/tracing.h"
38 #include "perfetto/tracing/core/forward_decls.h"
39 #include "perfetto/tracing/core/trace_config.h"
40 #include "src/base/test/utils.h"
41
42 #include "protos/perfetto/config/stress_test_config.gen.h"
43 #include "protos/perfetto/trace/test_event.pbzero.h"
44 #include "protos/perfetto/trace/trace_packet.pbzero.h"
45
46 #if PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
47 #include <Windows.h>
48 #else
49 #include <signal.h>
50 #endif
51
52 // Generated by gen_configs_blob.py. It defines the kStressTestConfigs array,
53 // which contains a proto-encoded StressTestConfig message for each .cfg file
54 // listed in /test/stress_test/configs/BUILD.gn.
55 #include "test/stress_test/configs/stress_test_config_blobs.h"
56
57 namespace perfetto {
58 namespace {
59
60 // TODO(primiano): We need a base::File to get around the awkwardness of
61 // files on Windows being a mix of int and HANDLE (and open() vs CreateFile())
62 // in our codebase.
OpenLogFile(const std::string & path)63 base::ScopedPlatformHandle OpenLogFile(const std::string& path) {
64 #if PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
65 return base::ScopedPlatformHandle(::CreateFileA(
66 path.c_str(), GENERIC_READ | GENERIC_WRITE,
67 FILE_SHARE_DELETE | FILE_SHARE_READ, nullptr, CREATE_ALWAYS, 0, nullptr));
68 #else
69 return base::OpenFile(path, O_RDWR | O_CREAT | O_TRUNC, 0644);
70 #endif
71 }
72
73 using StressTestConfig = protos::gen::StressTestConfig;
74
75 struct SigHandlerCtx {
76 std::atomic<bool> aborted{};
77 std::vector<int> pids_to_kill;
78 };
79 SigHandlerCtx* g_sig;
80
81 struct TestResult {
82 const char* cfg_name = nullptr;
83 StressTestConfig cfg;
84 uint32_t run_time_ms = 0;
85 uint32_t trace_size_kb = 0;
86 uint32_t num_packets = 0;
87 uint32_t num_threads = 0;
88 uint32_t num_errors = 0;
89 base::Subprocess::ResourceUsage svc_rusage;
90 base::Subprocess::ResourceUsage prod_rusage;
91 };
92
93 struct ParsedTraceStats {
94 struct WriterThread {
95 uint64_t packets_seen = 0;
96 bool last_seen = false;
97 uint32_t last_seq = 0;
98 uint64_t seq_errors = 0;
99 uint64_t counter_errors = 0;
100 std::minstd_rand0 rnd_engine;
101 };
102
103 // One for each trusted_packet_sequence_id.
104 std::map<uint32_t, WriterThread> threads;
105 };
106
107 class TestHarness {
108 public:
109 TestHarness();
110 void RunConfig(const char* cfg_name, const StressTestConfig&, bool verbose);
test_results() const111 const std::list<TestResult>& test_results() const { return test_results_; }
112
113 private:
114 void ReadbackTrace(const std::string&, ParsedTraceStats*);
115 void ParseTracePacket(const uint8_t*, size_t, ParsedTraceStats* ctx);
116 void AddFailure(const char* fmt, ...) PERFETTO_PRINTF_FORMAT(2, 3);
117
118 std::vector<std::string> env_;
119 std::list<TestResult> test_results_;
120 std::string results_dir_;
121 base::ScopedFile error_log_;
122 };
123
TestHarness()124 TestHarness::TestHarness() {
125 results_dir_ = base::GetSysTempDir() + "/perfetto-stress-test";
126 #if PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
127 base::ignore_result(system(("rmdir \"" + results_dir_ + "\" /s /q").c_str()));
128 #else
129 base::ignore_result(system(("rm -r -- \"" + results_dir_ + "\"").c_str()));
130 #endif
131 PERFETTO_CHECK(base::Mkdir(results_dir_));
132 PERFETTO_LOG("Saving test results in %s", results_dir_.c_str());
133 }
134
AddFailure(const char * fmt,...)135 void TestHarness::AddFailure(const char* fmt, ...) {
136 ++test_results_.back().num_errors;
137
138 char log_msg[512];
139 va_list args;
140 va_start(args, fmt);
141 int res = vsnprintf(log_msg, sizeof(log_msg), fmt, args);
142 va_end(args);
143
144 PERFETTO_ELOG("FAIL: %s", log_msg);
145
146 if (res > 0 && static_cast<size_t>(res) < sizeof(log_msg) - 2) {
147 log_msg[res++] = '\n';
148 log_msg[res++] = '\0';
149 }
150
151 base::WriteAll(*error_log_, log_msg, static_cast<size_t>(res));
152 }
153
RunConfig(const char * cfg_name,const StressTestConfig & cfg,bool verbose)154 void TestHarness::RunConfig(const char* cfg_name,
155 const StressTestConfig& cfg,
156 bool verbose) {
157 test_results_.emplace_back();
158 TestResult& test_result = test_results_.back();
159 test_result.cfg_name = cfg_name;
160 test_result.cfg = cfg;
161 g_sig->pids_to_kill.clear();
162
163 auto result_dir = results_dir_ + "/" + cfg_name;
164 PERFETTO_CHECK(base::Mkdir(result_dir));
165 error_log_ = base::OpenFile(result_dir + "/errors.log",
166 O_RDWR | O_CREAT | O_TRUNC, 0644);
167
168 PERFETTO_ILOG("Starting \"%s\" - %s", cfg_name, result_dir.c_str());
169
170 env_.emplace_back("PERFETTO_PRODUCER_SOCK_NAME=" + result_dir +
171 "/producer.sock");
172 env_.emplace_back("PERFETTO_CONSUMER_SOCK_NAME=" + result_dir +
173 "/consumer.sock");
174 std::string bin_dir = base::GetCurExecutableDir();
175
176 // Start the service.
177 base::Subprocess traced({bin_dir + "/traced"});
178 traced.args.env = env_;
179 if (!verbose) {
180 traced.args.out_fd = OpenLogFile(result_dir + "/traced.log");
181 traced.args.stderr_mode = traced.args.stdout_mode = base::Subprocess::kFd;
182 }
183 traced.Start();
184 g_sig->pids_to_kill.emplace_back(traced.pid());
185 std::this_thread::sleep_for(std::chrono::milliseconds(100));
186 PERFETTO_CHECK(traced.Poll() == base::Subprocess::kRunning);
187
188 // Start the producer processes.
189 std::list<base::Subprocess> producers;
190 for (uint32_t i = 0; i < cfg.num_processes(); ++i) {
191 producers.emplace_back(base::Subprocess({bin_dir + "/stress_producer"}));
192 auto& producer = producers.back();
193 producer.args.input = cfg.SerializeAsString();
194 if (!verbose) {
195 producer.args.out_fd =
196 OpenLogFile(result_dir + "/producer." + std::to_string(i) + ".log");
197 producer.args.stderr_mode = producer.args.stdout_mode =
198 base::Subprocess::kFd;
199 }
200 producer.args.env = env_;
201 producer.Start();
202 g_sig->pids_to_kill.emplace_back(producer.pid());
203 }
204 std::this_thread::sleep_for(std::chrono::milliseconds(100));
205 for (auto& producer : producers)
206 PERFETTO_CHECK(producer.Poll() == base::Subprocess::kRunning);
207
208 auto trace_file_path = result_dir + "/trace";
209 base::Subprocess consumer(
210 {bin_dir + "/perfetto", "-c", "-", "-o", trace_file_path.c_str()});
211 consumer.args.env = env_;
212 consumer.args.input = cfg.trace_config().SerializeAsString();
213 if (!verbose) {
214 consumer.args.out_fd = OpenLogFile(result_dir + "/perfetto.log");
215 consumer.args.stderr_mode = consumer.args.stdout_mode =
216 base::Subprocess::kFd;
217 }
218 remove(trace_file_path.c_str());
219 consumer.Start();
220 int64_t t_start = base::GetBootTimeNs().count();
221 g_sig->pids_to_kill.emplace_back(consumer.pid());
222
223 std::this_thread::sleep_for(std::chrono::milliseconds(100));
224 PERFETTO_CHECK(consumer.Poll() == base::Subprocess::kRunning);
225
226 if (!consumer.Wait(
227 static_cast<int>(cfg.trace_config().duration_ms() + 30000))) {
228 AddFailure("Consumer didn't quit in time");
229 consumer.KillAndWaitForTermination();
230 }
231
232 int64_t t_end = base::GetBootTimeNs().count();
233
234 for (auto& producer : producers) {
235 producer.KillAndWaitForTermination();
236 test_result.prod_rusage = producer.posix_rusage(); // Only keep last one
237 }
238 producers.clear();
239 traced.KillAndWaitForTermination();
240
241 test_result.svc_rusage = traced.posix_rusage();
242 test_result.run_time_ms = static_cast<uint32_t>((t_end - t_start) / 1000000);
243
244 // Verify
245 // TODO(primiano): read back the TraceStats and check them as well.
246 ParsedTraceStats ctx;
247 ReadbackTrace(trace_file_path, &ctx);
248 auto exp_thd = cfg.num_processes() * cfg.num_threads();
249 if (ctx.threads.size() != exp_thd) {
250 AddFailure("Trace threads mismatch. Expected %u threads, got %zu", exp_thd,
251 ctx.threads.size());
252 }
253 for (const auto& it : ctx.threads) {
254 uint32_t seq_id = it.first;
255 const auto& thd = it.second;
256 if (!thd.last_seen) {
257 AddFailure("Last packet not seen for sequence %u", seq_id);
258 }
259 if (thd.seq_errors > 0) {
260 AddFailure("Sequence %u had %" PRIu64 " packets out of sync", seq_id,
261 thd.seq_errors);
262 }
263 if (thd.counter_errors > 0) {
264 AddFailure("Sequence %u had %" PRIu64 " packets counter errors", seq_id,
265 thd.counter_errors);
266 }
267 }
268
269 error_log_.reset();
270 PERFETTO_ILOG("Completed \"%s\"", cfg_name);
271 }
272
ReadbackTrace(const std::string & trace_file_path,ParsedTraceStats * ctx)273 void TestHarness::ReadbackTrace(const std::string& trace_file_path,
274 ParsedTraceStats* ctx) {
275 TestResult& test_result = test_results_.back();
276 using namespace protozero::proto_utils;
277 auto fd = base::OpenFile(trace_file_path.c_str(), O_RDONLY);
278 if (!fd)
279 return AddFailure("Trace file does not exist");
280 const off_t file_size = lseek(*fd, 0, SEEK_END);
281 lseek(*fd, 0, SEEK_SET);
282 if (file_size <= 0)
283 return AddFailure("Trace file is empty");
284
285 test_result.trace_size_kb = static_cast<uint32_t>(file_size / 1000);
286 std::string trace_data;
287 PERFETTO_CHECK(base::ReadFileDescriptor(*fd, &trace_data));
288 const auto* const start = reinterpret_cast<const uint8_t*>(trace_data.data());
289 const uint8_t* const end = start + file_size;
290
291 constexpr uint8_t kTracePacketTag = MakeTagLengthDelimited(1);
292
293 for (auto* ptr = start; (end - ptr) > 2;) {
294 const uint8_t* tokenizer_start = ptr;
295 if (*(ptr++) != kTracePacketTag) {
296 return AddFailure("Tokenizer failure at offset %zd", ptr - start);
297 }
298 uint64_t packet_size = 0;
299 ptr = ParseVarInt(ptr, end, &packet_size);
300 const uint8_t* const packet_start = ptr;
301 ptr += packet_size;
302 if ((ptr - tokenizer_start) < 2 || ptr > end)
303 return AddFailure("Got invalid packet size %" PRIu64 " at offset %zd",
304 packet_size,
305 static_cast<ssize_t>(packet_start - start));
306 ParseTracePacket(packet_start, static_cast<size_t>(packet_size), ctx);
307 }
308 test_result.num_threads = static_cast<uint32_t>(ctx->threads.size());
309 }
310
ParseTracePacket(const uint8_t * start,size_t size,ParsedTraceStats * ctx)311 void TestHarness::ParseTracePacket(const uint8_t* start,
312 size_t size,
313 ParsedTraceStats* ctx) {
314 TestResult& test_result = test_results_.back();
315 protos::pbzero::TracePacket::Decoder packet(start, size);
316 if (!packet.has_for_testing())
317 return;
318
319 ++test_result.num_packets;
320 const uint32_t seq_id = packet.trusted_packet_sequence_id();
321
322 protos::pbzero::TestEvent::Decoder te(packet.for_testing());
323 auto t_it = ctx->threads.find(seq_id);
324 bool is_first_packet = false;
325 if (t_it == ctx->threads.end()) {
326 is_first_packet = true;
327 t_it = ctx->threads.emplace(seq_id, ParsedTraceStats::WriterThread()).first;
328 }
329 ParsedTraceStats::WriterThread& thd = t_it->second;
330
331 ++thd.packets_seen;
332 if (te.is_last()) {
333 if (thd.last_seen) {
334 return AddFailure(
335 "last_seen=true happened more than once for sequence %u", seq_id);
336 } else {
337 thd.last_seen = true;
338 }
339 }
340 if (is_first_packet) {
341 thd.rnd_engine = std::minstd_rand0(te.seq_value());
342 } else {
343 const uint32_t expected = static_cast<uint32_t>(thd.rnd_engine());
344 if (te.seq_value() != expected) {
345 thd.rnd_engine = std::minstd_rand0(te.seq_value()); // Resync the engine.
346 ++thd.seq_errors;
347 return AddFailure(
348 "TestEvent seq mismatch for sequence %u. Expected %u got %u", seq_id,
349 expected, te.seq_value());
350 }
351 if (te.counter() != thd.packets_seen) {
352 return AddFailure(
353 "TestEvent counter mismatch for sequence %u. Expected %" PRIu64
354 " got %" PRIu64,
355 seq_id, thd.packets_seen, te.counter());
356 }
357 }
358
359 if (!te.has_payload()) {
360 return AddFailure("TestEvent %u for sequence %u has no payload",
361 te.seq_value(), seq_id);
362 }
363
364 // Check the validity of the payload. The payload might be nested. If that is
365 // the case, we need to check all levels.
366 protozero::ConstBytes payload_bounds = te.payload();
367 for (uint32_t depth = 0, last_depth = 0;; depth++) {
368 if (depth > 100) {
369 return AddFailure("Unexpectedly deep depth for event %u, sequence %u",
370 te.seq_value(), seq_id);
371 }
372 protos::pbzero::TestEvent::TestPayload::Decoder payload(payload_bounds);
373 const uint32_t rem_depth = payload.remaining_nesting_depth();
374
375 // The payload is a repeated field and must have exactly two instances.
376 // The writer splits it always in two halves of identical size.
377 int num_payload_pieces = 0;
378 size_t last_size = 0;
379 for (auto it = payload.str(); it; ++it, ++num_payload_pieces) {
380 protozero::ConstChars payload_str = *it;
381 last_size = last_size ? last_size : payload_str.size;
382 if (payload_str.size != last_size) {
383 return AddFailure(
384 "Asymmetrical payload at depth %u, event id %u, sequence %u. "
385 "%zu != %zu",
386 depth, te.seq_value(), seq_id, last_size, payload_str.size);
387 }
388 // Check that the payload content matches the expected sequence.
389 for (size_t i = 0; i < payload_str.size; i++) {
390 char exp = static_cast<char>(33 + ((te.seq_value() + i) % 64));
391 if (payload_str.data[i] != exp) {
392 return AddFailure(
393 "Payload mismatch at %zu, depth %u, event id %u, sequence %u. "
394 "Expected: 0x%x, Actual: 0x%x",
395 i, depth, te.seq_value(), seq_id, exp, payload_str.data[i]);
396 }
397 }
398 }
399 if (num_payload_pieces != 2) {
400 return AddFailure(
401 "Broken payload at depth %u, event id %u, sequence %u. "
402 "Expecting 2 repeated str fields, got %d",
403 depth, te.seq_value(), seq_id, num_payload_pieces);
404 }
405
406 if (depth > 0 && rem_depth != last_depth - 1) {
407 return AddFailure(
408 "Unexpected nesting level (expected: %u, actual: %u) at depth %u, "
409 "event id %u, sequence %u",
410 rem_depth, last_depth - 1, depth, te.seq_value(), seq_id);
411 }
412
413 last_depth = rem_depth;
414 if (rem_depth == 0)
415 break;
416 if (payload.has_nested()) {
417 payload_bounds = *payload.nested();
418 } else {
419 payload_bounds = {nullptr, 0};
420 }
421 }
422 }
423
CtrlCHandler()424 void CtrlCHandler() {
425 g_sig->aborted.store(true);
426 for (auto it = g_sig->pids_to_kill.rbegin(); it != g_sig->pids_to_kill.rend();
427 it++) {
428 #if PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
429 base::ScopedPlatformHandle proc_handle(
430 ::OpenProcess(PROCESS_TERMINATE, false, *it));
431 ::TerminateProcess(*proc_handle, STATUS_CONTROL_C_EXIT);
432 #else
433 kill(*it, SIGKILL);
434 #endif
435 }
436 }
437
StressTestMain(int argc,char ** argv)438 void StressTestMain(int argc, char** argv) {
439 TestHarness th;
440 std::regex filter;
441 bool has_filter = false;
442
443 bool verbose = false;
444 for (int i = 1; i < argc; ++i) {
445 if (!strcmp(argv[i], "-v")) {
446 verbose = true;
447 } else {
448 filter = std::regex(argv[i], std::regex::ECMAScript | std::regex::icase);
449 has_filter = true;
450 }
451 }
452
453 g_sig = new SigHandlerCtx();
454 base::InstallCtrCHandler(&CtrlCHandler);
455
456 for (size_t i = 0; i < base::ArraySize(kStressTestConfigs) && !g_sig->aborted;
457 ++i) {
458 const auto& cfg_blob = kStressTestConfigs[i];
459 StressTestConfig cfg;
460 std::cmatch ignored;
461 if (has_filter && !std::regex_search(cfg_blob.name, ignored, filter)) {
462 continue;
463 }
464 PERFETTO_CHECK(cfg.ParseFromArray(cfg_blob.data, cfg_blob.size));
465 th.RunConfig(cfg_blob.name, cfg, verbose);
466 }
467
468 for (const auto& tres : th.test_results()) {
469 const auto& cfg = tres.cfg;
470 printf("===============================================================\n");
471 printf("Config: %s\n", tres.cfg_name);
472 printf("===============================================================\n");
473 printf("%-20s %-10s %-10s\n", "Metric", "Expected", "Actual");
474 printf("%-20s %-10s %-10s\n", "------", "--------", "------");
475 printf("%-20s %-10d %-10d\n", "#Errors", 0, tres.num_errors);
476 printf("%-20s %-10d %-10d \n", "Duration [ms]",
477 cfg.trace_config().duration_ms(), tres.run_time_ms);
478
479 uint32_t exp_threads = cfg.num_processes() * cfg.num_threads();
480 printf("%-20s %-10u %-10u\n", "Num threads", exp_threads, tres.num_threads);
481
482 double dur_s = cfg.trace_config().duration_ms() / 1e3;
483 double exp_per_thread = cfg.steady_state_timings().rate_mean() * dur_s;
484 if (cfg.burst_period_ms()) {
485 double burst_rate = 1.0 * cfg.burst_duration_ms() / cfg.burst_period_ms();
486 exp_per_thread *= 1.0 - burst_rate;
487 exp_per_thread += burst_rate * cfg.burst_timings().rate_mean() * dur_s;
488 }
489 if (cfg.max_events())
490 exp_per_thread = std::min(exp_per_thread, 1.0 * cfg.max_events());
491 double exp_packets = std::round(exp_per_thread * exp_threads);
492 printf("%-20s %-10.0f %-10d\n", "Num packets", exp_packets,
493 tres.num_packets);
494
495 double exp_size_kb = exp_packets * (cfg.nesting() + 1) *
496 (cfg.steady_state_timings().payload_mean() + 40) /
497 1000;
498 printf("%-20s ~%-9.0f %-10d\n", "Trace size [KB]", exp_size_kb,
499 tres.trace_size_kb);
500
501 double exp_rss_mb = cfg.trace_config().buffers()[0].size_kb() / 1000;
502 printf("%-20s (max) %-4.0f %-10d\n", "Svc RSS [MB]", exp_rss_mb,
503 tres.svc_rusage.max_rss_kb / 1000);
504 printf("%-20s %-10s %-10d\n", "Svc CPU [ms]", "---",
505 tres.svc_rusage.cpu_time_ms());
506 printf("%-20s %-10s %d / %d\n", "Svc #ctxswitch", "---",
507 tres.svc_rusage.invol_ctx_switch, tres.svc_rusage.vol_ctx_switch);
508
509 printf("%-20s %-10s %-10d\n", "Prod RSS [MB]", "---",
510 tres.prod_rusage.max_rss_kb / 1000);
511 printf("%-20s %-10s %-10d\n", "Prod CPU [ms]", "---",
512 tres.prod_rusage.cpu_time_ms());
513 printf("%-20s %-10s %d / %d\n", "Prod #ctxswitch", "---",
514 tres.prod_rusage.invol_ctx_switch, tres.prod_rusage.vol_ctx_switch);
515 printf("\n");
516 }
517 }
518
519 } // namespace
520 } // namespace perfetto
521
main(int argc,char ** argv)522 int main(int argc, char** argv) {
523 perfetto::StressTestMain(argc, argv);
524 }
525