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
42   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:
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 
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 
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 
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 
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 
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 
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 
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 
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 
416 void RegisterTraceSchedCommand() {
417   RegisterCommand("trace-sched", [] { return std::unique_ptr<Command>(new TraceSchedCommand()); });
418 }
419