Home | History | Annotate | Download | only in trace_processor 
      1 /*
      2  * Copyright (C) 2017 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 #include "VtsTraceProcessor.h"
     17 
     18 #include <dirent.h>
     19 #include <fcntl.h>
     20 #include <fstream>
     21 #include <iostream>
     22 #include <map>
     23 #include <string>
     24 #include <vector>
     25 
     26 #include <google/protobuf/io/zero_copy_stream_impl.h>
     27 #include <google/protobuf/text_format.h>
     28 #include <sys/stat.h>
     29 #include <test/vts/proto/ComponentSpecificationMessage.pb.h>
     30 #include <test/vts/proto/VtsReportMessage.pb.h>
     31 
     32 #include "VtsProfilingUtil.h"
     33 
     34 using namespace std;
     35 using google::protobuf::TextFormat;
     36 
     37 namespace android {
     38 namespace vts {
     39 
     40 bool VtsTraceProcessor::ParseBinaryTrace(const string& trace_file,
     41                                          bool ignore_timestamp, bool entry_only,
     42                                          VtsProfilingMessage* profiling_msg) {
     43   int fd =
     44       open(trace_file.c_str(), O_RDONLY, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
     45   if (fd < 0) {
     46     cerr << "Can not open trace file: " << trace_file
     47          << "error: " << std::strerror(errno);
     48     return false;
     49   }
     50   google::protobuf::io::FileInputStream input(fd);
     51   VtsProfilingRecord record;
     52   while (readOneDelimited(&record, &input)) {
     53     if (ignore_timestamp) {
     54       record.clear_timestamp();
     55     }
     56     if (entry_only) {
     57       if (isEntryEvent(record.event())) {
     58         *profiling_msg->add_records() = record;
     59       }
     60     } else {
     61       *profiling_msg->add_records() = record;
     62     }
     63     record.Clear();
     64   }
     65   input.Close();
     66   return true;
     67 }
     68 
     69 bool VtsTraceProcessor::ParseTextTrace(const string& trace_file,
     70                                        VtsProfilingMessage* profiling_msg) {
     71   ifstream in(trace_file, std::ios::in);
     72   bool new_record = true;
     73   string record_str, line;
     74 
     75   while (getline(in, line)) {
     76     // Assume records are separated by '\n'.
     77     if (line.empty()) {
     78       new_record = false;
     79     }
     80     if (new_record) {
     81       record_str += line + "\n";
     82     } else {
     83       VtsProfilingRecord record;
     84       if (!TextFormat::MergeFromString(record_str, &record)) {
     85         cerr << "Can't parse a given record: " << record_str << endl;
     86         return false;
     87       }
     88       *profiling_msg->add_records() = record;
     89       new_record = true;
     90       record_str.clear();
     91     }
     92   }
     93   in.close();
     94   return true;
     95 }
     96 
     97 void VtsTraceProcessor::ParseTrace(const string& trace_file) {
     98   VtsProfilingMessage profiling_msg;
     99   if (!ParseBinaryTrace(trace_file, false, false, &profiling_msg)) {
    100     cerr << __func__ << ": Failed to parse trace file: " << trace_file << endl;
    101     return;
    102   }
    103   for (auto record : profiling_msg.records()) {
    104     cout << record.DebugString() << endl;
    105   }
    106 }
    107 
    108 bool VtsTraceProcessor::WriteProfilingMsg(
    109     const string& output_file, const VtsProfilingMessage& profiling_msg) {
    110   int fd = open(output_file.c_str(), O_WRONLY | O_CREAT | O_EXCL,
    111                 S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
    112   if (fd < 0) {
    113     cerr << "Can not open trace file: " << output_file
    114          << "error: " << std::strerror(errno);
    115     return false;
    116   }
    117   google::protobuf::io::FileOutputStream output(fd);
    118   for (const auto& record : profiling_msg.records()) {
    119     if (!writeOneDelimited(record, &output)) {
    120       cerr << "Failed to write record";
    121     }
    122   }
    123   output.Close();
    124   return true;
    125 }
    126 
    127 void VtsTraceProcessor::ConvertTrace(const string& trace_file) {
    128   VtsProfilingMessage profiling_msg;
    129   if (!ParseTextTrace(trace_file, &profiling_msg)) {
    130     cerr << __func__ << ": Failed to parse trace file: " << trace_file << endl;
    131     return;
    132   }
    133   string tmp_file = trace_file + "_binary";
    134   if (!WriteProfilingMsg(tmp_file, profiling_msg)) {
    135     cerr << __func__ << ": Failed to write new trace file: " << tmp_file
    136          << endl;
    137     return;
    138   }
    139 }
    140 
    141 void VtsTraceProcessor::CleanupTraceFile(const string& trace_file) {
    142   VtsProfilingMessage profiling_msg;
    143   if (!ParseBinaryTrace(trace_file, false, false, &profiling_msg)) {
    144     cerr << __func__ << ": Failed to parse trace file: " << trace_file << endl;
    145     return;
    146   }
    147   VtsProfilingMessage clean_profiling_msg;
    148   bool first_record = true;
    149   enum TRACE_TYPE { server_trace, client_trace, passthrough_trace };
    150   string package;
    151   float version;
    152   TRACE_TYPE trace_type;
    153   for (const auto& record : profiling_msg.records()) {
    154     if (first_record) {
    155       package = record.package();
    156       version = record.version();
    157       // determine trace type based on the event of the first record.
    158       switch (record.event()) {
    159         case InstrumentationEventType::SERVER_API_ENTRY:
    160           trace_type = TRACE_TYPE::server_trace;
    161           break;
    162         case InstrumentationEventType::CLIENT_API_ENTRY:
    163           trace_type = TRACE_TYPE::client_trace;
    164           break;
    165         case InstrumentationEventType::PASSTHROUGH_ENTRY:
    166           trace_type = TRACE_TYPE::passthrough_trace;
    167           break;
    168         default:
    169           cerr << "Unexpected record: " << record.DebugString() << endl;
    170           return;
    171       }
    172       first_record = false;
    173     }
    174     // If trace contains records for a different hal, remove it.
    175     if (record.package() != package || record.version() != version) {
    176       cerr << "Unexpected record: " << record.DebugString() << endl;
    177       continue;
    178     }
    179     switch (trace_type) {
    180       case TRACE_TYPE::server_trace: {
    181         if (record.event() == InstrumentationEventType::SERVER_API_ENTRY ||
    182             record.event() == InstrumentationEventType::SERVER_API_EXIT) {
    183           *clean_profiling_msg.add_records() = record;
    184         }
    185         break;
    186       }
    187       case TRACE_TYPE::client_trace: {
    188         if (record.event() == InstrumentationEventType::CLIENT_API_ENTRY ||
    189             record.event() == InstrumentationEventType::CLIENT_API_EXIT) {
    190           *clean_profiling_msg.add_records() = record;
    191         }
    192         break;
    193       }
    194       case TRACE_TYPE::passthrough_trace: {
    195         if (record.event() == InstrumentationEventType::PASSTHROUGH_ENTRY ||
    196             record.event() == InstrumentationEventType::PASSTHROUGH_EXIT) {
    197           *clean_profiling_msg.add_records() = record;
    198         }
    199         break;
    200       }
    201       default:
    202         cerr << "Unknow trace type: " << trace_type << endl;
    203         return;
    204     }
    205   }
    206   string tmp_file = trace_file + "_tmp";
    207   if (!WriteProfilingMsg(tmp_file, clean_profiling_msg)) {
    208     cerr << __func__ << ": Failed to write new trace file: " << tmp_file
    209          << endl;
    210     return;
    211   }
    212   if (rename(tmp_file.c_str(), trace_file.c_str())) {
    213     cerr << __func__ << ": Failed to replace old trace file: " << trace_file
    214          << endl;
    215     return;
    216   }
    217 }
    218 
    219 void VtsTraceProcessor::CleanupTraces(const string& path) {
    220   struct stat path_stat;
    221   stat(path.c_str(), &path_stat);
    222   if (S_ISREG(path_stat.st_mode)) {
    223     CleanupTraceFile(path);
    224   } else if (S_ISDIR(path_stat.st_mode)) {
    225     DIR* dir = opendir(path.c_str());
    226     struct dirent* file;
    227     while ((file = readdir(dir)) != NULL) {
    228       if (file->d_type == DT_REG) {
    229         string trace_file = path;
    230         if (path.substr(path.size() - 1) != "/") {
    231           trace_file += "/";
    232         }
    233         trace_file += file->d_name;
    234         CleanupTraceFile(trace_file);
    235       }
    236     }
    237   }
    238 }
    239 
    240 void VtsTraceProcessor::ProcessTraceForLatencyProfiling(
    241     const string& trace_file) {
    242   VtsProfilingMessage profiling_msg;
    243   if (!ParseBinaryTrace(trace_file, false, false, &profiling_msg)) {
    244     cerr << __func__ << ": Failed to parse trace file: " << trace_file << endl;
    245     return;
    246   }
    247   if (!profiling_msg.records_size()) return;
    248   if (profiling_msg.records(0).event()
    249       == InstrumentationEventType::PASSTHROUGH_ENTRY
    250       || profiling_msg.records(0).event()
    251           == InstrumentationEventType::PASSTHROUGH_EXIT) {
    252     cout << "hidl_hal_mode:passthrough" << endl;
    253   } else {
    254     cout << "hidl_hal_mode:binder" << endl;
    255   }
    256 
    257   // stack to store all seen records.
    258   vector<VtsProfilingRecord> seen_records;
    259   // stack to store temp records that not processed.
    260   vector<VtsProfilingRecord> pending_records;
    261   for (auto record : profiling_msg.records()) {
    262     if (isEntryEvent(record.event())) {
    263       seen_records.emplace_back(record);
    264     } else {
    265       while (!seen_records.empty() &&
    266              !isPairedRecord(seen_records.back(), record)) {
    267         pending_records.emplace_back(seen_records.back());
    268         seen_records.pop_back();
    269       }
    270       if (seen_records.empty()) {
    271         cerr << "Could not found entry record for record: "
    272              << record.DebugString() << endl;
    273         continue;
    274       } else {
    275         // Found the paired entry record, calculate the latency.
    276         VtsProfilingRecord entry_record = seen_records.back();
    277         seen_records.pop_back();
    278         string api = record.func_msg().name();
    279         int64_t start_timestamp = entry_record.timestamp();
    280         int64_t end_timestamp = record.timestamp();
    281         int64_t latency = end_timestamp - start_timestamp;
    282         // sanity check.
    283         if (latency < 0) {
    284           cerr << __func__ << ": got negative latency for " << api << endl;
    285           exit(-1);
    286         }
    287         cout << api << ":" << latency << endl;
    288         while (!pending_records.empty()) {
    289           seen_records.emplace_back(pending_records.back());
    290           pending_records.pop_back();
    291         }
    292       }
    293     }
    294   }
    295 }
    296 
    297 void VtsTraceProcessor::DedupTraces(const string& trace_dir) {
    298   DIR *dir = opendir(trace_dir.c_str());
    299   if (dir == 0) {
    300     cerr << trace_dir << "does not exist." << endl;
    301     return;
    302   }
    303   vector<VtsProfilingMessage> seen_msgs;
    304   vector<string> duplicate_trace_files;
    305   struct dirent *file;
    306   long total_trace_num = 0;
    307   long duplicat_trace_num = 0;
    308   while ((file = readdir(dir)) != NULL) {
    309     if (file->d_type == DT_REG) {
    310       total_trace_num++;
    311       string trace_file = trace_dir;
    312       if (trace_dir.substr(trace_dir.size() - 1) != "/") {
    313         trace_file += "/";
    314       }
    315       trace_file += file->d_name;
    316       VtsProfilingMessage profiling_msg;
    317       if (!ParseBinaryTrace(trace_file, true, true, &profiling_msg)) {
    318         cerr << "Failed to parse trace file: " << trace_file << endl;
    319         return;
    320       }
    321       if (!profiling_msg.records_size()) {  // empty trace file
    322         duplicate_trace_files.push_back(trace_file);
    323         duplicat_trace_num++;
    324         continue;
    325       }
    326       auto found = find_if(
    327           seen_msgs.begin(), seen_msgs.end(),
    328           [&profiling_msg] (const VtsProfilingMessage& seen_msg) {
    329             std::string str_profiling_msg;
    330             std::string str_seen_msg;
    331             profiling_msg.SerializeToString(&str_profiling_msg);
    332             seen_msg.SerializeToString(&str_seen_msg);
    333             return (str_profiling_msg == str_seen_msg);
    334           });
    335       if (found == seen_msgs.end()) {
    336         seen_msgs.push_back(profiling_msg);
    337       } else {
    338         duplicate_trace_files.push_back(trace_file);
    339         duplicat_trace_num++;
    340       }
    341     }
    342   }
    343   for (const string& duplicate_trace : duplicate_trace_files) {
    344     cout << "deleting duplicate trace file: " << duplicate_trace << endl;
    345     remove(duplicate_trace.c_str());
    346   }
    347   cout << "Num of traces processed: " << total_trace_num << endl;
    348   cout << "Num of duplicate trace deleted: " << duplicat_trace_num << endl;
    349   cout << "Duplicate percentage: "
    350        << float(duplicat_trace_num) / total_trace_num << endl;
    351 }
    352 
    353 bool VtsTraceProcessor::ParseCoverageData(const string& coverage_file,
    354                                           TestReportMessage* report_msg) {
    355   ifstream in(coverage_file, std::ios::in);
    356   string msg_str((istreambuf_iterator<char>(in)), istreambuf_iterator<char>());
    357   if (!TextFormat::MergeFromString(msg_str, report_msg)) {
    358     cerr << __func__ << ": Can't parse a given record: " << msg_str << endl;
    359     return false;
    360   }
    361   return true;
    362 }
    363 
    364 void VtsTraceProcessor::UpdateCoverageData(
    365     const CoverageReportMessage& ref_msg,
    366     CoverageReportMessage* msg_to_be_updated) {
    367   if (ref_msg.file_path() == msg_to_be_updated->file_path()) {
    368     for (int line = 0; line < ref_msg.line_coverage_vector_size(); line++) {
    369       if (line < msg_to_be_updated->line_coverage_vector_size()) {
    370         if (ref_msg.line_coverage_vector(line) > 0 &&
    371             msg_to_be_updated->line_coverage_vector(line) > 0) {
    372           msg_to_be_updated->set_line_coverage_vector(line, 0);
    373           msg_to_be_updated->set_covered_line_count(
    374               msg_to_be_updated->covered_line_count() - 1);
    375         }
    376       } else {
    377         cout << "Reached the end of line_coverage_vector." << endl;
    378         break;
    379       }
    380     }
    381     // sanity check.
    382     if (msg_to_be_updated->covered_line_count() < 0) {
    383       cerr << __func__ << ": covered_line_count should not be negative."
    384            << endl;
    385       exit(-1);
    386     }
    387   }
    388 }
    389 
    390 void VtsTraceProcessor::SelectTraces(const string& coverage_file_dir,
    391                                      const string& trace_file_dir,
    392                                      TraceSelectionMetric metric) {
    393   DIR* coverage_dir = opendir(coverage_file_dir.c_str());
    394   if (coverage_dir == 0) {
    395     cerr << __func__ << ": " << coverage_file_dir << " does not exist." << endl;
    396     return;
    397   }
    398   DIR* trace_dir = opendir(trace_file_dir.c_str());
    399   if (trace_dir == 0) {
    400     cerr << __func__ << ": " << trace_file_dir << " does not exist." << endl;
    401     return;
    402   }
    403   map<string, CoverageInfo> original_coverages;
    404   map<string, CoverageInfo> selected_coverages;
    405 
    406   // Parse all the coverage files and store them into original_coverage_msgs.
    407   struct dirent* file;
    408   while ((file = readdir(coverage_dir)) != NULL) {
    409     if (file->d_type == DT_REG) {
    410       string coverage_file = coverage_file_dir;
    411       if (coverage_file_dir.substr(coverage_file_dir.size() - 1) != "/") {
    412         coverage_file += "/";
    413       }
    414       string coverage_file_base_name = file->d_name;
    415       coverage_file += coverage_file_base_name;
    416       TestReportMessage coverage_msg;
    417       if (!ParseCoverageData(coverage_file, &coverage_msg)) {
    418         cerr << "Failed to parse coverage file: " << coverage_file << endl;
    419         return;
    420       }
    421 
    422       string trace_file = trace_file_dir;
    423       if (trace_file_dir.substr(trace_file_dir.size() - 1) != "/") {
    424         trace_file += "/";
    425       }
    426       string trace_file_base_name = GetTraceFileName(coverage_file_base_name);
    427       trace_file += trace_file_base_name;
    428       ifstream in(trace_file, ifstream::binary | ifstream::ate);
    429       if (!in.good()) {
    430         cerr << "trace file: " << trace_file << " does not exists." << endl;
    431         continue;
    432       }
    433       long trace_file_size = in.tellg();
    434 
    435       CoverageInfo coverage_info;
    436       coverage_info.coverage_msg = coverage_msg;
    437       coverage_info.trace_file_name = trace_file;
    438       coverage_info.trace_file_size = trace_file_size;
    439 
    440       original_coverages[coverage_file] = coverage_info;
    441     }
    442   }
    443   // Greedy algorithm that selects coverage files with the maximal code coverage
    444   // delta at each iteration.
    445   // Note: Not guaranteed to generate the optimal set.
    446   // Example (*: covered, -: not_covered)
    447   // line#\coverage_file   cov1 cov2 cov3
    448   //          1              *   -    -
    449   //          2              *   *    -
    450   //          3              -   *    *
    451   //          4              -   *    *
    452   //          5              -   -    *
    453   // This algorithm will select cov2, cov1, cov3 while optimal solution is:
    454   // cov1, cov3.
    455   // double max_coverage_size_ratio = 0.0;
    456   TestReportMessage selected_coverage_msg;
    457   while (true) {
    458     double max_selection_metric = 0.0;
    459     string selected_coverage_file = "";
    460     // Update the remaining coverage file in original_coverage_msgs.
    461     for (auto it = original_coverages.begin(); it != original_coverages.end();
    462          ++it) {
    463       TestReportMessage cur_coverage_msg = it->second.coverage_msg;
    464       for (const auto ref_coverage : selected_coverage_msg.coverage()) {
    465         for (int i = 0; i < cur_coverage_msg.coverage_size(); i++) {
    466           CoverageReportMessage* coverage_to_be_updated =
    467               cur_coverage_msg.mutable_coverage(i);
    468           UpdateCoverageData(ref_coverage, coverage_to_be_updated);
    469         }
    470       }
    471       it->second.coverage_msg = cur_coverage_msg;
    472       long total_coverage_line = GetTotalCoverageLine(cur_coverage_msg);
    473       long trace_file_size = it->second.trace_file_size;
    474       double coverage_size_ratio =
    475           (double)total_coverage_line / trace_file_size;
    476       if (metric == TraceSelectionMetric::MAX_COVERAGE) {
    477         if (coverage_size_ratio > max_selection_metric) {
    478           max_selection_metric = coverage_size_ratio;
    479           selected_coverage_file = it->first;
    480         }
    481       } else if (metric == TraceSelectionMetric::MAX_COVERAGE_SIZE_RATIO) {
    482         if (total_coverage_line > max_selection_metric) {
    483           max_selection_metric = total_coverage_line;
    484           selected_coverage_file = it->first;
    485         }
    486       }
    487     }
    488     if (!max_selection_metric) {
    489       break;
    490     } else {
    491       CoverageInfo selected_coverage =
    492           original_coverages[selected_coverage_file];
    493       selected_coverages[selected_coverage_file] = selected_coverage;
    494       // Remove the coverage file from original_coverage_msgs.
    495       original_coverages.erase(selected_coverage_file);
    496       selected_coverage_msg = selected_coverage.coverage_msg;
    497     }
    498   }
    499   // Calculate the total code lines and total line covered.
    500   long total_lines = 0;
    501   long total_lines_covered = 0;
    502   for (auto it = selected_coverages.begin(); it != selected_coverages.end();
    503        ++it) {
    504     cout << "select trace file: " << it->second.trace_file_name << endl;
    505     TestReportMessage coverage_msg = it->second.coverage_msg;
    506     total_lines_covered += GetTotalCoverageLine(coverage_msg);
    507     if (GetTotalLine(coverage_msg) > total_lines) {
    508       total_lines = GetTotalLine(coverage_msg);
    509     }
    510   }
    511   double coverage_rate = (double)total_lines_covered / total_lines;
    512   cout << "total lines covered: " << total_lines_covered << endl;
    513   cout << "total lines: " << total_lines << endl;
    514   cout << "coverage rate: " << coverage_rate << endl;
    515 }
    516 
    517 long VtsTraceProcessor::GetTotalCoverageLine(const TestReportMessage& msg) {
    518   long total_coverage_line = 0;
    519   for (const auto coverage : msg.coverage()) {
    520     total_coverage_line += coverage.covered_line_count();
    521   }
    522   return total_coverage_line;
    523 }
    524 
    525 long VtsTraceProcessor::GetTotalLine(const TestReportMessage& msg) {
    526   long total_line = 0;
    527   for (const auto coverage : msg.coverage()) {
    528     total_line += coverage.total_line_count();
    529   }
    530   return total_line;
    531 }
    532 
    533 string VtsTraceProcessor::GetTraceFileName(const string& coverage_file_name) {
    534   std::size_t start = coverage_file_name.find("android.hardware");
    535   std::size_t end = coverage_file_name.find("vts.trace") + sizeof("vts.trace");
    536   return coverage_file_name.substr(start, end - start - 1);
    537 }
    538 
    539 bool VtsTraceProcessor::isEntryEvent(const InstrumentationEventType& event) {
    540   if (event == InstrumentationEventType::SERVER_API_ENTRY ||
    541       event == InstrumentationEventType::CLIENT_API_ENTRY ||
    542       event == InstrumentationEventType::PASSTHROUGH_ENTRY) {
    543     return true;
    544   }
    545   return false;
    546 }
    547 
    548 bool VtsTraceProcessor::isPairedRecord(const VtsProfilingRecord& entry_record,
    549                                        const VtsProfilingRecord& exit_record) {
    550   if (entry_record.package() != exit_record.package() ||
    551       entry_record.version() != exit_record.version() ||
    552       entry_record.interface() != exit_record.interface() ||
    553       entry_record.func_msg().name() != exit_record.func_msg().name()) {
    554     return false;
    555   }
    556   switch (entry_record.event()) {
    557     case InstrumentationEventType::SERVER_API_ENTRY: {
    558       if (exit_record.event() == InstrumentationEventType::SERVER_API_EXIT) {
    559         return true;
    560       }
    561       break;
    562     }
    563     case InstrumentationEventType::CLIENT_API_ENTRY: {
    564       if (exit_record.event() == InstrumentationEventType::CLIENT_API_EXIT)
    565         return true;
    566       break;
    567     }
    568     case InstrumentationEventType::PASSTHROUGH_ENTRY: {
    569       if (exit_record.event() == InstrumentationEventType::PASSTHROUGH_EXIT)
    570         return true;
    571       break;
    572     }
    573     default:
    574       cout << "Unsupported event: " << entry_record.event() << endl;
    575       return false;
    576   }
    577   return false;
    578 }
    579 
    580 }  // namespace vts
    581 }  // namespace android
    582