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 "tools/trace_to_text/trace_to_systrace.h"
18
19 #include <inttypes.h>
20 #include <stdio.h>
21
22 #include <algorithm>
23 #include <functional>
24 #include <map>
25 #include <memory>
26 #include <utility>
27
28 #include "perfetto/base/build_config.h"
29 #include "perfetto/base/logging.h"
30 #include "perfetto/ext/base/string_writer.h"
31 #include "perfetto/ext/base/utils.h"
32 #include "perfetto/trace_processor/trace_processor.h"
33 #include "tools/trace_to_text/utils.h"
34
35 #define FILTER_RAW_EVENTS \
36 " where not (name like \"chrome_event.%\" or name like \"track_event.%\")"
37
38 namespace perfetto {
39 namespace trace_to_text {
40
41 namespace {
42
43 const char kProcessDumpHeader[] =
44 "\"androidProcessDump\": "
45 "\"PROCESS DUMP\\nUSER PID PPID VSZ RSS WCHAN "
46 "PC S NAME COMM \\n";
47
48 const char kThreadHeader[] = "USER PID TID CMD \\n";
49
50 const char kSystemTraceEvents[] =
51 " \"systemTraceEvents\": \"";
52
53 const char kFtraceHeader[] =
54 "# tracer: nop\n"
55 "#\n"
56 "# entries-in-buffer/entries-written: 30624/30624 #P:4\n"
57 "#\n"
58 "# _-----=> irqs-off\n"
59 "# / _----=> need-resched\n"
60 "# | / _---=> hardirq/softirq\n"
61 "# || / _--=> preempt-depth\n"
62 "# ||| / delay\n"
63 "# TASK-PID TGID CPU# |||| TIMESTAMP FUNCTION\n"
64 "# | | | | |||| | |\n";
65
66 const char kFtraceJsonHeader[] =
67 "# tracer: nop\\n"
68 "#\\n"
69 "# entries-in-buffer/entries-written: 30624/30624 #P:4\\n"
70 "#\\n"
71 "# _-----=> irqs-off\\n"
72 "# / _----=> need-resched\\n"
73 "# | / _---=> hardirq/softirq\\n"
74 "# || / _--=> preempt-depth\\n"
75 "# ||| / delay\\n"
76 "# TASK-PID TGID CPU# |||| TIMESTAMP FUNCTION\\n"
77 "# | | | | |||| | |\\n";
78
79 // The legacy trace viewer requires a clock sync marker to tie ftrace and
80 // userspace clocks together. Trace processor already aligned these clocks, so
81 // we just emit a clock sync for an equality mapping.
82 const char kSystemTraceEventsFooter[] =
83 "\\n<...>-12345 (-----) [000] ...1 0.000000: tracing_mark_write: "
84 "trace_event_clock_sync: parent_ts=0\\n\"";
85
FormatProcess(uint32_t pid,uint32_t ppid,const base::StringView & name,base::StringWriter * writer)86 inline void FormatProcess(uint32_t pid,
87 uint32_t ppid,
88 const base::StringView& name,
89 base::StringWriter* writer) {
90 writer->AppendLiteral("root ");
91 writer->AppendInt(pid);
92 writer->AppendLiteral(" ");
93 writer->AppendInt(ppid);
94 writer->AppendLiteral(" 00000 000 null 0000000000 S ");
95 writer->AppendString(name);
96 writer->AppendLiteral(" null");
97 }
98
FormatThread(uint32_t tid,uint32_t tgid,const base::StringView & name,base::StringWriter * writer)99 inline void FormatThread(uint32_t tid,
100 uint32_t tgid,
101 const base::StringView& name,
102 base::StringWriter* writer) {
103 writer->AppendLiteral("root ");
104 writer->AppendInt(tgid);
105 writer->AppendChar(' ');
106 writer->AppendInt(tid);
107 writer->AppendChar(' ');
108 if (name.empty()) {
109 writer->AppendLiteral("<...>");
110 } else {
111 writer->AppendString(name);
112 }
113 }
114
115 class QueryWriter {
116 public:
QueryWriter(trace_processor::TraceProcessor * tp,TraceWriter * trace_writer)117 QueryWriter(trace_processor::TraceProcessor* tp, TraceWriter* trace_writer)
118 : tp_(tp),
119 buffer_(base::PagedMemory::Allocate(kBufferSize)),
120 global_writer_(static_cast<char*>(buffer_.Get()), kBufferSize),
121 trace_writer_(trace_writer) {}
122
123 template <typename Callback>
RunQuery(const std::string & sql,Callback callback)124 bool RunQuery(const std::string& sql, Callback callback) {
125 char buffer[2048];
126 auto iterator = tp_->ExecuteQuery(sql);
127 for (uint32_t rows = 0; iterator.Next(); rows++) {
128 base::StringWriter line_writer(buffer, base::ArraySize(buffer));
129 callback(&iterator, &line_writer);
130
131 if (global_writer_.pos() + line_writer.pos() >= global_writer_.size()) {
132 fprintf(stderr, "Writing row %" PRIu32 "%c", rows, kProgressChar);
133 auto str = global_writer_.GetStringView();
134 trace_writer_->Write(str.data(), str.size());
135 global_writer_.reset();
136 }
137 global_writer_.AppendStringView(line_writer.GetStringView());
138 }
139
140 // Check if we have an error in the iterator and print if so.
141 auto status = iterator.Status();
142 if (!status.ok()) {
143 PERFETTO_ELOG("Error while writing systrace %s", status.c_message());
144 return false;
145 }
146
147 // Flush any dangling pieces in the global writer.
148 auto str = global_writer_.GetStringView();
149 trace_writer_->Write(str.data(), str.size());
150 global_writer_.reset();
151 return true;
152 }
153
154 private:
155 static constexpr uint32_t kBufferSize = 1024u * 1024u * 16u;
156
157 trace_processor::TraceProcessor* tp_ = nullptr;
158 base::PagedMemory buffer_;
159 base::StringWriter global_writer_;
160 TraceWriter* trace_writer_;
161 };
162
163 } // namespace
164
TraceToSystrace(std::istream * input,std::ostream * output,bool ctrace,Keep truncate_keep,bool full_sort)165 int TraceToSystrace(std::istream* input,
166 std::ostream* output,
167 bool ctrace,
168 Keep truncate_keep,
169 bool full_sort) {
170 std::unique_ptr<TraceWriter> trace_writer(
171 ctrace ? new DeflateTraceWriter(output) : new TraceWriter(output));
172
173 trace_processor::Config config;
174 config.sorting_mode = full_sort
175 ? trace_processor::SortingMode::kForceFullSort
176 : trace_processor::SortingMode::kDefaultHeuristics;
177 std::unique_ptr<trace_processor::TraceProcessor> tp =
178 trace_processor::TraceProcessor::CreateInstance(config);
179
180 if (!ReadTrace(tp.get(), input))
181 return 1;
182 tp->NotifyEndOfFile();
183
184 if (ctrace)
185 *output << "TRACE:\n";
186
187 return ExtractSystrace(tp.get(), trace_writer.get(),
188 /*wrapped_in_json=*/false, truncate_keep);
189 }
190
ExtractSystrace(trace_processor::TraceProcessor * tp,TraceWriter * trace_writer,bool wrapped_in_json,Keep truncate_keep)191 int ExtractSystrace(trace_processor::TraceProcessor* tp,
192 TraceWriter* trace_writer,
193 bool wrapped_in_json,
194 Keep truncate_keep) {
195 using trace_processor::Iterator;
196
197 QueryWriter q_writer(tp, trace_writer);
198 if (wrapped_in_json) {
199 trace_writer->Write(kProcessDumpHeader);
200
201 // Write out all the processes in the trace.
202 // TODO(lalitm): change this query to actually use ppid when it is exposed
203 // by the process table.
204 static const char kPSql[] = "select pid, 0 as ppid, name from process";
205 auto p_callback = [](Iterator* it, base::StringWriter* writer) {
206 uint32_t pid = static_cast<uint32_t>(it->Get(0 /* col */).long_value);
207 uint32_t ppid = static_cast<uint32_t>(it->Get(1 /* col */).long_value);
208 const auto& name_col = it->Get(2 /* col */);
209 auto name_view = name_col.type == trace_processor::SqlValue::kString
210 ? base::StringView(name_col.string_value)
211 : base::StringView();
212 FormatProcess(pid, ppid, name_view, writer);
213 };
214 if (!q_writer.RunQuery(kPSql, p_callback))
215 return 1;
216
217 trace_writer->Write(kThreadHeader);
218
219 // Write out all the threads in the trace.
220 static const char kTSql[] =
221 "select tid, COALESCE(upid, 0), thread.name "
222 "from thread left join process using (upid)";
223 auto t_callback = [](Iterator* it, base::StringWriter* writer) {
224 uint32_t tid = static_cast<uint32_t>(it->Get(0 /* col */).long_value);
225 uint32_t tgid = static_cast<uint32_t>(it->Get(1 /* col */).long_value);
226 const auto& name_col = it->Get(2 /* col */);
227 auto name_view = name_col.type == trace_processor::SqlValue::kString
228 ? base::StringView(name_col.string_value)
229 : base::StringView();
230 FormatThread(tid, tgid, name_view, writer);
231 };
232 if (!q_writer.RunQuery(kTSql, t_callback))
233 return 1;
234
235 trace_writer->Write("\",\n");
236 trace_writer->Write(kSystemTraceEvents);
237 trace_writer->Write(kFtraceJsonHeader);
238 } else {
239 trace_writer->Write(kFtraceHeader);
240 }
241
242 fprintf(stderr, "Converting ftrace events%c", kProgressChar);
243 fflush(stderr);
244
245 static const char kEstimateSql[] =
246 "select count(1) from raw" FILTER_RAW_EVENTS;
247 uint32_t raw_events = 0;
248 auto e_callback = [&raw_events](Iterator* it, base::StringWriter*) {
249 raw_events = static_cast<uint32_t>(it->Get(0).long_value);
250 };
251 if (!q_writer.RunQuery(kEstimateSql, e_callback))
252 return 1;
253
254 auto raw_callback = [wrapped_in_json](Iterator* it,
255 base::StringWriter* writer) {
256 const char* line = it->Get(0 /* col */).string_value;
257 if (wrapped_in_json) {
258 for (uint32_t i = 0; line[i] != '\0'; i++) {
259 char c = line[i];
260 switch (c) {
261 case '\n':
262 writer->AppendLiteral("\\n");
263 break;
264 case '\f':
265 writer->AppendLiteral("\\f");
266 break;
267 case '\b':
268 writer->AppendLiteral("\\b");
269 break;
270 case '\r':
271 writer->AppendLiteral("\\r");
272 break;
273 case '\t':
274 writer->AppendLiteral("\\t");
275 break;
276 case '\\':
277 writer->AppendLiteral("\\\\");
278 break;
279 case '"':
280 writer->AppendLiteral("\\\"");
281 break;
282 default:
283 writer->AppendChar(c);
284 break;
285 }
286 }
287 writer->AppendChar('\\');
288 writer->AppendChar('n');
289 } else {
290 writer->AppendString(line);
291 writer->AppendChar('\n');
292 }
293 };
294
295 // An estimate of 130b per ftrace event, allowing some space for the processes
296 // and threads.
297 const uint32_t max_ftrace_events = (140 * 1024 * 1024) / 130;
298
299 static const char kRawEventsQuery[] =
300 "select to_ftrace(id) from raw" FILTER_RAW_EVENTS;
301
302 if (truncate_keep == Keep::kEnd && raw_events > max_ftrace_events) {
303 char end_truncate[150];
304 sprintf(end_truncate, "%s limit %d offset %d", kRawEventsQuery,
305 max_ftrace_events, raw_events - max_ftrace_events);
306 if (!q_writer.RunQuery(end_truncate, raw_callback))
307 return 1;
308 } else if (truncate_keep == Keep::kStart) {
309 char start_truncate[150];
310 sprintf(start_truncate, "%s limit %d", kRawEventsQuery, max_ftrace_events);
311 if (!q_writer.RunQuery(start_truncate, raw_callback))
312 return 1;
313 } else {
314 if (!q_writer.RunQuery(kRawEventsQuery, raw_callback))
315 return 1;
316 }
317
318 if (wrapped_in_json)
319 trace_writer->Write(kSystemTraceEventsFooter);
320
321 return 0;
322 }
323
324 } // namespace trace_to_text
325 } // namespace perfetto
326