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 <memory>
18 #include <queue>
19 #include <string>
20 #include <unordered_map>
21 #include <vector>
22
23 #include <android-base/file.h>
24 #include <android-base/logging.h>
25 #include <android-base/stringprintf.h>
26
27 #include "command.h"
28 #include "event_selection_set.h"
29 #include "record.h"
30 #include "record_file.h"
31 #include "SampleDisplayer.h"
32 #include "tracing.h"
33 #include "utils.h"
34
35 using android::base::StringPrintf;
36
37 namespace {
38
39 struct SampleInfo {
40 uint64_t timestamp; // the time when the kernel generates the sample
41 uint64_t runtime_in_ns; // the runtime of the thread in the sample
SampleInfo__anon966944c30111::SampleInfo42 SampleInfo(uint64_t timestamp = 0, uint64_t runtime_in_ns = 0)
43 : timestamp(timestamp), runtime_in_ns(runtime_in_ns) {}
44 };
45
46 struct SpinInfo {
47 uint64_t spinloop_count = 0;
48 double max_rate = 0;
49 uint64_t max_rate_start_timestamp = 0;
50 uint64_t max_rate_end_timestamp = 0;
51 std::queue<SampleInfo> samples_in_check_period;
52 uint64_t runtime_in_check_period = 0;
53 };
54
55 struct ThreadInfo {
56 pid_t process_id = 0;
57 pid_t thread_id = 0;
58 std::string name;
59 uint64_t total_runtime_in_ns = 0;
60 SpinInfo spin_info;
61 };
62
63 struct ProcessInfo {
64 pid_t process_id = 0;
65 std::string name;
66 uint64_t total_runtime_in_ns = 0;
67 std::vector<const ThreadInfo*> threads;
68 };
69
70 class TraceSchedCommand : public Command {
71 public:
TraceSchedCommand()72 TraceSchedCommand()
73 : Command("trace-sched", "Trace system-wide process runtime events.",
74 // clang-format off
75 "Records system-wide sched:sched_stat_runtime events, reports runtime taken\n"
76 "by each process during recording, and optionally warns about processes which\n"
77 "may have spinloops.\n"
78 "Usage: simpleperf trace-sched [options]\n"
79 "--duration time_in_sec Monitor for time_in_sec seconds. Here time_in_sec may\n"
80 " be any positive floating point number. Default is 10.\n"
81 "--check-spinloop check_period_in_sec\n"
82 " Give warning for threads which may be spinning. A thread is\n"
83 " thought of spinning on the CPU, when it takes more than\n"
84 " [spin-rate] * [check_period] cpu time in any [check_period].\n"
85 " [spin-rate] can be set by --spin-rate. Default check_period is 1 sec.\n"
86 "--spin-rate spin-rate Default is 0.8. Vaild range is (0, 1].\n"
87 "--show-threads Show runtime of each thread.\n"
88 "--record-file file_path Read records from file_path.\n"
89 // clang-format on
90 ),
91 duration_in_sec_(10.0),
92 spinloop_check_period_in_sec_(1.0),
93 spinloop_check_rate_(0.8),
94 show_threads_(false) {
95 }
96
97 bool Run(const std::vector<std::string>& args);
98
99 private:
100 bool ParseOptions(const std::vector<std::string>& args);
101 bool RecordSchedEvents(const std::string& record_file_path);
102 bool ParseSchedEvents(const std::string& record_file_path);
103 void ProcessRecord(Record& record);
104 void ProcessSampleRecord(const SampleRecord& record);
105 std::vector<ProcessInfo> BuildProcessInfo();
106 void ReportProcessInfo(const std::vector<ProcessInfo>& processes);
107
108 double duration_in_sec_;
109 double spinloop_check_period_in_sec_;
110 double spinloop_check_rate_;
111 bool show_threads_;
112 std::string record_file_;
113
114 StringTracingFieldPlace tracing_field_comm_;
115 TracingFieldPlace tracing_field_runtime_;
116 std::unordered_map<pid_t, ThreadInfo> thread_map_;
117 };
118
Run(const std::vector<std::string> & args)119 bool TraceSchedCommand::Run(const std::vector<std::string>& args) {
120 if (!ParseOptions(args)) {
121 return false;
122 }
123 TemporaryFile tmp_file;
124 if (record_file_.empty()) {
125 if (!RecordSchedEvents(tmp_file.path)) {
126 return false;
127 }
128 record_file_ = tmp_file.path;
129 }
130 if (!ParseSchedEvents(record_file_)) {
131 return false;
132 }
133 std::vector<ProcessInfo> processes = BuildProcessInfo();
134 ReportProcessInfo(processes);
135 return true;
136 }
137
ParseOptions(const std::vector<std::string> & args)138 bool TraceSchedCommand::ParseOptions(const std::vector<std::string>& args) {
139 size_t i;
140 for (i = 0; i < args.size(); ++i) {
141 if (args[i] == "--duration") {
142 if (!GetDoubleOption(args, &i, &duration_in_sec_, 1e-9)) {
143 return false;
144 }
145 } else if (args[i] == "--check-spinloop") {
146 if (!GetDoubleOption(args, &i, &spinloop_check_period_in_sec_, 1e-9)) {
147 return false;
148 }
149 } else if (args[i] == "--spin-rate") {
150 if (!GetDoubleOption(args, &i, &spinloop_check_rate_, 1e-9, 1.0)) {
151 return false;
152 }
153 } else if (args[i] == "--show-threads") {
154 show_threads_ = true;
155 } else if (args[i] == "--record-file") {
156 if (!NextArgumentOrError(args, &i)) {
157 return false;
158 }
159 record_file_ = args[i];
160 } else {
161 ReportUnknownOption(args, i);
162 return false;
163 }
164 }
165 return true;
166 }
167
RecordSchedEvents(const std::string & record_file_path)168 bool TraceSchedCommand::RecordSchedEvents(const std::string& record_file_path) {
169 if (!IsRoot()) {
170 LOG(ERROR) << "Need root privilege to trace system wide events.\n";
171 return false;
172 }
173 std::unique_ptr<Command> record_cmd = CreateCommandInstance("record");
174 CHECK(record_cmd);
175 std::vector<std::string> record_args = {"-e", "sched:sched_stat_runtime", "-a",
176 "--duration", std::to_string(duration_in_sec_),
177 "-o", record_file_path};
178 if (IsSettingClockIdSupported()) {
179 record_args.push_back("--clockid");
180 record_args.push_back("monotonic");
181 }
182 return record_cmd->Run(record_args);
183 }
184
ParseSchedEvents(const std::string & record_file_path)185 bool TraceSchedCommand::ParseSchedEvents(const std::string& record_file_path) {
186 std::unique_ptr<RecordFileReader> reader = RecordFileReader::CreateInstance(record_file_path);
187 if (!reader) {
188 return false;
189 }
190 const EventType* event = FindEventTypeByName("sched:sched_stat_runtime");
191 std::vector<EventAttrWithId> attrs = reader->AttrSection();
192 if (attrs.size() != 1u || attrs[0].attr->type != event->type ||
193 attrs[0].attr->config != event->config) {
194 LOG(ERROR) << "sched:sched_stat_runtime isn't recorded in " << record_file_path;
195 return false;
196 }
197
198 auto callback = [this](std::unique_ptr<Record> record) {
199 ProcessRecord(*record);
200 return true;
201 };
202 return reader->ReadDataSection(callback);
203 }
204
ProcessRecord(Record & record)205 void TraceSchedCommand::ProcessRecord(Record& record) {
206 switch (record.type()) {
207 case PERF_RECORD_SAMPLE: {
208 ProcessSampleRecord(*static_cast<SampleRecord*>(&record));
209 break;
210 }
211 case PERF_RECORD_COMM: {
212 const CommRecord& r = *static_cast<const CommRecord*>(&record);
213 auto& thread = thread_map_[r.data->tid];
214 thread.process_id = r.data->pid;
215 thread.thread_id = r.data->tid;
216 thread.name = r.comm;
217 break;
218 }
219 case PERF_RECORD_FORK: {
220 const ForkRecord& r = *static_cast<const ForkRecord*>(&record);
221 auto& parent_thread = thread_map_[r.data->ptid];
222 auto& child_thread = thread_map_[r.data->tid];
223 parent_thread.process_id = r.data->ppid;
224 parent_thread.thread_id = r.data->ptid;
225 child_thread.process_id = r.data->pid;
226 child_thread.thread_id = r.data->tid;
227 child_thread.name = parent_thread.name;
228 break;
229 }
230 case PERF_RECORD_TRACING_DATA:
231 case SIMPLE_PERF_RECORD_TRACING_DATA: {
232 const TracingDataRecord& r = *static_cast<const TracingDataRecord*>(&record);
233 Tracing tracing(std::vector<char>(r.data, r.data + r.data_size));
234 const EventType* event = FindEventTypeByName("sched:sched_stat_runtime");
235 CHECK(event != nullptr);
236 TracingFormat format = tracing.GetTracingFormatHavingId(event->config);
237 format.GetField("comm", tracing_field_comm_);
238 format.GetField("runtime", tracing_field_runtime_);
239 break;
240 }
241 }
242 }
243
ProcessSampleRecord(const SampleRecord & record)244 void TraceSchedCommand::ProcessSampleRecord(const SampleRecord& record) {
245 std::string thread_name = tracing_field_comm_.ReadFromData(record.raw_data.data);
246 uint64_t runtime = tracing_field_runtime_.ReadFromData(record.raw_data.data);
247 ThreadInfo& thread = thread_map_[record.tid_data.tid];
248 thread.process_id = record.tid_data.pid;
249 thread.thread_id = record.tid_data.tid;
250 thread.name = thread_name;
251 thread.total_runtime_in_ns += runtime;
252 SpinInfo& spin_info = thread.spin_info;
253 spin_info.runtime_in_check_period += runtime;
254 spin_info.samples_in_check_period.push(SampleInfo(record.Timestamp(), runtime));
255
256 // Check spin loop.
257 if (thread.spin_info.samples_in_check_period.size() == 1u) {
258 return;
259 }
260 uint64_t start_timestamp = spin_info.samples_in_check_period.front().timestamp;
261 uint64_t time_period_in_ns = record.Timestamp() - start_timestamp;
262 if (time_period_in_ns < spinloop_check_period_in_sec_ * 1e9) {
263 return;
264 }
265 if (thread.spin_info.runtime_in_check_period > time_period_in_ns * spinloop_check_rate_) {
266 // Detect a spin loop.
267 thread.spin_info.spinloop_count++;
268 double rate = std::min(1.0,
269 static_cast<double>(thread.spin_info.runtime_in_check_period) / time_period_in_ns);
270 if (rate > thread.spin_info.max_rate) {
271 thread.spin_info.max_rate = rate;
272 thread.spin_info.max_rate_start_timestamp = start_timestamp;
273 thread.spin_info.max_rate_end_timestamp = record.Timestamp();
274 // Clear samples to avoid overlapped spin loop periods.
275 std::queue<SampleInfo> empty_q;
276 std::swap(thread.spin_info.samples_in_check_period, empty_q);
277 thread.spin_info.runtime_in_check_period = 0;
278 } else {
279 thread.spin_info.runtime_in_check_period -=
280 spin_info.samples_in_check_period.front().runtime_in_ns;
281 thread.spin_info.samples_in_check_period.pop();
282 }
283 }
284 }
285
BuildProcessInfo()286 std::vector<ProcessInfo> TraceSchedCommand::BuildProcessInfo() {
287 std::unordered_map<pid_t, ProcessInfo> process_map;
288 for (auto& pair : thread_map_) {
289 const ThreadInfo& thread = pair.second;
290 // No need to report simpleperf.
291 if (thread.name == "simpleperf") {
292 continue;
293 }
294 ProcessInfo& process = process_map[thread.process_id];
295 process.process_id = thread.process_id;
296 if (thread.process_id == thread.thread_id) {
297 process.name = thread.name;
298 }
299 process.total_runtime_in_ns += thread.total_runtime_in_ns;
300 process.threads.push_back(&thread);
301 }
302 std::vector<ProcessInfo> processes;
303 for (auto& pair : process_map) {
304 processes.push_back(pair.second);
305 }
306 auto sort_process = [](const ProcessInfo& p1, const ProcessInfo& p2) {
307 return p1.total_runtime_in_ns > p2.total_runtime_in_ns;
308 };
309 auto sort_thread = [](const ThreadInfo* t1, const ThreadInfo* t2) {
310 return t1->total_runtime_in_ns > t2->total_runtime_in_ns;
311 };
312 std::sort(processes.begin(), processes.end(), sort_process);
313 for (auto& process : processes) {
314 std::sort(process.threads.begin(), process.threads.end(), sort_thread);
315 }
316 return processes;
317 }
318
ReportProcessInfo(const std::vector<ProcessInfo> & processes)319 void TraceSchedCommand::ReportProcessInfo(const std::vector<ProcessInfo>& processes) {
320 uint64_t total_runtime_in_ns = 0u;
321 for (auto& process : processes) {
322 total_runtime_in_ns += process.total_runtime_in_ns;
323 }
324 printf("Total Runtime: %.3f ms\n", total_runtime_in_ns / 1e6);
325 struct ReportEntry {
326 bool is_process = false;
327 uint64_t runtime_in_ns = 0;
328 double percentage = 0;
329 pid_t pid = 0;
330 std::string name;
331 };
332 std::vector<ReportEntry> entries;
333 for (auto& process : processes) {
334 ReportEntry entry;
335 entry.is_process = true;
336 entry.runtime_in_ns = process.total_runtime_in_ns;
337 entry.pid = process.process_id;
338 entry.name = process.name;
339 entry.percentage = 0.0;
340 if (total_runtime_in_ns != 0u) {
341 entry.percentage = 100.0 * process.total_runtime_in_ns / total_runtime_in_ns;
342 }
343 // Omit processes taken too small percentage.
344 if (entry.percentage < 0.01) {
345 continue;
346 }
347 entries.push_back(entry);
348 if (show_threads_) {
349 for (auto& thread : process.threads) {
350 ReportEntry entry;
351 entry.is_process = false;
352 entry.runtime_in_ns = thread->total_runtime_in_ns;
353 entry.pid = thread->thread_id;
354 entry.name = thread->name;
355 entry.percentage = 0.0;
356 if (total_runtime_in_ns != 0u) {
357 entry.percentage = 100.0 * thread->total_runtime_in_ns / total_runtime_in_ns;
358 }
359 // Omit threads taken too small percentage.
360 if (entry.percentage < 0.01) {
361 continue;
362 }
363 entries.push_back(entry);
364 }
365 }
366 }
367
368 SampleDisplayer<ReportEntry, uint64_t> displayer;
369 if (show_threads_) {
370 displayer.AddDisplayFunction("Type", [](const ReportEntry* entry) -> std::string {
371 return entry->is_process ? "Process" : "Thread";
372 });
373 }
374 displayer.AddDisplayFunction("Runtime", [](const ReportEntry* entry) {
375 return StringPrintf("%.3f ms", entry->runtime_in_ns / 1e6);
376 });
377 displayer.AddDisplayFunction("Percentage", [](const ReportEntry* entry) {
378 return StringPrintf("%.2f%%", entry->percentage);
379 });
380 displayer.AddDisplayFunction("Pid", [](const ReportEntry* entry) {
381 return StringPrintf("%d", entry->pid);
382 });
383 displayer.AddDisplayFunction("Name", [](const ReportEntry* entry) {
384 return entry->name;
385 });
386 for (auto& entry : entries) {
387 displayer.AdjustWidth(&entry);
388 }
389 displayer.PrintNames(stdout);
390 for (auto& entry : entries) {
391 displayer.PrintSample(stdout, &entry);
392 }
393
394 for (auto& process : processes) {
395 for (auto& thread : process.threads) {
396 if (thread->spin_info.spinloop_count != 0u) {
397 double percentage = 100.0 * thread->spin_info.max_rate;
398 double duration_in_ns = thread->spin_info.max_rate_end_timestamp -
399 thread->spin_info.max_rate_start_timestamp;
400 double running_time_in_ns = duration_in_ns * thread->spin_info.max_rate;
401 printf("Detect %" PRIu64 " spin loops in process %s (%d) thread %s (%d),\n"
402 "max rate at [%.6f s - %.6f s], taken %.3f ms / %.3f ms (%.2f%%).\n",
403 thread->spin_info.spinloop_count, process.name.c_str(), process.process_id,
404 thread->name.c_str(), thread->thread_id,
405 thread->spin_info.max_rate_start_timestamp / 1e9,
406 thread->spin_info.max_rate_end_timestamp / 1e9,
407 running_time_in_ns / 1e6, duration_in_ns / 1e6,
408 percentage);
409 }
410 }
411 }
412 }
413
414 } // namespace
415
RegisterTraceSchedCommand()416 void RegisterTraceSchedCommand() {
417 RegisterCommand("trace-sched", [] { return std::unique_ptr<Command>(new TraceSchedCommand()); });
418 }
419