1 /*
2 * Copyright (C) 2018 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 <inttypes.h>
18
19 #include <stdio.h>
20 #include <sys/ioctl.h>
21 #include <unistd.h>
22
23 #include <algorithm>
24 #include <fstream>
25 #include <functional>
26 #include <iostream>
27 #include <istream>
28 #include <limits>
29 #include <map>
30 #include <memory>
31 #include <ostream>
32 #include <sstream>
33 #include <utility>
34
35 #include <google/protobuf/compiler/importer.h>
36 #include <google/protobuf/dynamic_message.h>
37 #include <google/protobuf/io/zero_copy_stream_impl.h>
38 #include <google/protobuf/text_format.h>
39 #include <google/protobuf/util/field_comparator.h>
40 #include <google/protobuf/util/message_differencer.h>
41
42 #include "perfetto/base/logging.h"
43 #include "perfetto/trace/trace.pb.h"
44 #include "perfetto/trace/trace_packet.pb.h"
45 #include "tools/trace_to_text/ftrace_event_formatter.h"
46 #include "tools/trace_to_text/ftrace_inode_handler.h"
47
48 namespace perfetto {
49 namespace {
50
51 const char kTraceHeader[] = R"({
52 "traceEvents": [],
53 )";
54
55 const char kTraceFooter[] = R"(\n",
56 "controllerTraceDataKey": "systraceController"
57 })";
58
59 const char kFtraceHeader[] =
60 ""
61 " \"systemTraceEvents\": \""
62 "# tracer: nop\\n"
63 "#\\n"
64 "# entries-in-buffer/entries-written: 30624/30624 #P:4\\n"
65 "#\\n"
66 "# _-----=> irqs-off\\n"
67 "# / _----=> need-resched\\n"
68 "# | / _---=> hardirq/softirq\\n"
69 "# || / _--=> preempt-depth\\n"
70 "# ||| / delay\\n"
71 "# TASK-PID TGID CPU# |||| TIMESTAMP FUNCTION\\n"
72 "# | | | | |||| | |\\n";
73
74 using google::protobuf::Descriptor;
75 using google::protobuf::DynamicMessageFactory;
76 using google::protobuf::FileDescriptor;
77 using google::protobuf::Message;
78 using google::protobuf::TextFormat;
79 using google::protobuf::compiler::DiskSourceTree;
80 using google::protobuf::compiler::Importer;
81 using google::protobuf::compiler::MultiFileErrorCollector;
82 using google::protobuf::io::OstreamOutputStream;
83
84 using protos::FtraceEvent;
85 using protos::FtraceEventBundle;
86 using protos::InodeFileMap;
87 using protos::PrintFtraceEvent;
88 using protos::ProcessTree;
89 using protos::Trace;
90 using protos::TracePacket;
91 using Entry = protos::InodeFileMap::Entry;
92 using Process = protos::ProcessTree::Process;
93
94 // TODO(hjd): Add tests.
95
GetWidth()96 size_t GetWidth() {
97 if (!isatty(STDOUT_FILENO))
98 return 80;
99 struct winsize win_size;
100 ioctl(STDOUT_FILENO, TIOCGWINSZ, &win_size);
101 return win_size.ws_col;
102 }
103
104 class MFE : public MultiFileErrorCollector {
AddError(const std::string & filename,int line,int column,const std::string & message)105 virtual void AddError(const std::string& filename,
106 int line,
107 int column,
108 const std::string& message) {
109 PERFETTO_ELOG("Error %s %d:%d: %s", filename.c_str(), line, column,
110 message.c_str());
111 }
112
AddWarning(const std::string & filename,int line,int column,const std::string & message)113 virtual void AddWarning(const std::string& filename,
114 int line,
115 int column,
116 const std::string& message) {
117 PERFETTO_ELOG("Error %s %d:%d: %s", filename.c_str(), line, column,
118 message.c_str());
119 }
120 };
121
ForEachPacketInTrace(std::istream * input,const std::function<void (const protos::TracePacket &)> & f)122 void ForEachPacketInTrace(
123 std::istream* input,
124 const std::function<void(const protos::TracePacket&)>& f) {
125 size_t bytes_processed = 0;
126 // The trace stream can be very large. We cannot just pass it in one go to
127 // libprotobuf as that will refuse to parse messages > 64MB. However we know
128 // that a trace is merely a sequence of TracePackets. Here we just manually
129 // tokenize the repeated TracePacket messages and parse them individually
130 // using libprotobuf.
131 for (;;) {
132 fprintf(stderr, "Processing trace: %8zu KB\r", bytes_processed / 1024);
133 fflush(stderr);
134 // A TracePacket consists in one byte stating its field id and type ...
135 char preamble;
136 input->get(preamble);
137 if (!input->good())
138 break;
139 bytes_processed++;
140 PERFETTO_DCHECK(preamble == 0x0a); // Field ID:1, type:length delimited.
141
142 // ... a varint stating its size ...
143 uint32_t field_size = 0;
144 uint32_t shift = 0;
145 for (;;) {
146 char c = 0;
147 input->get(c);
148 field_size |= static_cast<uint32_t>(c & 0x7f) << shift;
149 shift += 7;
150 bytes_processed++;
151 if (!(c & 0x80))
152 break;
153 }
154
155 // ... and the actual TracePacket itself.
156 std::unique_ptr<char[]> buf(new char[field_size]);
157 input->read(buf.get(), static_cast<std::streamsize>(field_size));
158 bytes_processed += field_size;
159
160 protos::TracePacket packet;
161 auto res = packet.ParseFromArray(buf.get(), static_cast<int>(field_size));
162 PERFETTO_CHECK(res);
163 f(packet);
164 }
165 }
166
TraceToSystrace(std::istream * input,std::ostream * output,bool wrap_in_json)167 int TraceToSystrace(std::istream* input,
168 std::ostream* output,
169 bool wrap_in_json) {
170 std::multimap<uint64_t, std::string> sorted;
171
172 ForEachPacketInTrace(input, [&sorted](const protos::TracePacket& packet) {
173 if (!packet.has_ftrace_events())
174 return;
175
176 const FtraceEventBundle& bundle = packet.ftrace_events();
177 for (const FtraceEvent& event : bundle.event()) {
178 std::string line =
179 FormatFtraceEvent(event.timestamp(), bundle.cpu(), event);
180 if (line == "")
181 continue;
182 sorted.emplace(event.timestamp(), line);
183 }
184 });
185
186 if (wrap_in_json) {
187 *output << kTraceHeader;
188 *output << kFtraceHeader;
189 }
190
191 fprintf(stderr, "\n");
192 size_t total_events = sorted.size();
193 size_t written_events = 0;
194 for (auto it = sorted.begin(); it != sorted.end(); it++) {
195 *output << it->second << (wrap_in_json ? "\\n" : "\n");
196 if (written_events++ % 100 == 0 && !isatty(STDOUT_FILENO)) {
197 fprintf(stderr, "Writing trace: %.2f %%\r",
198 written_events * 100.0 / total_events);
199 fflush(stderr);
200 }
201 }
202
203 if (wrap_in_json)
204 *output << kTraceFooter;
205
206 return 0;
207 }
208
TraceToText(std::istream * input,std::ostream * output)209 int TraceToText(std::istream* input, std::ostream* output) {
210 DiskSourceTree dst;
211 dst.MapPath("perfetto", "protos/perfetto");
212 MFE mfe;
213 Importer importer(&dst, &mfe);
214 const FileDescriptor* parsed_file =
215 importer.Import("perfetto/trace/trace.proto");
216
217 DynamicMessageFactory dmf;
218 const Descriptor* trace_descriptor = parsed_file->message_type(0);
219 const Message* msg_root = dmf.GetPrototype(trace_descriptor);
220 Message* msg = msg_root->New();
221
222 if (!msg->ParseFromIstream(input)) {
223 PERFETTO_ELOG("Could not parse input.");
224 return 1;
225 }
226 OstreamOutputStream zero_copy_output(output);
227 TextFormat::Print(*msg, &zero_copy_output);
228 return 0;
229 }
230
PrintFtraceTrack(std::ostream * output,const uint64_t & start,const uint64_t & end,const std::multiset<uint64_t> & ftrace_timestamps)231 void PrintFtraceTrack(std::ostream* output,
232 const uint64_t& start,
233 const uint64_t& end,
234 const std::multiset<uint64_t>& ftrace_timestamps) {
235 constexpr char kFtraceTrackName[] = "ftrace ";
236 size_t width = GetWidth();
237 size_t bucket_count = width - strlen(kFtraceTrackName);
238 size_t bucket_size = static_cast<size_t>(end - start) / bucket_count;
239 size_t max = 0;
240 std::vector<size_t> buckets(bucket_count);
241 for (size_t i = 0; i < bucket_count; i++) {
242 auto low = ftrace_timestamps.lower_bound(i * bucket_size + start);
243 auto high = ftrace_timestamps.upper_bound((i + 1) * bucket_size + start);
244 buckets[i] = static_cast<size_t>(std::distance(low, high));
245 max = std::max(max, buckets[i]);
246 }
247
248 std::vector<std::string> out =
249 std::vector<std::string>({" ", "▁", "▂", "▃", "▄", "▅", "▆", "▇"});
250 *output << "-------------------- " << kFtraceTrackName
251 << "--------------------\n";
252 char line[2048];
253 for (size_t i = 0; i < bucket_count; i++) {
254 sprintf(
255 line, "%s",
256 out[std::min(buckets[i] / (max / out.size()), out.size() - 1)].c_str());
257 *output << std::string(line);
258 }
259 *output << "\n\n";
260 }
261
PrintInodeStats(std::ostream * output,const std::set<uint64_t> & ftrace_inodes,const uint64_t & ftrace_inode_count,const std::set<uint64_t> & resolved_map_inodes,const std::set<uint64_t> & resolved_scan_inodes,bool compact_output)262 void PrintInodeStats(std::ostream* output,
263 const std::set<uint64_t>& ftrace_inodes,
264 const uint64_t& ftrace_inode_count,
265 const std::set<uint64_t>& resolved_map_inodes,
266 const std::set<uint64_t>& resolved_scan_inodes,
267 bool compact_output) {
268 if (!compact_output)
269 *output << "--------------------Inode Stats-------------------\n";
270
271 char line[2048];
272 if (compact_output) {
273 sprintf(line, "events_inodes,%" PRIu64 "\n", ftrace_inode_count);
274 } else {
275 sprintf(line, "Events with inodes: %" PRIu64 "\n", ftrace_inode_count);
276 }
277 *output << std::string(line);
278
279 if (compact_output) {
280 sprintf(line, "events_unique_inodes,%zu\n", ftrace_inodes.size());
281 } else {
282 sprintf(line, "Unique inodes from events: %zu\n", ftrace_inodes.size());
283 }
284 *output << std::string(line);
285
286 if (compact_output) {
287 sprintf(line, "resolved_inodes_static,%zu\n", resolved_map_inodes.size());
288 } else {
289 sprintf(line, "Resolved inodes from static map: %zu\n",
290 resolved_map_inodes.size());
291 }
292 *output << std::string(line);
293
294 if (compact_output) {
295 sprintf(line, "resolved_inodes_scan_cache,%zu\n",
296 resolved_scan_inodes.size());
297 } else {
298 sprintf(line, "Resolved inodes from scan and cache: %zu\n",
299 resolved_scan_inodes.size());
300 }
301 *output << std::string(line);
302
303 std::set<uint64_t> resolved_inodes;
304 set_union(resolved_map_inodes.begin(), resolved_map_inodes.end(),
305 resolved_scan_inodes.begin(), resolved_scan_inodes.end(),
306 std::inserter(resolved_inodes, resolved_inodes.begin()));
307
308 if (compact_output) {
309 sprintf(line, "total_resolved_inodes,%zu\n", resolved_inodes.size());
310 } else {
311 sprintf(line, "Total resolved inodes: %zu\n", resolved_inodes.size());
312 }
313 *output << std::string(line);
314
315 std::set<uint64_t> intersect;
316 set_intersection(resolved_inodes.begin(), resolved_inodes.end(),
317 ftrace_inodes.begin(), ftrace_inodes.end(),
318 std::inserter(intersect, intersect.begin()));
319
320 size_t unresolved_inodes = ftrace_inodes.size() - intersect.size();
321 if (compact_output) {
322 sprintf(line, "unresolved_inodes,%zu\n", unresolved_inodes);
323 } else {
324 sprintf(line, "Unresolved inodes: %zu\n", unresolved_inodes);
325 }
326 *output << std::string(line);
327
328 size_t unexpected_inodes = resolved_inodes.size() - intersect.size();
329 if (compact_output) {
330 sprintf(line, "unexpected_inodes_fs,%zu\n", unexpected_inodes);
331 } else {
332 sprintf(line, "Unexpected inodes from filesystem: %zu\n",
333 unexpected_inodes);
334 }
335 *output << std::string(line);
336
337 if (!compact_output)
338 *output << "\n";
339 }
340
PrintProcessStats(std::ostream * output,const std::set<pid_t> & tids_in_tree,const std::set<pid_t> & tids_in_events,bool compact_output)341 void PrintProcessStats(std::ostream* output,
342 const std::set<pid_t>& tids_in_tree,
343 const std::set<pid_t>& tids_in_events,
344 bool compact_output) {
345 if (!compact_output)
346 *output << "----------------Process Tree Stats----------------\n";
347
348 char tid[2048];
349 if (compact_output) {
350 sprintf(tid, "unique_thread_process,%zu\n", tids_in_tree.size());
351 } else {
352 sprintf(tid, "Unique thread ids in process tree: %zu\n",
353 tids_in_tree.size());
354 }
355 *output << std::string(tid);
356
357 char tid_event[2048];
358 if (compact_output) {
359 sprintf(tid_event, "unique_thread_ftrace,%zu\n", tids_in_events.size());
360 } else {
361 sprintf(tid_event, "Unique thread ids in ftrace events: %zu\n",
362 tids_in_events.size());
363 }
364 *output << std::string(tid_event);
365
366 std::set<pid_t> intersect;
367 set_intersection(tids_in_tree.begin(), tids_in_tree.end(),
368 tids_in_events.begin(), tids_in_events.end(),
369 std::inserter(intersect, intersect.begin()));
370
371 char matching[2048];
372 size_t thread_id_process_info =
373 (intersect.size() * 100) / tids_in_events.size();
374 if (compact_output) {
375 sprintf(matching,
376 "tids_with_pinfo,%zu\ntids,%zu\ntids_with_pinfo_percentage,%zu\n",
377 intersect.size(), tids_in_events.size(), thread_id_process_info);
378 } else {
379 sprintf(matching, "Thread ids with process info: %zu/%zu -> %zu %%\n\n",
380 intersect.size(), tids_in_events.size(), thread_id_process_info);
381 }
382 *output << std::string(matching);
383
384 if (!compact_output)
385 *output << "\n";
386 }
387
TraceToSummary(std::istream * input,std::ostream * output,bool compact_output)388 int TraceToSummary(std::istream* input,
389 std::ostream* output,
390 bool compact_output) {
391 uint64_t start = std::numeric_limits<uint64_t>::max();
392 uint64_t end = 0;
393 std::multiset<uint64_t> ftrace_timestamps;
394 std::set<pid_t> tids_in_tree;
395 std::set<pid_t> tids_in_events;
396 std::set<uint64_t> ftrace_inodes;
397 uint64_t ftrace_inode_count = 0;
398 std::set<uint64_t> resolved_map_inodes;
399 std::set<uint64_t> resolved_scan_inodes;
400
401 ForEachPacketInTrace(
402 input, [&start, &end, &ftrace_timestamps, &tids_in_tree, &tids_in_events,
403 &ftrace_inodes, &ftrace_inode_count, &resolved_map_inodes,
404 &resolved_scan_inodes](const protos::TracePacket& packet) {
405
406 if (packet.has_process_tree()) {
407 const ProcessTree& tree = packet.process_tree();
408 for (Process process : tree.processes()) {
409 tids_in_tree.insert(process.pid());
410 for (ProcessTree::Thread thread : process.threads_deprecated())
411 tids_in_tree.insert(thread.tid());
412 }
413 for (ProcessTree::Thread thread : tree.threads())
414 tids_in_tree.insert(thread.tid());
415 }
416
417 if (packet.has_inode_file_map()) {
418 const InodeFileMap& inode_file_map = packet.inode_file_map();
419 const auto& mount_points = inode_file_map.mount_points();
420 bool from_scan = std::find(mount_points.begin(), mount_points.end(),
421 "/data") != mount_points.end();
422 for (const auto& entry : inode_file_map.entries())
423 if (from_scan)
424 resolved_scan_inodes.insert(entry.inode_number());
425 else
426 resolved_map_inodes.insert(entry.inode_number());
427 }
428
429 if (!packet.has_ftrace_events())
430 return;
431
432 const FtraceEventBundle& bundle = packet.ftrace_events();
433 uint64_t inode_number = 0;
434 for (const FtraceEvent& event : bundle.event()) {
435 if (ParseInode(event, &inode_number)) {
436 ftrace_inodes.insert(inode_number);
437 ftrace_inode_count++;
438 }
439 if (event.pid()) {
440 tids_in_events.insert(static_cast<int>(event.pid()));
441 }
442 if (event.timestamp()) {
443 start = std::min<uint64_t>(start, event.timestamp());
444 end = std::max<uint64_t>(end, event.timestamp());
445 ftrace_timestamps.insert(event.timestamp());
446 }
447 }
448 });
449
450 fprintf(stderr, "\n");
451
452 char line[2048];
453 uint64_t duration = (end - start) / (1000 * 1000);
454 if (compact_output) {
455 sprintf(line, "duration,%" PRIu64 "\n", duration);
456 } else {
457 sprintf(line, "Duration: %" PRIu64 "ms\n", duration);
458 }
459 *output << std::string(line);
460
461 if (!compact_output)
462 PrintFtraceTrack(output, start, end, ftrace_timestamps);
463 PrintProcessStats(output, tids_in_tree, tids_in_events, compact_output);
464 PrintInodeStats(output, ftrace_inodes, ftrace_inode_count,
465 resolved_map_inodes, resolved_scan_inodes, compact_output);
466
467 return 0;
468 }
469
470 } // namespace
471 } // namespace perfetto
472
473 namespace {
474
Usage(const char * argv0)475 int Usage(const char* argv0) {
476 printf(
477 "Usage: %s [systrace|json|text|summary|short_summary] < trace.proto > "
478 "trace.txt\n",
479 argv0);
480 return 1;
481 }
482
483 } // namespace
484
main(int argc,char ** argv)485 int main(int argc, char** argv) {
486 if (argc != 2)
487 return Usage(argv[0]);
488
489 std::string format(argv[1]);
490
491 if (format == "json")
492 return perfetto::TraceToSystrace(&std::cin, &std::cout,
493 /*wrap_in_json=*/true);
494 if (format == "systrace")
495 return perfetto::TraceToSystrace(&std::cin, &std::cout,
496 /*wrap_in_json=*/false);
497 if (format == "text")
498 return perfetto::TraceToText(&std::cin, &std::cout);
499 if (format == "summary")
500 return perfetto::TraceToSummary(&std::cin, &std::cout,
501 /* compact_output */ true);
502 if (format == "short_summary")
503 return perfetto::TraceToSummary(&std::cin, &std::cout,
504 /* compact_output */ true);
505
506 return Usage(argv[0]);
507 }
508