simpleperf/cmd_debug_unwind.cpp

   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 <algorithm>
  18 #include <memory>
  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/parseint.h>
  26 #include <android-base/stringprintf.h>
  27 #include <android-base/strings.h>
  28
  29 #include "CallChainJoiner.h"
  30 #include "command.h"
  31 #include "environment.h"
  32 #include "OfflineUnwinder.h"
  33 #include "perf_regs.h"
  34 #include "record_file.h"
  35 #include "thread_tree.h"
  36 #include "utils.h"
  37 #include "workload.h"
  38
  39 using namespace simpleperf;
  40
  41 // Cache size used by CallChainJoiner to cache call chains in memory.
  42 constexpr size_t DEFAULT_CALL_CHAIN_JOINER_CACHE_SIZE = 8 * 1024 * 1024;
  43
  44 struct MemStat {
  45   std::string vm_peak;
  46   std::string vm_size;
  47   std::string vm_hwm;
  48   std::string vm_rss;
  49
  50   std::string ToString() const {
  51     return android::base::StringPrintf("VmPeak:%s;VmSize:%s;VmHWM:%s;VmRSS:%s", vm_peak.c_str(),
  52                                        vm_size.c_str(), vm_hwm.c_str(), vm_rss.c_str());
  53   }
  54 };
  55
  56 static bool GetMemStat(MemStat* stat) {
  57   std::string s;
  58   if (!android::base::ReadFileToString(android::base::StringPrintf("/proc/%d/status", getpid()),
  59                                                                    &s)) {
  60     PLOG(ERROR) << "Failed to read process status";
  61     return false;
  62   }
  63   std::vector<std::string> lines = android::base::Split(s, "\n");
  64   for (auto& line : lines) {
  65     if (android::base::StartsWith(line, "VmPeak:")) {
  66       stat->vm_peak = android::base::Trim(line.substr(strlen("VmPeak:")));
  67     } else if (android::base::StartsWith(line, "VmSize:")) {
  68       stat->vm_size = android::base::Trim(line.substr(strlen("VmSize:")));
  69     } else if (android::base::StartsWith(line, "VmHWM:")) {
  70       stat->vm_hwm = android::base::Trim(line.substr(strlen("VmHWM:")));
  71     } else if (android::base::StartsWith(line, "VmRSS:")) {
  72       stat->vm_rss = android::base::Trim(line.substr(strlen("VmRSS:")));
  73     }
  74   }
  75   return true;
  76 }
  77
  78 class DebugUnwindCommand : public Command {
  79  public:
  80   DebugUnwindCommand()
  81       : Command("debug-unwind", "Debug/test offline unwinding.",
  82                 // clang-format off
  83 "Usage: simpleperf debug-unwind [options]\n"
  84 "       Given a perf.data generated with \"-g --no-unwind\", it converts\n"
  85 "       regs/stack data of samples into callchains, and write result into\n"
  86 "       a new perf.data. The new perf.data can be passed to\n"
  87 "       unwind_result_reporter.py to generate a text report.\n"
  88 "-i <file>  The path of record file generated with \"-g --no-unwind\".\n"
  89 "           Default is perf.data.\n"
  90 "-o <file>  The path ot write new perf.data. Default is perf.data.debug.\n"
  91 "--symfs <dir>  Look for files with symbols relative to this directory.\n"
  92 "--time time    Only unwind samples recorded at selected time.\n"
  93                 // clang-format on
  94                ),
  95           input_filename_("perf.data"),
  96           output_filename_("perf.data.debug"),
  97           offline_unwinder_(true),
  98           callchain_joiner_(DEFAULT_CALL_CHAIN_JOINER_CACHE_SIZE, 1, true),
  99           selected_time_(0) {
 100   }
 101
 102   bool Run(const std::vector<std::string>& args);
 103
 104  private:
 105   bool ParseOptions(const std::vector<std::string>& args);
 106   bool UnwindRecordFile();
 107   bool ProcessRecord(Record* record);
 108   void CollectHitFileInfo(const SampleRecord& r, const std::vector<uint64_t>& ips);
 109   bool JoinCallChains();
 110   bool WriteFeatureSections();
 111   void PrintStat();
 112
 113   struct Stat {
 114     // For testing unwinding performance.
 115     uint64_t unwinding_sample_count = 0u;
 116     uint64_t total_unwinding_time_in_ns = 0u;
 117     uint64_t max_unwinding_time_in_ns = 0u;
 118
 119     // For memory consumption.
 120     MemStat mem_before_unwinding;
 121     MemStat mem_after_unwinding;
 122   };
 123
 124   std::string input_filename_;
 125   std::string output_filename_;
 126   std::unique_ptr<RecordFileReader> reader_;
 127   std::unique_ptr<RecordFileWriter> writer_;
 128   ThreadTree thread_tree_;
 129   OfflineUnwinder offline_unwinder_;
 130   CallChainJoiner callchain_joiner_;
 131   Stat stat_;
 132   uint64_t selected_time_;
 133 };
 134
 135 bool DebugUnwindCommand::Run(const std::vector<std::string>& args) {
 136   // 1. Parse options.
 137   if (!ParseOptions(args)) {
 138     return false;
 139   }
 140
 141   // 2. Read input perf.data, and generate new perf.data.
 142   if (!UnwindRecordFile()) {
 143     return false;
 144   }
 145
 146   // 3. Show stat of unwinding.
 147   PrintStat();
 148   return true;
 149 }
 150
 151 bool DebugUnwindCommand::ParseOptions(const std::vector<std::string>& args) {
 152   for (size_t i = 0; i < args.size(); ++i) {
 153     if (args[i] == "-i") {
 154       if (!NextArgumentOrError(args, &i)) {
 155         return false;
 156       }
 157       input_filename_ = args[i];
 158     } else if (args[i] == "-o") {
 159       if (!NextArgumentOrError(args, &i)) {
 160         return false;
 161       }
 162       output_filename_ = args[i];
 163     } else if (args[i] == "--symfs") {
 164       if (!NextArgumentOrError(args, &i)) {
 165         return false;
 166       }
 167       if (!Dso::SetSymFsDir(args[i])) {
 168         return false;
 169       }
 170     } else if (args[i] == "--time") {
 171       if (!NextArgumentOrError(args, &i)) {
 172         return false;
 173       }
 174       if (!android::base::ParseUint(args[i].c_str(), &selected_time_)) {
 175         LOG(ERROR) << "Invalid option for " << args[i-1] << ": " << args[i];
 176         return false;
 177       }
 178     } else {
 179       ReportUnknownOption(args, i);
 180       return false;
 181     }
 182   }
 183   SetTempDirectoryUsedInRecording(android::base::Dirname(output_filename_));
 184   return true;
 185 }
 186
 187 bool DebugUnwindCommand::UnwindRecordFile() {
 188   // 1. Check input file.
 189   reader_ = RecordFileReader::CreateInstance(input_filename_);
 190   if (!reader_) {
 191     return false;
 192   }
 193   std::string record_cmd = android::base::Join(reader_->ReadCmdlineFeature(), " ");
 194   if (record_cmd.find("--no-unwind") == std::string::npos ||
 195       (record_cmd.find("-g") == std::string::npos &&
 196           record_cmd.find("--call-graph dwarf") == std::string::npos)) {
 197     LOG(ERROR) << input_filename_ << " isn't recorded with \"-g --no-unwind\"";
 198     return false;
 199   }
 200   ScopedCurrentArch scoped_arch(GetArchType(reader_->ReadFeatureString(PerfFileFormat::FEAT_ARCH)));
 201
 202   // 2. Copy attr section.
 203   writer_ = RecordFileWriter::CreateInstance(output_filename_);
 204   if (!writer_ || !writer_->WriteAttrSection(reader_->AttrSection())) {
 205     return false;
 206   }
 207
 208   // 3. Process records in data section.
 209   if (!GetMemStat(&stat_.mem_before_unwinding)) {
 210     return false;
 211   }
 212   auto callback = [this](std::unique_ptr<Record> record) {
 213     return ProcessRecord(record.get());
 214   };
 215   if (!reader_->ReadDataSection(callback)) {
 216     return false;
 217   }
 218   if (!JoinCallChains()) {
 219     return false;
 220   }
 221   if (!GetMemStat(&stat_.mem_after_unwinding)) {
 222     return false;
 223   }
 224
 225   // 4. Write feature sections.
 226   return WriteFeatureSections();
 227 }
 228
 229 bool DebugUnwindCommand::ProcessRecord(Record* record) {
 230   if (record->type() == PERF_RECORD_SAMPLE) {
 231     auto& r = *static_cast<SampleRecord*>(record);
 232     if (selected_time_ != 0u && r.Timestamp() != selected_time_) {
 233       return true;
 234     }
 235     r.AdjustCallChainGeneratedByKernel();
 236     r.RemoveInvalidStackData();
 237     uint64_t need_type = PERF_SAMPLE_CALLCHAIN | PERF_SAMPLE_REGS_USER | PERF_SAMPLE_STACK_USER;
 238     if ((r.sample_type & need_type) == need_type && r.regs_user_data.reg_mask != 0 &&
 239         r.GetValidStackSize() > 0) {
 240       ThreadEntry* thread = thread_tree_.FindThreadOrNew(r.tid_data.pid, r.tid_data.tid);
 241       RegSet regs(r.regs_user_data.abi, r.regs_user_data.reg_mask, r.regs_user_data.regs);
 242       std::vector<uint64_t> ips;
 243       std::vector<uint64_t> sps;
 244       if (!offline_unwinder_.UnwindCallChain(*thread, regs, r.stack_user_data.data,
 245                                              r.GetValidStackSize(), &ips, &sps)) {
 246         return false;
 247       }
 248
 249       const UnwindingResult& unwinding_result = offline_unwinder_.GetUnwindingResult();
 250       stat_.unwinding_sample_count++;
 251       stat_.total_unwinding_time_in_ns += unwinding_result.used_time;
 252       stat_.max_unwinding_time_in_ns = std::max(stat_.max_unwinding_time_in_ns,
 253                                                 unwinding_result.used_time);
 254       if (!writer_->WriteRecord(UnwindingResultRecord(r.time_data.time, unwinding_result))) {
 255         return false;
 256       }
 257       // We want to keep both reg/stack data and callchain of a sample. However, storing both
 258       // can exceed the size limit of a SampleRecord. So instead we store one sample with reg/stack
 259       // data and one sample with callchain.
 260       if (!writer_->WriteRecord(r)) {
 261         return false;
 262       }
 263       r.ReplaceRegAndStackWithCallChain(ips);
 264       if (!callchain_joiner_.AddCallChain(r.tid_data.pid, r.tid_data.tid,
 265                                           CallChainJoiner::ORIGINAL_OFFLINE, ips, sps)) {
 266         return false;
 267       }
 268       CollectHitFileInfo(r, ips);
 269     }
 270   } else {
 271     thread_tree_.Update(*record);
 272   }
 273   return writer_->WriteRecord(*record);
 274 }
 275
 276 void DebugUnwindCommand::CollectHitFileInfo(const SampleRecord& r,
 277                                             const std::vector<uint64_t>& ips) {
 278   const ThreadEntry* thread = thread_tree_.FindThreadOrNew(r.tid_data.pid, r.tid_data.tid);
 279   for (auto ip : ips) {
 280     const MapEntry* map = thread_tree_.FindMap(thread, ip, false);
 281     Dso* dso = map->dso;
 282     if (!dso->HasDumpId()) {
 283       dso->CreateDumpId();
 284     }
 285     const Symbol* symbol = thread_tree_.FindSymbol(map, ip, nullptr, &dso);
 286     if (!symbol->HasDumpId()) {
 287       dso->CreateSymbolDumpId(symbol);
 288     }
 289   }
 290 }
 291
 292 bool DebugUnwindCommand::JoinCallChains() {
 293   // 1. Prepare joined callchains.
 294   if (!callchain_joiner_.JoinCallChains()) {
 295     return false;
 296   }
 297   // 2. Move records from record_filename_ to a temporary file.
 298   if (!writer_->Close()) {
 299     return false;
 300   }
 301   writer_.reset();
 302   std::unique_ptr<TemporaryFile> tmpfile = CreateTempFileUsedInRecording();
 303   if (!Workload::RunCmd({"mv", output_filename_, tmpfile->path})) {
 304     return false;
 305   }
 306
 307   // 3. Read records from the temporary file, and write records with joined call chains back
 308   // to record_filename_.
 309   std::unique_ptr<RecordFileReader> reader = RecordFileReader::CreateInstance(tmpfile->path);
 310   if (!reader) {
 311     return false;
 312   }
 313   writer_ = RecordFileWriter::CreateInstance(output_filename_);
 314   if (!writer_ || !writer_->WriteAttrSection(reader->AttrSection())) {
 315     return false;
 316   }
 317
 318   auto record_callback = [&](std::unique_ptr<Record> r) {
 319     if (r->type() != PERF_RECORD_SAMPLE) {
 320       return writer_->WriteRecord(*r);
 321     }
 322     SampleRecord& sr = *static_cast<SampleRecord*>(r.get());
 323     if (!sr.HasUserCallChain()) {
 324       return writer_->WriteRecord(sr);
 325     }
 326     pid_t pid;
 327     pid_t tid;
 328     CallChainJoiner::ChainType type;
 329     std::vector<uint64_t> ips;
 330     std::vector<uint64_t> sps;
 331     do {
 332       if (!callchain_joiner_.GetNextCallChain(pid, tid, type, ips, sps)) {
 333         return false;
 334       }
 335       if (!writer_->WriteRecord(CallChainRecord(pid, tid, type, sr.Timestamp(), ips, sps))) {
 336         return false;
 337       }
 338     } while (type != CallChainJoiner::JOINED_OFFLINE);
 339     CHECK_EQ(pid, static_cast<pid_t>(sr.tid_data.pid));
 340     CHECK_EQ(tid, static_cast<pid_t>(sr.tid_data.tid));
 341     sr.UpdateUserCallChain(ips);
 342     return writer_->WriteRecord(sr);
 343   };
 344   return reader->ReadDataSection(record_callback, false);
 345 }
 346
 347 bool DebugUnwindCommand::WriteFeatureSections() {
 348   // Add debug_unwind info in META_INFO section, and add symbol info in FILE section.
 349   const std::map<int, PerfFileFormat::SectionDesc>& features = reader_->FeatureSectionDescriptors();
 350   size_t new_feature_count = features.size();
 351   for (int feature : {PerfFileFormat::FEAT_FILE, PerfFileFormat::FEAT_META_INFO}) {
 352     if (features.find(feature) == features.end()) {
 353       new_feature_count++;
 354     }
 355   }
 356   if (!writer_->BeginWriteFeatures(new_feature_count)) {
 357     return false;
 358   }
 359
 360   auto it = features.begin();
 361   // Copy all feature sections except FEAT_FILE and FEAT_META_INFO, which require special handling.
 362   while (it != features.end() && it->first < PerfFileFormat::FEAT_FILE) {
 363     std::vector<char> data;
 364     if (!reader_->ReadFeatureSection(it->first, &data) || !writer_->WriteFeature(it->first, data)) {
 365       return false;
 366     }
 367     ++it;
 368   }
 369   // Write a new file section.
 370   if (it != features.end() && it->first == PerfFileFormat::FEAT_FILE) {
 371     ++it;
 372   }
 373   if (!writer_->WriteFileFeatures(thread_tree_.GetAllDsos())) {
 374     return false;
 375   }
 376   // Write meta_info section.
 377   std::unordered_map<std::string, std::string> info_map;
 378   if (it != features.end() && it->first == PerfFileFormat::FEAT_META_INFO) {
 379     if (!reader_->ReadMetaInfoFeature(&info_map)) {
 380       return false;
 381     }
 382     ++it;
 383   }
 384   info_map["debug_unwind"] = "true";
 385   info_map["debug_unwind_mem_before"] = stat_.mem_before_unwinding.ToString();
 386   info_map["debug_unwind_mem_after"] = stat_.mem_after_unwinding.ToString();
 387   if (!writer_->WriteMetaInfoFeature(info_map)) {
 388     return false;
 389   }
 390   CHECK(it == features.end());
 391   return writer_->EndWriteFeatures() && writer_->Close();
 392 }
 393
 394 void DebugUnwindCommand::PrintStat() {
 395   printf("Unwinding sample count: %" PRIu64 "\n", stat_.unwinding_sample_count);
 396   if (stat_.unwinding_sample_count > 0u) {
 397     printf("Average unwinding time: %f us\n", static_cast<double>(stat_.total_unwinding_time_in_ns)
 398            / 1000 / stat_.unwinding_sample_count);
 399     printf("Max unwinding time: %f us\n", static_cast<double>(stat_.max_unwinding_time_in_ns)
 400            / 1000);
 401   }
 402   printf("Memory change:\n");
 403   PrintIndented(1, "VmPeak: %s -> %s\n", stat_.mem_before_unwinding.vm_peak.c_str(),
 404                 stat_.mem_after_unwinding.vm_peak.c_str());
 405   PrintIndented(1, "VmSize: %s -> %s\n", stat_.mem_before_unwinding.vm_size.c_str(),
 406                 stat_.mem_after_unwinding.vm_size.c_str());
 407   PrintIndented(1, "VmHWM: %s -> %s\n", stat_.mem_before_unwinding.vm_hwm.c_str(),
 408                 stat_.mem_after_unwinding.vm_hwm.c_str());
 409   PrintIndented(1, "VmRSS: %s -> %s\n", stat_.mem_before_unwinding.vm_rss.c_str(),
 410                 stat_.mem_after_unwinding.vm_rss.c_str());
 411   callchain_joiner_.DumpStat();
 412   printf("Please use debug_unwind_reporter.py to get a report in details.\n");
 413 }
 414
 415 void RegisterDebugUnwindCommand() {
 416   RegisterCommand("debug-unwind",
 417                   []{ return std::unique_ptr<Command>(new DebugUnwindCommand()); });
 418 }