main.cc revision 5e8fa4b6f11c49df07e70314f79060109a72ad42 
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
48namespace perfetto {
49namespace {
50
51const char kTraceHeader[] = R"({
52  "traceEvents": [],
53)";
54
55const char kTraceFooter[] = R"(\n",
56  "controllerTraceDataKey": "systraceController"
57})";
58
59const 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
74using google::protobuf::Descriptor;
75using google::protobuf::DynamicMessageFactory;
76using google::protobuf::FileDescriptor;
77using google::protobuf::Message;
78using google::protobuf::TextFormat;
79using google::protobuf::compiler::DiskSourceTree;
80using google::protobuf::compiler::Importer;
81using google::protobuf::compiler::MultiFileErrorCollector;
82using google::protobuf::io::OstreamOutputStream;
83
84using protos::FtraceEvent;
85using protos::FtraceEventBundle;
86using protos::InodeFileMap;
87using protos::PrintFtraceEvent;
88using protos::ProcessTree;
89using protos::Trace;
90using protos::TracePacket;
91using Entry = protos::InodeFileMap::Entry;
92using Process = protos::ProcessTree::Process;
93
94// TODO(hjd): Add tests.
95
96size_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
104class MFE : public MultiFileErrorCollector {
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
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
122void 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(), field_size);
158    bytes_processed += field_size;
159
160    protos::TracePacket packet;
161    PERFETTO_CHECK(packet.ParseFromArray(buf.get(), field_size));
162
163    f(packet);
164  }
165}
166
167int TraceToSystrace(std::istream* input, std::ostream* output) {
168  std::multimap<uint64_t, std::string> sorted;
169
170  ForEachPacketInTrace(input, [&sorted](const protos::TracePacket& packet) {
171    if (!packet.has_ftrace_events())
172      return;
173
174    const FtraceEventBundle& bundle = packet.ftrace_events();
175    for (const FtraceEvent& event : bundle.event()) {
176      std::string line =
177          FormatFtraceEvent(event.timestamp(), bundle.cpu(), event);
178      if (line == "")
179        continue;
180      sorted.emplace(event.timestamp(), line);
181    }
182  });
183
184  *output << kTraceHeader;
185  *output << kFtraceHeader;
186
187  fprintf(stderr, "\n");
188  size_t total_events = sorted.size();
189  size_t written_events = 0;
190  for (auto it = sorted.begin(); it != sorted.end(); it++) {
191    *output << it->second;
192    if (written_events++ % 100 == 0) {
193      fprintf(stderr, "Writing trace: %.2f %%\r",
194              written_events * 100.0 / total_events);
195      fflush(stderr);
196    }
197  }
198
199  *output << kTraceFooter;
200
201  return 0;
202}
203
204int TraceToText(std::istream* input, std::ostream* output) {
205  DiskSourceTree dst;
206  dst.MapPath("perfetto", "protos/perfetto");
207  MFE mfe;
208  Importer importer(&dst, &mfe);
209  const FileDescriptor* parsed_file =
210      importer.Import("perfetto/trace/trace.proto");
211
212  DynamicMessageFactory dmf;
213  const Descriptor* trace_descriptor = parsed_file->message_type(0);
214  const Message* msg_root = dmf.GetPrototype(trace_descriptor);
215  Message* msg = msg_root->New();
216
217  if (!msg->ParseFromIstream(input)) {
218    PERFETTO_ELOG("Could not parse input.");
219    return 1;
220  }
221  OstreamOutputStream zero_copy_output(output);
222  TextFormat::Print(*msg, &zero_copy_output);
223  return 0;
224}
225
226void PrintFtraceTrack(std::ostream* output,
227                      const uint64_t& start,
228                      const uint64_t& end,
229                      const std::multiset<uint64_t>& ftrace_timestamps) {
230  constexpr char kFtraceTrackName[] = "ftrace ";
231  size_t width = GetWidth();
232  size_t bucket_count = width - strlen(kFtraceTrackName);
233  size_t bucket_size = (end - start) / bucket_count;
234  size_t max = 0;
235  std::vector<size_t> buckets(bucket_count);
236  for (size_t i = 0; i < bucket_count; i++) {
237    auto low = ftrace_timestamps.lower_bound(i * bucket_size + start);
238    auto high = ftrace_timestamps.upper_bound((i + 1) * bucket_size + start);
239    buckets[i] = std::distance(low, high);
240    max = std::max(max, buckets[i]);
241  }
242
243  std::vector<std::string> out =
244      std::vector<std::string>({" ", "▁", "▂", "▃", "▄", "▅", "▆", "▇"});
245  *output << "-------------------- " << kFtraceTrackName
246          << "--------------------\n";
247  char line[2048];
248  for (size_t i = 0; i < bucket_count; i++) {
249    sprintf(
250        line, "%s",
251        out[std::min(buckets[i] / (max / out.size()), out.size() - 1)].c_str());
252    *output << std::string(line);
253  }
254  *output << "\n\n";
255}
256
257void PrintInodeStats(std::ostream* output,
258                     const std::set<uint64_t>& ftrace_inodes,
259                     const uint64_t& ftrace_inode_count,
260                     const std::set<uint64_t>& resolved_map_inodes,
261                     const std::set<uint64_t>& resolved_scan_inodes) {
262  *output << "--------------------Inode Stats-------------------\n";
263  char line[2048];
264
265  sprintf(line, "Events with inodes: %" PRIu64 "\n", ftrace_inode_count);
266  *output << std::string(line);
267
268  sprintf(line, "Unique inodes from events: %zu\n", ftrace_inodes.size());
269  *output << std::string(line);
270
271  sprintf(line, "Resolved inodes from static map: %zu\n",
272          resolved_map_inodes.size());
273  *output << std::string(line);
274
275  sprintf(line, "Resolved inodes from scan and cache: %zu\n",
276          resolved_scan_inodes.size());
277  *output << std::string(line);
278
279  std::set<uint64_t> resolved_inodes;
280  set_union(resolved_map_inodes.begin(), resolved_map_inodes.end(),
281            resolved_scan_inodes.begin(), resolved_scan_inodes.end(),
282            std::inserter(resolved_inodes, resolved_inodes.begin()));
283
284  sprintf(line, "Total resolved inodes: %zu\n", resolved_inodes.size());
285  *output << std::string(line);
286
287  std::set<uint64_t> intersect;
288  set_intersection(resolved_inodes.begin(), resolved_inodes.end(),
289                   ftrace_inodes.begin(), ftrace_inodes.end(),
290                   std::inserter(intersect, intersect.begin()));
291
292  sprintf(line, "Unresolved inodes: %" PRIu64 "\n",
293          ftrace_inodes.size() - intersect.size());
294
295  sprintf(line, "Unexpected inodes from filesystem: %" PRIu64 "\n",
296          resolved_inodes.size() - intersect.size());
297  *output << std::string(line);
298
299  *output << "\n";
300}
301
302void PrintProcessStats(std::ostream* output,
303                       const std::set<pid_t>& tids_in_tree,
304                       const std::set<pid_t>& tids_in_events) {
305  *output << "----------------Process Tree Stats----------------\n";
306
307  char tid[2048];
308  sprintf(tid, "Unique thread ids in process tree: %zu\n", tids_in_tree.size());
309  *output << std::string(tid);
310
311  char tid_event[2048];
312  sprintf(tid_event, "Unique thread ids in ftrace events: %zu\n",
313          tids_in_events.size());
314  *output << std::string(tid_event);
315
316  std::set<pid_t> intersect;
317  set_intersection(tids_in_tree.begin(), tids_in_tree.end(),
318                   tids_in_events.begin(), tids_in_events.end(),
319                   std::inserter(intersect, intersect.begin()));
320
321  char matching[2048];
322  sprintf(matching, "Thread ids with process info: %zu/%zu -> %zu %%\n\n",
323          intersect.size(), tids_in_events.size(),
324          (intersect.size() * 100) / tids_in_events.size());
325  *output << std::string(matching);
326  *output << "\n";
327}
328
329int TraceToSummary(std::istream* input, std::ostream* output) {
330  uint64_t start = std::numeric_limits<uint64_t>::max();
331  uint64_t end = 0;
332  std::multiset<uint64_t> ftrace_timestamps;
333  std::set<pid_t> tids_in_tree;
334  std::set<pid_t> tids_in_events;
335  std::set<uint64_t> ftrace_inodes;
336  uint64_t ftrace_inode_count = 0;
337  std::set<uint64_t> resolved_map_inodes;
338  std::set<uint64_t> resolved_scan_inodes;
339
340  ForEachPacketInTrace(
341      input, [&start, &end, &ftrace_timestamps, &tids_in_tree, &tids_in_events,
342              &ftrace_inodes, &ftrace_inode_count, &resolved_map_inodes,
343              &resolved_scan_inodes](const protos::TracePacket& packet) {
344
345        if (packet.has_process_tree()) {
346          const ProcessTree& tree = packet.process_tree();
347          for (Process process : tree.processes()) {
348            for (ProcessTree::Thread thread : process.threads()) {
349              tids_in_tree.insert(thread.tid());
350            }
351          }
352        }
353
354        if (packet.has_inode_file_map()) {
355          const InodeFileMap& inode_file_map = packet.inode_file_map();
356          const auto& mount_points = inode_file_map.mount_points();
357          bool from_scan = std::find(mount_points.begin(), mount_points.end(),
358                                     "/data") != mount_points.end();
359          for (const auto& entry : inode_file_map.entries())
360            if (from_scan)
361              resolved_scan_inodes.insert(entry.inode_number());
362            else
363              resolved_map_inodes.insert(entry.inode_number());
364        }
365
366        if (!packet.has_ftrace_events())
367          return;
368
369        const FtraceEventBundle& bundle = packet.ftrace_events();
370        uint64_t inode_number = 0;
371        for (const FtraceEvent& event : bundle.event()) {
372          if (ParseInode(event, &inode_number)) {
373            ftrace_inodes.insert(inode_number);
374            ftrace_inode_count++;
375          }
376          if (event.pid()) {
377            tids_in_events.insert(event.pid());
378          }
379          if (event.timestamp()) {
380            start = std::min<uint64_t>(start, event.timestamp());
381            end = std::max<uint64_t>(end, event.timestamp());
382            ftrace_timestamps.insert(event.timestamp());
383          }
384        }
385      });
386
387  fprintf(stderr, "\n");
388
389  char line[2048];
390  sprintf(line, "Duration: %" PRIu64 "ms\n", (end - start) / (1000 * 1000));
391  *output << std::string(line);
392
393  PrintFtraceTrack(output, start, end, ftrace_timestamps);
394  PrintProcessStats(output, tids_in_tree, tids_in_events);
395  PrintInodeStats(output, ftrace_inodes, ftrace_inode_count,
396                  resolved_map_inodes, resolved_scan_inodes);
397
398  return 0;
399}
400
401}  // namespace
402}  // namespace perfetto
403
404namespace {
405
406int Usage(int argc, char** argv) {
407  printf("Usage: %s [systrace|text|summary] < trace.proto > trace.txt\n",
408         argv[0]);
409  return 1;
410}
411
412}  // namespace
413
414int main(int argc, char** argv) {
415  if (argc != 2)
416    return Usage(argc, argv);
417
418  std::string format(argv[1]);
419
420  bool is_systrace = format == "systrace";
421  bool is_text = format == "text";
422  bool is_summary = format == "summary";
423
424  if (is_systrace)
425    return perfetto::TraceToSystrace(&std::cin, &std::cout);
426  if (is_text)
427    return perfetto::TraceToText(&std::cin, &std::cout);
428  if (is_summary)
429    return perfetto::TraceToSummary(&std::cin, &std::cout);
430  return Usage(argc, argv);
431}
432