/* * Copyright (C) 2017 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 "VtsTraceProcessor.h" #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include "VtsProfilingUtil.h" using namespace std; using google::protobuf::TextFormat; namespace android { namespace vts { bool VtsTraceProcessor::ParseBinaryTrace(const string& trace_file, bool ignore_timestamp, bool entry_only, bool ignore_func_params, VtsProfilingMessage* profiling_msg) { int fd = open(trace_file.c_str(), O_RDONLY, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH); if (fd < 0) { cerr << "Can not open trace file: " << trace_file << "error: " << std::strerror(errno); return false; } google::protobuf::io::FileInputStream input(fd); VtsProfilingRecord record; while (readOneDelimited(&record, &input)) { if (ignore_timestamp) { record.clear_timestamp(); } if (ignore_func_params) { record.mutable_func_msg()->clear_arg(); record.mutable_func_msg()->clear_return_type_hidl(); } if (entry_only) { if (isEntryEvent(record.event())) { *profiling_msg->add_records() = record; } } else { *profiling_msg->add_records() = record; } record.Clear(); } input.Close(); return true; } bool VtsTraceProcessor::ParseTextTrace(const string& trace_file, VtsProfilingMessage* profiling_msg) { ifstream in(trace_file, std::ios::in); bool new_record = true; string record_str, line; while (getline(in, line)) { // Assume records are separated by '\n'. if (line.empty()) { new_record = false; } if (new_record) { record_str += line + "\n"; } else { VtsProfilingRecord record; if (!TextFormat::MergeFromString(record_str, &record)) { cerr << "Can't parse a given record: " << record_str << endl; return false; } *profiling_msg->add_records() = record; new_record = true; record_str.clear(); } } in.close(); return true; } void VtsTraceProcessor::ParseTrace(const string& trace_file) { VtsProfilingMessage profiling_msg; if (!ParseBinaryTrace(trace_file, false, false, false, &profiling_msg)) { cerr << __func__ << ": Failed to parse trace file: " << trace_file << endl; return; } for (const auto& record : profiling_msg.records()) { cout << record.DebugString() << endl; } } bool VtsTraceProcessor::WriteProfilingMsg( const string& output_file, const VtsProfilingMessage& profiling_msg) { int fd = open(output_file.c_str(), O_WRONLY | O_CREAT | O_EXCL, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH); if (fd < 0) { cerr << "Can not open trace file: " << output_file << "error: " << std::strerror(errno); return false; } google::protobuf::io::FileOutputStream output(fd); for (const auto& record : profiling_msg.records()) { if (!writeOneDelimited(record, &output)) { cerr << "Failed to write record"; } } output.Close(); return true; } void VtsTraceProcessor::ConvertTrace(const string& trace_file) { VtsProfilingMessage profiling_msg; if (!ParseTextTrace(trace_file, &profiling_msg)) { cerr << __func__ << ": Failed to parse trace file: " << trace_file << endl; return; } string tmp_file = trace_file + "_binary"; if (!WriteProfilingMsg(tmp_file, profiling_msg)) { cerr << __func__ << ": Failed to write new trace file: " << tmp_file << endl; return; } } void VtsTraceProcessor::CleanupTraceFile(const string& trace_file) { VtsProfilingMessage profiling_msg; if (!ParseBinaryTrace(trace_file, false, false, true, &profiling_msg)) { cerr << __func__ << ": Failed to parse trace file: " << trace_file << endl; return; } VtsProfilingMessage clean_profiling_msg; bool first_record = true; enum TRACE_TYPE { server_trace, client_trace, passthrough_trace }; string package; int version_major; int version_minor; TRACE_TYPE trace_type; for (const auto& record : profiling_msg.records()) { if (first_record) { package = record.package(); version_major = record.version_major(); version_minor = record.version_minor(); // determine trace type based on the event of the first record. switch (record.event()) { case InstrumentationEventType::SERVER_API_ENTRY: trace_type = TRACE_TYPE::server_trace; break; case InstrumentationEventType::CLIENT_API_ENTRY: trace_type = TRACE_TYPE::client_trace; break; case InstrumentationEventType::PASSTHROUGH_ENTRY: trace_type = TRACE_TYPE::passthrough_trace; break; default: cerr << "Unexpected record: " << record.DebugString() << endl; return; } first_record = false; } // If trace contains records for a different hal, remove it. if (record.package() != package || record.version_major() != version_major || record.version_minor() != version_minor) { cerr << "Unexpected record: " << record.DebugString() << endl; continue; } switch (trace_type) { case TRACE_TYPE::server_trace: { if (record.event() == InstrumentationEventType::SERVER_API_ENTRY || record.event() == InstrumentationEventType::SERVER_API_EXIT) { *clean_profiling_msg.add_records() = record; } break; } case TRACE_TYPE::client_trace: { if (record.event() == InstrumentationEventType::CLIENT_API_ENTRY || record.event() == InstrumentationEventType::CLIENT_API_EXIT) { *clean_profiling_msg.add_records() = record; } break; } case TRACE_TYPE::passthrough_trace: { if (record.event() == InstrumentationEventType::PASSTHROUGH_ENTRY || record.event() == InstrumentationEventType::PASSTHROUGH_EXIT) { *clean_profiling_msg.add_records() = record; } break; } default: cerr << "Unknow trace type: " << trace_type << endl; return; } } string tmp_file = trace_file + "_tmp"; if (!WriteProfilingMsg(tmp_file, clean_profiling_msg)) { cerr << __func__ << ": Failed to write new trace file: " << tmp_file << endl; return; } if (rename(tmp_file.c_str(), trace_file.c_str())) { cerr << __func__ << ": Failed to replace old trace file: " << trace_file << endl; return; } } void VtsTraceProcessor::CleanupTraces(const string& path) { struct stat path_stat; stat(path.c_str(), &path_stat); if (S_ISREG(path_stat.st_mode)) { CleanupTraceFile(path); } else if (S_ISDIR(path_stat.st_mode)) { DIR* dir = opendir(path.c_str()); struct dirent* file; while ((file = readdir(dir)) != NULL) { if (file->d_type == DT_REG) { string trace_file = path; if (path.substr(path.size() - 1) != "/") { trace_file += "/"; } trace_file += file->d_name; CleanupTraceFile(trace_file); } } } } void VtsTraceProcessor::ProcessTraceForLatencyProfiling( const string& trace_file) { VtsProfilingMessage profiling_msg; if (!ParseBinaryTrace(trace_file, false, false, true, &profiling_msg)) { cerr << __func__ << ": Failed to parse trace file: " << trace_file << endl; return; } if (!profiling_msg.records_size()) return; if (profiling_msg.records(0).event() == InstrumentationEventType::PASSTHROUGH_ENTRY || profiling_msg.records(0).event() == InstrumentationEventType::PASSTHROUGH_EXIT) { cout << "hidl_hal_mode:passthrough" << endl; } else { cout << "hidl_hal_mode:binder" << endl; } // stack to store all seen records. vector seen_records; // stack to store temp records that not processed. vector pending_records; for (const auto& record : profiling_msg.records()) { if (isEntryEvent(record.event())) { seen_records.emplace_back(record); } else { while (!seen_records.empty() && !isPairedRecord(seen_records.back(), record)) { pending_records.emplace_back(seen_records.back()); seen_records.pop_back(); } if (seen_records.empty()) { cerr << "Could not found entry record for record: " << record.DebugString() << endl; continue; } else { // Found the paired entry record, calculate the latency. VtsProfilingRecord entry_record = seen_records.back(); seen_records.pop_back(); string full_api_name = GetFullApiStr(record); int64_t start_timestamp = entry_record.timestamp(); int64_t end_timestamp = record.timestamp(); int64_t latency = end_timestamp - start_timestamp; // Negative latency check. if (latency < 0) { cerr << __func__ << ": got negative latency for " << full_api_name << endl; exit(-1); } cout << full_api_name << ":" << latency << endl; while (!pending_records.empty()) { seen_records.emplace_back(pending_records.back()); pending_records.pop_back(); } } } } } void VtsTraceProcessor::DedupTraces(const string& trace_dir) { DIR* dir = opendir(trace_dir.c_str()); if (dir == 0) { cerr << trace_dir << "does not exist." << endl; return; } vector seen_msgs; vector duplicate_trace_files; struct dirent* file; long total_trace_num = 0; long duplicat_trace_num = 0; while ((file = readdir(dir)) != NULL) { if (file->d_type == DT_REG) { total_trace_num++; string trace_file = trace_dir; if (trace_dir.substr(trace_dir.size() - 1) != "/") { trace_file += "/"; } trace_file += file->d_name; VtsProfilingMessage profiling_msg; if (!ParseBinaryTrace(trace_file, true, true, false, &profiling_msg)) { cerr << "Failed to parse trace file: " << trace_file << endl; return; } if (!profiling_msg.records_size()) { // empty trace file duplicate_trace_files.push_back(trace_file); duplicat_trace_num++; continue; } auto found = find_if(seen_msgs.begin(), seen_msgs.end(), [&profiling_msg](const VtsProfilingMessage& seen_msg) { std::string str_profiling_msg; std::string str_seen_msg; profiling_msg.SerializeToString(&str_profiling_msg); seen_msg.SerializeToString(&str_seen_msg); return (str_profiling_msg == str_seen_msg); }); if (found == seen_msgs.end()) { seen_msgs.push_back(profiling_msg); } else { duplicate_trace_files.push_back(trace_file); duplicat_trace_num++; } } } for (const string& duplicate_trace : duplicate_trace_files) { cout << "deleting duplicate trace file: " << duplicate_trace << endl; remove(duplicate_trace.c_str()); } cout << "Num of traces processed: " << total_trace_num << endl; cout << "Num of duplicate trace deleted: " << duplicat_trace_num << endl; cout << "Duplicate percentage: " << float(duplicat_trace_num) / total_trace_num << endl; } void VtsTraceProcessor::SelectTraces(const string& coverage_file_dir, const string& trace_file_dir, TraceSelectionMetric metric) { DIR* coverage_dir = opendir(coverage_file_dir.c_str()); if (coverage_dir == 0) { cerr << __func__ << ": " << coverage_file_dir << " does not exist." << endl; return; } DIR* trace_dir = opendir(trace_file_dir.c_str()); if (trace_dir == 0) { cerr << __func__ << ": " << trace_file_dir << " does not exist." << endl; return; } map original_coverages; map selected_coverages; // Parse all the coverage files and store them into original_coverage_msgs. struct dirent* file; while ((file = readdir(coverage_dir)) != NULL) { if (file->d_type == DT_REG) { string coverage_file = coverage_file_dir; if (coverage_file_dir.substr(coverage_file_dir.size() - 1) != "/") { coverage_file += "/"; } string coverage_file_base_name = file->d_name; coverage_file += coverage_file_base_name; TestReportMessage coverage_msg; coverage_processor_->ParseCoverageData(coverage_file, &coverage_msg); string trace_file = trace_file_dir; if (trace_file_dir.substr(trace_file_dir.size() - 1) != "/") { trace_file += "/"; } string trace_file_base_name = GetTraceFileName(coverage_file_base_name); trace_file += trace_file_base_name; ifstream in(trace_file, ifstream::binary | ifstream::ate); if (!in.good()) { cerr << "trace file: " << trace_file << " does not exists." << endl; continue; } long trace_file_size = in.tellg(); CoverageInfo coverage_info; coverage_info.coverage_msg = coverage_msg; coverage_info.trace_file_name = trace_file; coverage_info.trace_file_size = trace_file_size; original_coverages[coverage_file] = coverage_info; } } // Greedy algorithm that selects coverage files with the maximal code // coverage delta at each iteration. Note: Not guaranteed to generate the // optimal set. Example (*: covered, -: not_covered) line#\coverage_file // cov1 cov2 cov3 // 1 * - - // 2 * * - // 3 - * * // 4 - * * // 5 - - * // This algorithm will select cov2, cov1, cov3 while optimal solution is: // cov1, cov3. // double max_coverage_size_ratio = 0.0; TestReportMessage selected_coverage_msg; while (true) { double max_selection_metric = 0.0; string selected_coverage_file = ""; // Update the remaining coverage file in original_coverage_msgs. for (auto it = original_coverages.begin(); it != original_coverages.end(); ++it) { TestReportMessage cur_coverage_msg = it->second.coverage_msg; for (const auto& ref_coverage : selected_coverage_msg.coverage()) { for (int i = 0; i < cur_coverage_msg.coverage_size(); i++) { CoverageReportMessage* coverage_to_be_updated = cur_coverage_msg.mutable_coverage(i); coverage_processor_->UpdateCoverageData(ref_coverage, coverage_to_be_updated); } } it->second.coverage_msg = cur_coverage_msg; long total_coverage_line = coverage_processor_->GetTotalCoverageLine(cur_coverage_msg); long trace_file_size = it->second.trace_file_size; double coverage_size_ratio = (double)total_coverage_line / trace_file_size; if (metric == TraceSelectionMetric::MAX_COVERAGE) { if (coverage_size_ratio > max_selection_metric) { max_selection_metric = coverage_size_ratio; selected_coverage_file = it->first; } } else if (metric == TraceSelectionMetric::MAX_COVERAGE_SIZE_RATIO) { if (total_coverage_line > max_selection_metric) { max_selection_metric = total_coverage_line; selected_coverage_file = it->first; } } } if (!max_selection_metric) { break; } else { CoverageInfo selected_coverage = original_coverages[selected_coverage_file]; selected_coverages[selected_coverage_file] = selected_coverage; // Remove the coverage file from original_coverage_msgs. original_coverages.erase(selected_coverage_file); selected_coverage_msg = selected_coverage.coverage_msg; } } // Calculate the total code lines and total line covered. long total_lines = 0; long total_lines_covered = 0; for (auto it = selected_coverages.begin(); it != selected_coverages.end(); ++it) { cout << "select trace file: " << it->second.trace_file_name << endl; TestReportMessage coverage_msg = it->second.coverage_msg; total_lines_covered += coverage_processor_->GetTotalCoverageLine(coverage_msg); if (coverage_processor_->GetTotalCodeLine(coverage_msg) > total_lines) { total_lines = coverage_processor_->GetTotalCodeLine(coverage_msg); } } double coverage_rate = (double)total_lines_covered / total_lines; cout << "total lines covered: " << total_lines_covered << endl; cout << "total lines: " << total_lines << endl; cout << "coverage rate: " << coverage_rate << endl; } string VtsTraceProcessor::GetTraceFileName(const string& coverage_file_name) { std::size_t start = coverage_file_name.find("android.hardware"); std::size_t end = coverage_file_name.find("vts.trace") + sizeof("vts.trace"); return coverage_file_name.substr(start, end - start - 1); } bool VtsTraceProcessor::isEntryEvent(const InstrumentationEventType& event) { if (event == InstrumentationEventType::SERVER_API_ENTRY || event == InstrumentationEventType::CLIENT_API_ENTRY || event == InstrumentationEventType::PASSTHROUGH_ENTRY) { return true; } return false; } bool VtsTraceProcessor::isPairedRecord(const VtsProfilingRecord& entry_record, const VtsProfilingRecord& exit_record) { if (entry_record.package() != exit_record.package() || entry_record.version_major() != exit_record.version_major() || entry_record.version_minor() != exit_record.version_minor() || entry_record.interface() != exit_record.interface() || entry_record.func_msg().name() != exit_record.func_msg().name()) { return false; } switch (entry_record.event()) { case InstrumentationEventType::SERVER_API_ENTRY: { if (exit_record.event() == InstrumentationEventType::SERVER_API_EXIT) { return true; } break; } case InstrumentationEventType::CLIENT_API_ENTRY: { if (exit_record.event() == InstrumentationEventType::CLIENT_API_EXIT) return true; break; } case InstrumentationEventType::PASSTHROUGH_ENTRY: { if (exit_record.event() == InstrumentationEventType::PASSTHROUGH_EXIT) return true; break; } default: cout << "Unsupported event: " << entry_record.event() << endl; return false; } return false; } void VtsTraceProcessor::GetTestListForHal(const string& test_trace_dir, const string& output_file, bool verbose_output) { // Mapping from hal name to the list of test that access that hal. map> hal_trace_mapping; GetHalTraceMapping(test_trace_dir, &hal_trace_mapping); map> test_list; for (auto it = hal_trace_mapping.begin(); it != hal_trace_mapping.end(); it++) { test_list[it->first] = set(); vector trace_summaries = it->second; vector covered_apis; for (const auto& summary : trace_summaries) { for (auto const& api_stat_it : summary.api_stats) { if (std::find(covered_apis.begin(), covered_apis.end(), api_stat_it.first) == covered_apis.end()) { covered_apis.push_back(api_stat_it.first); test_list[it->first].insert(summary.test_name); } } } for (const auto& api : covered_apis) { cout << "covered api: " << api << endl; } } ofstream fout; fout.open(output_file); for (auto it = hal_trace_mapping.begin(); it != hal_trace_mapping.end(); it++) { if (verbose_output) { Json::Value root(Json::objectValue); root["Hal_name"] = Json::Value(it->first); Json::Value arr(Json::arrayValue); for (const TraceSummary& summary : it->second) { Json::Value obj; obj["Test_name"] = summary.test_name; obj["Unique_Api_Count"] = std::to_string(summary.unique_api_count); obj["Total_Api_Count"] = std::to_string(summary.total_api_count); arr.append(obj); } root["Test_list"] = arr; fout << root.toStyledString(); } else { fout << it->first << ","; for (auto test : test_list[it->first]) { auto found = find_if(it->second.begin(), it->second.end(), [&](const TraceSummary& trace_summary) { return (trace_summary.test_name == test); }); if (found != it->second.end()) { fout << found->test_name << "(" << found->unique_api_count << "/" << found->total_api_count << "),"; } } fout << endl; } } fout.close(); } void VtsTraceProcessor::GetHalTraceMapping( const string& test_trace_dir, map>* hal_trace_mapping) { DIR* trace_dir = opendir(test_trace_dir.c_str()); if (trace_dir == 0) { cerr << __func__ << ": " << trace_dir << " does not exist." << endl; return; } vector trace_summaries; struct dirent* test_dir; while ((test_dir = readdir(trace_dir)) != NULL) { if (test_dir->d_type == DT_DIR) { string test_name = test_dir->d_name; cout << "Processing test: " << test_name << endl; string trace_file_dir_name = test_trace_dir; if (test_trace_dir.substr(test_trace_dir.size() - 1) != "/") { trace_file_dir_name += "/"; } trace_file_dir_name += test_name; DIR* trace_file_dir = opendir(trace_file_dir_name.c_str()); struct dirent* trace_file; while ((trace_file = readdir(trace_file_dir)) != NULL) { if (trace_file->d_type == DT_REG) { string trace_file_name = trace_file_dir_name + "/" + trace_file->d_name; GetHalTraceSummary(trace_file_name, test_name, &trace_summaries); } } } } // Generate hal_trace_mapping mappings. for (const TraceSummary& trace_summary : trace_summaries) { string test_name = trace_summary.test_name; stringstream stream; stream << trace_summary.version_major << "." << trace_summary.version_minor; string hal_name = trace_summary.package + "@" + stream.str(); if (hal_trace_mapping->find(hal_name) != hal_trace_mapping->end()) { (*hal_trace_mapping)[hal_name].push_back(trace_summary); } else { (*hal_trace_mapping)[hal_name] = vector{trace_summary}; } } for (auto it = hal_trace_mapping->begin(); it != hal_trace_mapping->end(); it++) { // Sort the tests according to unique_api_count and break tie with // total_api_count. std::sort(it->second.begin(), it->second.end(), [](const TraceSummary& lhs, const TraceSummary& rhs) { return (lhs.unique_api_count > rhs.unique_api_count) || (lhs.unique_api_count == rhs.unique_api_count && lhs.total_api_count > rhs.total_api_count); }); } } void VtsTraceProcessor::GetHalTraceSummary( const string& trace_file, const string& test_name, vector* trace_summaries) { VtsProfilingMessage profiling_msg; if (!ParseBinaryTrace(trace_file, true, true, true, &profiling_msg)) { cerr << __func__ << ": Failed to parse trace file: " << trace_file << endl; return; } for (const auto& record : profiling_msg.records()) { string package = record.package(); int version_major = record.version_major(); int version_minor = record.version_minor(); string func_name = record.func_msg().name(); auto found = find_if(trace_summaries->begin(), trace_summaries->end(), [&](const TraceSummary& trace_summary) { return (test_name == trace_summary.test_name && package == trace_summary.package && version_major == trace_summary.version_major && version_minor == trace_summary.version_minor); }); if (found != trace_summaries->end()) { found->total_api_count++; if (found->api_stats.find(func_name) != found->api_stats.end()) { found->api_stats[func_name]++; } else { found->unique_api_count++; found->api_stats[func_name] = 1; } } else { map api_stats; api_stats[func_name] = 1; TraceSummary trace_summary(test_name, package, version_major, version_minor, 1, 1, api_stats); trace_summaries->push_back(trace_summary); } } } string VtsTraceProcessor::GetFullApiStr(const VtsProfilingRecord& record) { return record.package() + '@' + std::to_string(record.version_major()) + '.' + std::to_string(record.version_minor()) + "::" + record.interface() + "::" + record.func_msg().name(); } } // namespace vts } // namespace android