/* * Copyright (C) 2018 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include #include #include #include #include #include #include #include #include "command.h" #include "event_selection_set.h" #include "record.h" #include "record_file.h" #include "SampleDisplayer.h" #include "tracing.h" #include "utils.h" using android::base::StringPrintf; using namespace simpleperf; namespace { struct SampleInfo { uint64_t timestamp; // the time when the kernel generates the sample uint64_t runtime_in_ns; // the runtime of the thread in the sample SampleInfo(uint64_t timestamp = 0, uint64_t runtime_in_ns = 0) : timestamp(timestamp), runtime_in_ns(runtime_in_ns) {} }; struct SpinInfo { uint64_t spinloop_count = 0; double max_rate = 0; uint64_t max_rate_start_timestamp = 0; uint64_t max_rate_end_timestamp = 0; std::queue samples_in_check_period; uint64_t runtime_in_check_period = 0; }; struct ThreadInfo { pid_t process_id = 0; pid_t thread_id = 0; std::string name; uint64_t total_runtime_in_ns = 0; SpinInfo spin_info; }; struct ProcessInfo { pid_t process_id = 0; std::string name; uint64_t total_runtime_in_ns = 0; std::vector threads; }; class TraceSchedCommand : public Command { public: TraceSchedCommand() : Command("trace-sched", "Trace system-wide process runtime events.", // clang-format off "Records system-wide sched:sched_stat_runtime events, reports runtime taken\n" "by each process during recording, and optionally warns about processes which\n" "may have spinloops.\n" "Usage: simpleperf trace-sched [options]\n" "--duration time_in_sec Monitor for time_in_sec seconds. Here time_in_sec may\n" " be any positive floating point number. Default is 10.\n" "--check-spinloop check_period_in_sec\n" " Give warning for threads which may be spinning. A thread is\n" " thought of spinning on the CPU, when it takes more than\n" " [spin-rate] * [check_period] cpu time in any [check_period].\n" " [spin-rate] can be set by --spin-rate. Default check_period is 1 sec.\n" "--spin-rate spin-rate Default is 0.8. Vaild range is (0, 1].\n" "--show-threads Show runtime of each thread.\n" "--record-file file_path Read records from file_path.\n" // clang-format on ), duration_in_sec_(10.0), spinloop_check_period_in_sec_(1.0), spinloop_check_rate_(0.8), show_threads_(false) { } bool Run(const std::vector& args); private: bool ParseOptions(const std::vector& args); bool RecordSchedEvents(const std::string& record_file_path); bool ParseSchedEvents(const std::string& record_file_path); void ProcessRecord(Record& record); void ProcessSampleRecord(const SampleRecord& record); std::vector BuildProcessInfo(); void ReportProcessInfo(const std::vector& processes); double duration_in_sec_; double spinloop_check_period_in_sec_; double spinloop_check_rate_; bool show_threads_; std::string record_file_; StringTracingFieldPlace tracing_field_comm_; TracingFieldPlace tracing_field_runtime_; std::unordered_map thread_map_; }; bool TraceSchedCommand::Run(const std::vector& args) { if (!ParseOptions(args)) { return false; } TemporaryFile tmp_file; if (record_file_.empty()) { if (!RecordSchedEvents(tmp_file.path)) { return false; } record_file_ = tmp_file.path; } if (!ParseSchedEvents(record_file_)) { return false; } std::vector processes = BuildProcessInfo(); ReportProcessInfo(processes); return true; } bool TraceSchedCommand::ParseOptions(const std::vector& args) { size_t i; for (i = 0; i < args.size(); ++i) { if (args[i] == "--duration") { if (!GetDoubleOption(args, &i, &duration_in_sec_, 1e-9)) { return false; } } else if (args[i] == "--check-spinloop") { if (!GetDoubleOption(args, &i, &spinloop_check_period_in_sec_, 1e-9)) { return false; } } else if (args[i] == "--spin-rate") { if (!GetDoubleOption(args, &i, &spinloop_check_rate_, 1e-9, 1.0)) { return false; } } else if (args[i] == "--show-threads") { show_threads_ = true; } else if (args[i] == "--record-file") { if (!NextArgumentOrError(args, &i)) { return false; } record_file_ = args[i]; } else { ReportUnknownOption(args, i); return false; } } return true; } bool TraceSchedCommand::RecordSchedEvents(const std::string& record_file_path) { if (!IsRoot()) { LOG(ERROR) << "Need root privilege to trace system wide events.\n"; return false; } std::unique_ptr record_cmd = CreateCommandInstance("record"); CHECK(record_cmd); std::vector record_args = {"-e", "sched:sched_stat_runtime", "-a", "--duration", std::to_string(duration_in_sec_), "-o", record_file_path}; if (IsSettingClockIdSupported()) { record_args.push_back("--clockid"); record_args.push_back("monotonic"); } return record_cmd->Run(record_args); } bool TraceSchedCommand::ParseSchedEvents(const std::string& record_file_path) { std::unique_ptr reader = RecordFileReader::CreateInstance(record_file_path); if (!reader) { return false; } const EventType* event = FindEventTypeByName("sched:sched_stat_runtime"); std::vector attrs = reader->AttrSection(); if (attrs.size() != 1u || attrs[0].attr->type != event->type || attrs[0].attr->config != event->config) { LOG(ERROR) << "sched:sched_stat_runtime isn't recorded in " << record_file_path; return false; } auto callback = [this](std::unique_ptr record) { ProcessRecord(*record); return true; }; return reader->ReadDataSection(callback); } void TraceSchedCommand::ProcessRecord(Record& record) { switch (record.type()) { case PERF_RECORD_SAMPLE: { ProcessSampleRecord(*static_cast(&record)); break; } case PERF_RECORD_COMM: { const CommRecord& r = *static_cast(&record); auto& thread = thread_map_[r.data->tid]; thread.process_id = r.data->pid; thread.thread_id = r.data->tid; thread.name = r.comm; break; } case PERF_RECORD_FORK: { const ForkRecord& r = *static_cast(&record); auto& parent_thread = thread_map_[r.data->ptid]; auto& child_thread = thread_map_[r.data->tid]; parent_thread.process_id = r.data->ppid; parent_thread.thread_id = r.data->ptid; child_thread.process_id = r.data->pid; child_thread.thread_id = r.data->tid; child_thread.name = parent_thread.name; break; } case PERF_RECORD_TRACING_DATA: case SIMPLE_PERF_RECORD_TRACING_DATA: { const TracingDataRecord& r = *static_cast(&record); Tracing tracing(std::vector(r.data, r.data + r.data_size)); const EventType* event = FindEventTypeByName("sched:sched_stat_runtime"); CHECK(event != nullptr); TracingFormat format = tracing.GetTracingFormatHavingId(event->config); format.GetField("comm", tracing_field_comm_); format.GetField("runtime", tracing_field_runtime_); break; } } } void TraceSchedCommand::ProcessSampleRecord(const SampleRecord& record) { std::string thread_name = tracing_field_comm_.ReadFromData(record.raw_data.data); uint64_t runtime = tracing_field_runtime_.ReadFromData(record.raw_data.data); ThreadInfo& thread = thread_map_[record.tid_data.tid]; thread.process_id = record.tid_data.pid; thread.thread_id = record.tid_data.tid; thread.name = thread_name; thread.total_runtime_in_ns += runtime; SpinInfo& spin_info = thread.spin_info; spin_info.runtime_in_check_period += runtime; spin_info.samples_in_check_period.push(SampleInfo(record.Timestamp(), runtime)); // Check spin loop. if (thread.spin_info.samples_in_check_period.size() == 1u) { return; } uint64_t start_timestamp = spin_info.samples_in_check_period.front().timestamp; uint64_t time_period_in_ns = record.Timestamp() - start_timestamp; if (time_period_in_ns < spinloop_check_period_in_sec_ * 1e9) { return; } if (thread.spin_info.runtime_in_check_period > time_period_in_ns * spinloop_check_rate_) { // Detect a spin loop. thread.spin_info.spinloop_count++; double rate = std::min(1.0, static_cast(thread.spin_info.runtime_in_check_period) / time_period_in_ns); if (rate > thread.spin_info.max_rate) { thread.spin_info.max_rate = rate; thread.spin_info.max_rate_start_timestamp = start_timestamp; thread.spin_info.max_rate_end_timestamp = record.Timestamp(); // Clear samples to avoid overlapped spin loop periods. std::queue empty_q; std::swap(thread.spin_info.samples_in_check_period, empty_q); thread.spin_info.runtime_in_check_period = 0; } else { thread.spin_info.runtime_in_check_period -= spin_info.samples_in_check_period.front().runtime_in_ns; thread.spin_info.samples_in_check_period.pop(); } } } std::vector TraceSchedCommand::BuildProcessInfo() { std::unordered_map process_map; for (auto& pair : thread_map_) { const ThreadInfo& thread = pair.second; // No need to report simpleperf. if (thread.name == "simpleperf") { continue; } ProcessInfo& process = process_map[thread.process_id]; process.process_id = thread.process_id; if (thread.process_id == thread.thread_id) { process.name = thread.name; } process.total_runtime_in_ns += thread.total_runtime_in_ns; process.threads.push_back(&thread); } std::vector processes; for (auto& pair : process_map) { processes.push_back(pair.second); } auto sort_process = [](const ProcessInfo& p1, const ProcessInfo& p2) { return p1.total_runtime_in_ns > p2.total_runtime_in_ns; }; auto sort_thread = [](const ThreadInfo* t1, const ThreadInfo* t2) { return t1->total_runtime_in_ns > t2->total_runtime_in_ns; }; std::sort(processes.begin(), processes.end(), sort_process); for (auto& process : processes) { std::sort(process.threads.begin(), process.threads.end(), sort_thread); } return processes; } void TraceSchedCommand::ReportProcessInfo(const std::vector& processes) { uint64_t total_runtime_in_ns = 0u; for (auto& process : processes) { total_runtime_in_ns += process.total_runtime_in_ns; } printf("Total Runtime: %.3f ms\n", total_runtime_in_ns / 1e6); struct ReportEntry { bool is_process = false; uint64_t runtime_in_ns = 0; double percentage = 0; pid_t pid = 0; std::string name; }; std::vector entries; for (auto& process : processes) { ReportEntry entry; entry.is_process = true; entry.runtime_in_ns = process.total_runtime_in_ns; entry.pid = process.process_id; entry.name = process.name; entry.percentage = 0.0; if (total_runtime_in_ns != 0u) { entry.percentage = 100.0 * process.total_runtime_in_ns / total_runtime_in_ns; } // Omit processes taken too small percentage. if (entry.percentage < 0.01) { continue; } entries.push_back(entry); if (show_threads_) { for (auto& thread : process.threads) { ReportEntry entry; entry.is_process = false; entry.runtime_in_ns = thread->total_runtime_in_ns; entry.pid = thread->thread_id; entry.name = thread->name; entry.percentage = 0.0; if (total_runtime_in_ns != 0u) { entry.percentage = 100.0 * thread->total_runtime_in_ns / total_runtime_in_ns; } // Omit threads taken too small percentage. if (entry.percentage < 0.01) { continue; } entries.push_back(entry); } } } SampleDisplayer displayer; if (show_threads_) { displayer.AddDisplayFunction("Type", [](const ReportEntry* entry) -> std::string { return entry->is_process ? "Process" : "Thread"; }); } displayer.AddDisplayFunction("Runtime", [](const ReportEntry* entry) { return StringPrintf("%.3f ms", entry->runtime_in_ns / 1e6); }); displayer.AddDisplayFunction("Percentage", [](const ReportEntry* entry) { return StringPrintf("%.2f%%", entry->percentage); }); displayer.AddDisplayFunction("Pid", [](const ReportEntry* entry) { return StringPrintf("%d", entry->pid); }); displayer.AddDisplayFunction("Name", [](const ReportEntry* entry) { return entry->name; }); for (auto& entry : entries) { displayer.AdjustWidth(&entry); } displayer.PrintNames(stdout); for (auto& entry : entries) { displayer.PrintSample(stdout, &entry); } for (auto& process : processes) { for (auto& thread : process.threads) { if (thread->spin_info.spinloop_count != 0u) { double percentage = 100.0 * thread->spin_info.max_rate; double duration_in_ns = thread->spin_info.max_rate_end_timestamp - thread->spin_info.max_rate_start_timestamp; double running_time_in_ns = duration_in_ns * thread->spin_info.max_rate; printf("Detect %" PRIu64 " spin loops in process %s (%d) thread %s (%d),\n" "max rate at [%.6f s - %.6f s], taken %.3f ms / %.3f ms (%.2f%%).\n", thread->spin_info.spinloop_count, process.name.c_str(), process.process_id, thread->name.c_str(), thread->thread_id, thread->spin_info.max_rate_start_timestamp / 1e9, thread->spin_info.max_rate_end_timestamp / 1e9, running_time_in_ns / 1e6, duration_in_ns / 1e6, percentage); } } } } } // namespace namespace simpleperf { void RegisterTraceSchedCommand() { RegisterCommand("trace-sched", [] { return std::unique_ptr(new TraceSchedCommand()); }); } } // namespace simpleperf