// Copyright (C) 2019 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 "session.h" #include "prefetcher/prefetcher_daemon.h" #include "prefetcher/task_id.h" #include "serialize/arena_ptr.h" #include "serialize/protobuf_io.h" #include #include #include #include #include #include #include #include #include #include #include namespace iorap { namespace prefetcher { // Print per-entry details even if successful. Default-off, too spammy. static constexpr bool kLogVerboseReadAhead = false; std::ostream& operator<<(std::ostream& os, const Session& session) { session.Dump(os, /*multiline*/false); return os; } Session::Session() { } void SessionBase::Dump(std::ostream& os, bool multiline) const { if (!multiline) { os << "Session{"; os << "session_id=" << SessionId(); os << "}"; return; } else { os << "Session (id=" << SessionId() << ")" << std::endl; return; } } SessionBase::SessionBase(size_t session_id, std::string description) : session_id_{session_id}, description_{description} { } std::optional SessionBase::GetFilePath(size_t path_id) const { auto it = path_map_.find(path_id); if (it != path_map_.end()) { return {it->second}; } else { return std::nullopt; } } bool SessionBase::RemoveFilePath(size_t path_id) { auto it = path_map_.find(path_id); if (it != path_map_.end()) { path_map_.erase(it); return true; } else { return false; } } bool SessionBase::InsertFilePath(size_t path_id, std::string file_path) { path_map_.insert({path_id, std::move(file_path)}); return true; } bool SessionBase::ProcessFd(int fd) { // Only SessionDirect has an implementation of this. // TODO: Maybe add a CommandChoice::kProcessFd ? instead of kCreateFdSession? LOG(FATAL) << "SessionBase::ProcessFd is not implemented"; return false; } // // Direct // std::ostream& operator<<(std::ostream& os, const SessionDirect::Entry& entry) { os << "Entry{"; os << "path_id=" << entry.path_id << ","; os << "kind=" << static_cast(entry.kind) << ","; os << "length=" << entry.length << ","; os << "offset=" << entry.offset << ","; os << "}"; return os; } // Just in case the failures are slowing down performance, turn them off. // static constexpr bool kLogFailures = true; static constexpr bool kLogFailures = false; bool SessionDirect::RegisterFilePath(size_t path_id, std::string_view file_path) { std::string file_path_str{file_path}; // no c_str for string_view. auto fd = TEMP_FAILURE_RETRY(open(file_path_str.c_str(), O_RDONLY)); if (fd < 0) { if (kLogFailures) { PLOG(ERROR) << "Failed to register file path: " << file_path << ", id=" << path_id << ", open(2) failed: "; } fd = android::base::unique_fd{}; // mark as 'bad' descriptor. } LOG(VERBOSE) << "RegisterFilePath path_id=" << path_id << ", file_path=" << file_path_str; if (!InsertFilePath(path_id, std::move(file_path_str))) { return false; } path_fd_map_.insert(std::make_pair(path_id, std::move(fd))); DCHECK(entry_list_map_[path_id].empty()); return true; } bool SessionDirect::UnregisterFilePath(size_t path_id) { if (!RemoveFilePath(path_id)) { return false; } { // Scoped FD reference lifetime. auto maybe_fd = GetFdForPath(path_id); DCHECK(*maybe_fd != nullptr); const android::base::unique_fd& entry_fd = **maybe_fd; auto list = entry_list_map_[path_id]; for (const EntryMapping& entry_mapping : list) { ReadAheadKind kind = entry_mapping.entry.kind; switch (kind) { case ReadAheadKind::kFadvise: // Nothing to do. break; case ReadAheadKind::kMmapLocked: FALLTHROUGH_INTENDED; case ReadAheadKind::kMlock: // Don't do any erases in the unregister file path to avoid paying O(n^2) erase cost. UnmapWithoutErase(entry_mapping); break; } } } auto it = entry_list_map_.find(path_id); auto end = entry_list_map_.end(); DCHECK(it != end); entry_list_map_.erase(it); // Close the FD for this file path. auto fd_it = path_fd_map_.find(path_id); DCHECK(fd_it != path_fd_map_.end()); path_fd_map_.erase(fd_it); return true; } // Note: return a pointer because optional doesn't hold references directly. std::optional SessionDirect::GetFdForPath(size_t path_id) { auto it = path_fd_map_.find(path_id); if (it == path_fd_map_.end()) { return std::nullopt; } else { return &it->second; } } bool SessionDirect::ReadAhead(size_t path_id, ReadAheadKind kind, size_t length, size_t offset) { // Take by-reference so we can mutate list at the end. auto& list = entry_list_map_[path_id]; Entry entry{path_id, kind, length, offset}; EntryMapping entry_mapping{entry, /*address*/nullptr, /*success*/false}; bool success = true; auto maybe_fd = GetFdForPath(path_id); if (!maybe_fd) { LOG(ERROR) << "SessionDirect: Failed to find FD for path_id=" << path_id; return false; } DCHECK(*maybe_fd != nullptr); const android::base::unique_fd& entry_fd = **maybe_fd; std::optional file_name_opt = GetFilePath(path_id); DCHECK(file_name_opt.has_value()); // if one map has it, all maps have it. std::string_view file_name = *file_name_opt; if (!entry_fd.ok()) { LOG(VERBOSE) << "SessionDirect: No file descriptor for (path_id=" << path_id << ") " << "path '" << file_name << "', failed to readahead entry."; // Even failures get kept with success=false. list.push_back(entry_mapping); return false; } switch (kind) { case ReadAheadKind::kFadvise: if (posix_fadvise(entry_fd, offset, length, POSIX_FADV_WILLNEED) < 0) { PLOG(ERROR) << "SessionDirect: Failed to fadvise entry " << file_name << ", offset=" << offset << ", length=" << length; success = false; } break; case ReadAheadKind::kMmapLocked: FALLTHROUGH_INTENDED; case ReadAheadKind::kMlock: { const bool need_mlock = kind == ReadAheadKind::kMlock; int flags = MAP_SHARED; if (!need_mlock) { // MAP_LOCKED is a best-effort to lock the page. it could still be // paged in later at a fault. flags |= MAP_LOCKED; } entry_mapping.address = mmap(/*addr*/nullptr, length, PROT_READ, flags, entry_fd, offset); if (entry_mapping.address == nullptr) { PLOG(ERROR) << "SessionDirect: Failed to mmap entry " << file_name << ", offset=" << offset << ", length=" << length; success = false; break; } // Strong guarantee that page will be locked if mlock returns successfully. if (need_mlock && mlock(entry_mapping.address, length) < 0) { PLOG(ERROR) << "SessionDirect: Failed to mlock entry " << file_name << ", offset=" << offset << ", length=" << length; // We already have a mapping address, so we should add it to the list. // However this didn't succeed 100% because the lock failed, so return false later. success = false; } } } // Keep track of success so we know in Dump() what the number of failed entry mappings were. entry_mapping.success = success; // Keep track of this so that we can clean it up later in UnreadAhead. list.push_back(entry_mapping); if (entry_mapping.success) { if (kLogVerboseReadAhead) { LOG(VERBOSE) << "SessionDirect: ReadAhead for " << entry_mapping.entry; } } // else one of the errors above already did print. return success; } bool SessionDirect::UnreadAhead(size_t path_id, ReadAheadKind kind, size_t length, size_t offset) { Entry entry{path_id, kind, length, offset}; auto list = entry_list_map_[path_id]; if (list.empty()) { return false; } std::optional entry_mapping; size_t idx = 0; for (size_t i = 0; i < list.size(); ++i) { if (entry == list[i].entry) { entry_mapping = list[i]; idx = 0; break; } } if (!entry_mapping) { return false; } switch (kind) { case ReadAheadKind::kFadvise: // Nothing to do. // TODO: maybe fadvise(RANDOM)? return true; case ReadAheadKind::kMmapLocked: FALLTHROUGH_INTENDED; case ReadAheadKind::kMlock: UnmapWithoutErase(*entry_mapping); return true; } list.erase(list.begin() + idx); // FDs close only with UnregisterFilePath. return true; } void SessionDirect::UnmapWithoutErase(const EntryMapping& entry_mapping) { void* address = entry_mapping.address; size_t length = entry_mapping.entry.length; // munmap also unlocks. Do not need explicit munlock. if (munmap(address, length) < 0) { PLOG(WARNING) << "ReadAhead (Finish): Failed to munmap address: " << address << ", length: " << length; } } bool SessionDirect::ProcessFd(int fd) { // TODO: the path is advisory, but it would still be cleaner to pass it separately const char* fd_path = SessionDescription().c_str(); android::base::Timer open_timer{}; android::base::Timer total_timer{}; serialize::ArenaPtr trace_file_ptr = serialize::ProtobufIO::Open(fd, fd_path); if (trace_file_ptr == nullptr) { LOG(ERROR) << "SessionDirect::ProcessFd failed, corrupted protobuf format? " << fd_path; return false; } // TODO: maybe make it part of a kProcessFd type of command? ReadAheadKind kind = ReadAheadKind::kFadvise; // TODO: The "Task[Id]" should probably be the one owning the trace file. // When the task is fully complete, the task can be deleted and the // associated arenas can go with them. // TODO: we should probably have the file entries all be relative // to the package path? // Open every file in the trace index. const serialize::proto::TraceFileIndex& index = trace_file_ptr->index(); size_t count_entries = 0; for (const serialize::proto::TraceFileIndexEntry& index_entry : index.entries()) { LOG(VERBOSE) << "ReadAhead: found file entry: " << index_entry.file_name(); if (index_entry.id() < 0) { LOG(WARNING) << "ReadAhead: Skip bad TraceFileIndexEntry, negative ID not allowed: " << index_entry.id(); continue; } size_t path_id = index_entry.id(); const auto& path_file_name = index_entry.file_name(); if (!this->RegisterFilePath(path_id, path_file_name)) { LOG(WARNING) << "ReadAhead: Failed to register file path: " << path_file_name; ++count_entries; } } LOG(VERBOSE) << "ReadAhead: Registered " << count_entries << " file paths"; std::chrono::milliseconds open_duration_ms = open_timer.duration(); LOG(DEBUG) << "ProcessFd: open+parsed headers in " << open_duration_ms.count() << "ms"; // Go through every trace entry and readahead every (file,offset,len) tuple. size_t entry_offset = 0; const serialize::proto::TraceFileList& file_list = trace_file_ptr->list(); for (const serialize::proto::TraceFileEntry& file_entry : file_list.entries()) { ++entry_offset; if (file_entry.file_length() < 0 || file_entry.file_offset() < 0) { LOG(WARNING) << "ProcessFd entry negative file length or offset, illegal: " << "index_id=" << file_entry.index_id() << ", skipping"; continue; } // Attempt to perform readahead. This can generate more warnings dynamically. if (!this->ReadAhead(file_entry.index_id(), kind, file_entry.file_length(), file_entry.file_offset())) { if (kLogFailures) { LOG(WARNING) << "Failed readahead, bad file length/offset in entry @ " << (entry_offset - 1); } } } std::chrono::milliseconds total_duration_ms = total_timer.duration(); LOG(DEBUG) << "ProcessFd: total duration " << total_duration_ms.count() << "ms"; { struct timeval now; gettimeofday(&now, nullptr); uint64_t now_usec = (now.tv_sec * 1000000LL + now.tv_usec); LOG(DEBUG) << "ProcessFd: finishing usec: " << now_usec; } return true; } static bool IsDumpEveryEntry() { // Set to 'true' to dump every single entry for debugging (multiline). // Otherwise it only prints per-file-path summaries. return ::android::base::GetBoolProperty("iorapd.readahead.dump_all", /*default*/false); } static bool IsDumpEveryPath() { // Dump per-file-path (entry) stats. Defaults to on if the above property is on. return ::android::base::GetBoolProperty("iorapd.readahead.dump_paths", /*default*/false); } void SessionDirect::Dump(std::ostream& os, bool multiline) const { { struct timeval now; gettimeofday(&now, nullptr); uint64_t now_usec = (now.tv_sec * 1000000LL + now.tv_usec); LOG(DEBUG) << "SessionDirect::Dump: beginning usec: " << now_usec; } size_t path_count = entry_list_map_.size(); size_t read_ahead_entries = 0; size_t read_ahead_bytes = 0; size_t overall_entry_count = 0; size_t overall_byte_count = 0; for (auto it = entry_list_map_.begin(); it != entry_list_map_.end(); ++it) { const auto& entry_mapping_list = it->second; for (size_t j = 0; j < entry_mapping_list.size(); ++j) { const EntryMapping& entry_mapping = entry_mapping_list[j]; const Entry& entry = entry_mapping.entry; ++overall_entry_count; overall_byte_count += entry.length; if (entry_mapping.success) { ++read_ahead_entries; read_ahead_bytes += entry.length; } } } double overall_success_entry_rate = read_ahead_entries * 100.0 / overall_entry_count; double overall_success_byte_rate = read_ahead_bytes * 100.0 / overall_byte_count; size_t fd_count = path_fd_map_.size(); size_t good_fd_count = 0; for (auto it = path_fd_map_.begin(); it != path_fd_map_.end(); ++it) { if (it->second.ok()) { ++good_fd_count; } } double good_fd_rate = good_fd_count * 100.0 / fd_count; // double bad_fd_rate = (fd_count - good_fd_count) * 1.0 / fd_count; if (!multiline) { os << "SessionDirect{"; os << "session_id=" << SessionId() << ","; os << "file_paths=" << path_count << " (good: " << good_fd_rate << "),"; os << "read_ahead_entries=" << read_ahead_entries; os << "(" << overall_success_entry_rate << "%),"; os << "read_ahead_bytes=" << read_ahead_bytes << ""; os << "(" << overall_success_byte_rate << "%),"; os << "timer=" << timer_.duration().count() << ","; os << "}"; return; } else { // Always try to pay attention to these stats below. // They can be signs of potential performance problems. os << "Session Direct (id=" << SessionId() << ")" << std::endl; os << " Summary: " << std::endl; os << " Description = " << SessionDescription() << std::endl; os << " Duration = " << timer_.duration().count() << "ms" << std::endl; os << " Total File Paths=" << path_count << " (good: " << good_fd_rate << "%)" << std::endl; os << " Total Entries=" << overall_entry_count; os << " (good: " << overall_success_entry_rate << "%)" << std::endl; os << " Total Bytes=" << overall_byte_count << ""; os << " (good: " << overall_success_byte_rate << "%)" << std::endl; os << std::endl; // Probably too spammy, but they could narrow down the issue for a problem in above stats. if (!IsDumpEveryPath() && !IsDumpEveryEntry()) { return; } for (auto it = entry_list_map_.begin(); it != entry_list_map_.end(); ++it) { size_t path_id = it->first; const auto& entry_mapping_list = it->second; std::optional file_path = GetFilePath(path_id); os << " File Path (id=" << path_id << "): "; if (file_path.has_value()) { os << "'" << *file_path << "'"; } else { os << "(nullopt)"; } auto fd_it = path_fd_map_.find(path_id); os << ", FD="; if (fd_it != path_fd_map_.end()) { const android::base::unique_fd& fd = fd_it->second; os << fd.get(); // -1 for failed fd. } else { os << "(none)"; } os << std::endl; size_t total_entries = entry_mapping_list.size(); size_t total_bytes = 0; size_t local_read_ahead_entries = 0; size_t local_read_ahead_bytes = 0; for (size_t j = 0; j < entry_mapping_list.size(); ++j) { const EntryMapping& entry_mapping = entry_mapping_list[j]; const Entry& entry = entry_mapping.entry; total_bytes += entry.length; // Sidenote: Bad FDs will have 100% failed mappings. // Good FDs may sometimes have failed mappings. if (entry_mapping.success) { ++local_read_ahead_entries; local_read_ahead_bytes += entry.length; } if (IsDumpEveryEntry()) { os << " Entry " << j << " details:" << std::endl; os << " " << entry << std::endl; os << " Mapping " << (entry_mapping.success ? "Succeeded" : "Failed") << ", Address " << entry_mapping.address << std::endl; } } double entry_success_rate = local_read_ahead_entries * 100.0 / total_entries; double bytes_success_rate = local_read_ahead_bytes * 100.0 / total_bytes; double entry_failure_rate = (total_entries - local_read_ahead_entries) * 100.0 / total_entries; double bytes_failure_rate = (total_bytes - local_read_ahead_bytes) * 100.0 / total_bytes; os << " Successful: Entries=" << local_read_ahead_entries << " (" << entry_success_rate << "%)" << ", Bytes=" << local_read_ahead_bytes << " (" << bytes_success_rate << "%)" << std::endl; os << " Failed: Entries=" << (total_entries - local_read_ahead_entries) << " (" << entry_failure_rate << "%)" << ", Bytes=" << (total_bytes - local_read_ahead_bytes) << " (" << bytes_failure_rate << "%)" << std::endl; os << " Total: Entries=" << total_entries << ", Bytes=" << total_bytes << std::endl; } return; } } SessionDirect::~SessionDirect() { for (auto it = entry_list_map_.begin(); it != entry_list_map_.end();) { size_t path_id = it->first; ++it; // the iterator is removed in the following Unregister method. UnregisterFilePath(path_id); } } // // Indirect // SessionIndirect::SessionIndirect(size_t session_id, std::string description, std::shared_ptr daemon, bool send_command) : SessionBase{session_id, description}, daemon_{daemon} { // Don't do anything in e.g. subclasses. if (!send_command) { return; } Command cmd{}; cmd.choice = CommandChoice::kCreateSession; cmd.session_id = session_id; cmd.file_path = description; LOG(VERBOSE) << "SessionIndirect: " << cmd; if (!daemon_->SendCommand(cmd)) { LOG(FATAL) << "SessionIndirect: Failure to create session " << session_id << ", description: " << description; } } SessionIndirect::~SessionIndirect() { Command cmd{}; cmd.choice = CommandChoice::kDestroySession; cmd.session_id = SessionId(); if (!daemon_->SendCommand(cmd)) { LOG(WARNING) << "SessionIndirect: Failure to destroy session " << SessionId() << ", description: " << SessionDescription(); } } void SessionIndirect::Dump(std::ostream& os, bool multiline) const { // SessionBase::Dump(os, multiline); // TODO: does having the local dump do anything for us? Command cmd{}; cmd.choice = CommandChoice::kDumpSession; cmd.session_id = SessionId(); daemon_->SendCommand(cmd); } bool SessionIndirect::RegisterFilePath(size_t path_id, std::string_view file_path) { Command cmd{}; cmd.choice = CommandChoice::kRegisterFilePath; cmd.session_id = SessionId(); cmd.id = path_id; cmd.file_path = file_path; return daemon_->SendCommand(cmd); } bool SessionIndirect::UnregisterFilePath(size_t path_id) { Command cmd{}; cmd.choice = CommandChoice::kUnregisterFilePath; cmd.session_id = SessionId(); cmd.id = path_id; return daemon_->SendCommand(cmd); } bool SessionIndirect::ReadAhead(size_t path_id, ReadAheadKind kind, size_t length, size_t offset) { Command cmd{}; cmd.choice = CommandChoice::kReadAhead; cmd.session_id = SessionId(); cmd.id = path_id; cmd.read_ahead_kind = kind; cmd.length = length; cmd.offset = offset; return daemon_->SendCommand(cmd); } bool SessionIndirect::UnreadAhead(size_t path_id, ReadAheadKind kind, size_t length, size_t offset) { LOG(WARNING) << "UnreadAhead: command not implemented yet"; return true; } // // IndirectSocket // SessionIndirectSocket::SessionIndirectSocket(size_t session_id, int fd, std::string description, std::shared_ptr daemon) : SessionIndirect{session_id, description, daemon, /*send_command*/false} { // TODO: all of the WriteCommand etc in the daemon. Command cmd{}; cmd.choice = CommandChoice::kCreateFdSession; cmd.fd = fd; cmd.session_id = session_id; cmd.file_path = description; LOG(VERBOSE) << "SessionIndirectSocket: " << cmd; if (!daemon_->SendCommand(cmd)) { LOG(FATAL) << "SessionIndirectSocket: Failure to create session " << session_id << ", description: " << description; } // This goes into the SessionDirect ctor + SessionDirect::ProcessFd // as implemented in PrefetcherDaemon::ReceiveCommand } SessionIndirectSocket::~SessionIndirectSocket() { } } // namespace prefetcher } // namespace iorap