binder: Add more debugging information to dumpsys
Usage:
$> adb shell dumpsys iorapd
Example output:
----------------------------------
Recent prefetches:
/data/misc/iorapd/com.google.android.GoogleCamera/60092050/com.android.camera.CameraLauncher/compiled_traces/compiled_trace.pb
Task ID: 48
Bytes count: 37552128
/data/misc/iorapd/com.google.android.GoogleCamera/60092050/com.android.camera.CameraLauncher/compiled_traces/compiled_trace.pb
Task ID: 50
Bytes count: 37552128
Perfetto consumer state:
Last destroyed handle: 3
Last created handle: 4
In-flight handles:
Handle 4
Kind: kStartedTracing
Perfetto State: 3
Started tracing at: 1583366848124890862
Last transition at: 1583366848124890862
Background job:
Last run at: (None)
Activities last compiled: 0
Package history in database:
com.google.android.GoogleCamera/com.android.camera.CameraLauncher@60092050
Compiled Status: Usable compiled trace
Bytes to be prefetched: 37552128
Time compiled: Thu Feb 27 19:29:44 2020
/data/misc/iorapd/com.google.android.GoogleCamera/60092050/com.android.camera.CameraLauncher/compiled_traces/compiled_trace.pb
Raw traces:
Trace count: 4
/data/misc/iorapd/com.google.android.GoogleCamera/60092050/com.android.camera.CameraLauncher/raw_traces/1582849735195156086.perfetto_trace.pb
/data/misc/iorapd/com.google.android.GoogleCamera/60092050/com.android.camera.CameraLauncher/raw_traces/1582849740552479901.perfetto_trace.pb
/data/misc/iorapd/com.google.android.GoogleCamera/60092050/com.android.camera.CameraLauncher/raw_traces/1582849747538387055.perfetto_trace.pb
/data/misc/iorapd/com.google.android.GoogleCamera/60092050/com.android.camera.CameraLauncher/raw_traces/1582849754783053715.perfetto_trace.pb
com.android.chrome/com.google.android.apps.chrome.Main@406800383
Compiled Status: Usable compiled trace
Bytes to be prefetched: 22462464
Time compiled: Tue Mar 03 17:37:55 2020
/data/misc/iorapd/com.android.chrome/406800383/com.google.android.apps.chrome.Main/compiled_traces/compiled_trace.pb
Raw traces:
Trace count: 3
/data/misc/iorapd/com.android.chrome/406800383/com.google.android.apps.chrome.Main/raw_traces/1583194201492399331.perfetto_trace.pb
/data/misc/iorapd/com.android.chrome/406800383/com.google.android.apps.chrome.Main/raw_traces/1583255733288245600.perfetto_trace.pb
/data/misc/iorapd/com.android.chrome/406800383/com.google.android.apps.chrome.Main/raw_traces/1583275047005372750.perfetto_trace.pb
com.google.android.apps.nexuslauncher/com.google.android.apps.nexuslauncher.NexusLauncherActivity@806
Compiled Status: Need 3 more traces for compilation
Raw traces:
Trace count: 0
com.facebook.orca/com.facebook.orca.auth.StartScreenActivity@197803942
Compiled Status: Need 2 more traces for compilation
Raw traces:
Trace count: 1
/data/misc/iorapd/com.facebook.orca/197803942/com.facebook.orca.auth.StartScreenActivity/raw_traces/1583255729334294165.perfetto_trace.pb
com.google.android.apps.messaging/com.google.android.apps.messaging.ui.ConversationListActivity@52062040
Compiled Status: Usable compiled trace
Bytes to be prefetched: 135168
Time compiled: Wed Mar 04 17:35:05 2020
/data/misc/iorapd/com.google.android.apps.messaging/52062040/com.google.android.apps.messaging.ui.ConversationListActivity/compiled_traces/compiled_trace.pb
Raw traces:
Trace count: 3
/data/misc/iorapd/com.google.android.apps.messaging/52062040/com.google.android.apps.messaging.ui.ConversationListActivity/raw_traces/1583358909410587832.perfetto_trace.pb
/data/misc/iorapd/com.google.android.apps.messaging/52062040/com.google.android.apps.messaging.ui.ConversationListActivity/raw_traces/1583361233567436080.perfetto_trace.pb
/data/misc/iorapd/com.google.android.apps.messaging/52062040/com.google.android.apps.messaging.ui.ConversationListActivity/raw_traces/1583361249989595059.perfetto_trace.pb
com.google.android.dialer/com.google.android.dialer.extensions.GoogleDialtactsActivity@5013553
Compiled Status: Need 2 more traces for compilation
Raw traces:
Trace count: 1
/data/misc/iorapd/com.google.android.dialer/5013553/com.google.android.dialer.extensions.GoogleDialtactsActivity/raw_traces/1583360061315454718.perfetto_trace.pb
com.google.android.apps.photos/com.google.android.apps.photos.home.HomeActivity@17136497
Compiled Status: Need 3 more traces for compilation
Raw traces:
Trace count: 0
Test: adb shell dumpsys iorapd
Bug: 150710847
Change-Id: Idd1a4668c407c5233bdc603470864632c8a41a22
diff --git a/src/db/models.h b/src/db/models.h
index bfe8cfc..1feac47 100644
--- a/src/db/models.h
+++ b/src/db/models.h
@@ -1070,6 +1070,23 @@
return p;
}
+ static std::vector<PrefetchFileModel> SelectAll(DbHandle db) {
+ ScopedLockDb lock{db};
+
+ std::string query =
+ "SELECT prefetch_files.id, prefetch_files.activity_id, prefetch_files.file_path "
+ "FROM prefetch_files";
+ DbStatement stmt = DbStatement::Prepare(db, query);
+
+ std::vector<PrefetchFileModel> prefetch_files;
+ PrefetchFileModel p{db};
+ while (DbQueryBuilder::SelectOnce(stmt, p.id, p.activity_id, p.file_path)) {
+ prefetch_files.push_back(p);
+ }
+
+ return prefetch_files;
+ }
+
static std::optional<PrefetchFileModel> Insert(DbHandle db,
int activity_id,
std::string file_path) {
diff --git a/src/maintenance/controller.cc b/src/maintenance/controller.cc
index 853afcd..f8fe9d9 100644
--- a/src/maintenance/controller.cc
+++ b/src/maintenance/controller.cc
@@ -22,13 +22,17 @@
#include "db/models.h"
#include "inode2filename/inode.h"
#include "inode2filename/search_directories.h"
+#include "prefetcher/read_ahead.h"
#include <android-base/file.h>
+#include <utils/Printer.h>
+#include <ctime>
#include <iostream>
#include <filesystem>
#include <fstream>
#include <limits>
+#include <mutex>
#include <optional>
#include <vector>
#include <string>
@@ -36,6 +40,16 @@
namespace iorap::maintenance {
+static constexpr size_t kMinTracesForCompilation = 3;
+
+struct LastJobInfo {
+ time_t last_run_ns_{0};
+ size_t activities_last_compiled_{0};
+};
+
+LastJobInfo last_job_info_;
+std::mutex last_job_info_mutex_;
+
// Gets the path of output compiled trace.
db::CompiledTraceFileModel CalculateNewestFilePath(
const std::string& package_name,
@@ -240,6 +254,11 @@
return false;
}
+ {
+ std::lock_guard<std::mutex> last_job_info_guard{last_job_info_mutex_};
+ last_job_info_.activities_last_compiled_++;
+ }
+
// Show the compilation config.
LOG(DEBUG) << "Try to compiled package_id: " << package_id
<< " package_name: " << package_name
@@ -308,6 +327,11 @@
// Compiled the perfetto traces for packages in a device.
bool CompileAppsOnDevice(const db::DbHandle& db, const ControllerParameters& params) {
+ {
+ std::lock_guard<std::mutex> last_job_info_guard{last_job_info_mutex_};
+ last_job_info_.activities_last_compiled_ = 0;
+ }
+
std::vector<db::PackageModel> packages = db::PackageModel::SelectAll(db);
bool ret = true;
for (db::PackageModel package : packages) {
@@ -316,6 +340,11 @@
}
}
+ {
+ std::lock_guard<std::mutex> last_job_info_guard{last_job_info_mutex_};
+ last_job_info_.last_run_ns_ = time(nullptr);
+ }
+
return ret;
}
@@ -355,4 +384,149 @@
return CompileActivity(db, package->id, package_name, activity_name, version, params);
}
+static std::string TimeToString(time_t the_time) {
+ tm tm_buf{};
+ tm* tm_ptr = localtime_r(&the_time, &tm_buf);
+
+ if (tm_ptr != nullptr) {
+ char time_buffer[256];
+ strftime(time_buffer, sizeof(time_buffer), "%a %b %d %H:%M:%S %Y", tm_ptr);
+ return std::string{time_buffer};
+ } else {
+ return std::string{"(nullptr)"};
+ }
+}
+
+static std::string GetTimestampForPrefetchFile(const db::PrefetchFileModel& prefetch_file) {
+ std::filesystem::path path{prefetch_file.file_path};
+
+ std::error_code ec{};
+ auto last_write_time = std::filesystem::last_write_time(path, /*out*/ec);
+ if (ec) {
+ return std::string("Failed to get last write time: ") + ec.message();
+ }
+
+ time_t time = decltype(last_write_time)::clock::to_time_t(last_write_time);
+
+ std::string time_str = TimeToString(time);
+ return time_str;
+}
+
+void DumpPackageActivity(const db::DbHandle& db,
+ ::android::Printer& printer,
+ const db::PackageModel& package,
+ const db::ActivityModel& activity) {
+ int package_id = package.id;
+ const std::string& package_name = package.name;
+ int package_version = package.version;
+ const std::string& activity_name = activity.name;
+ db::VersionedComponentName vcn{package_name, activity_name, package_version};
+
+ // com.google.Settings/com.google.Settings.ActivityMain@1234567890
+ printer.printFormatLine(" %s/%s@%d",
+ package_name.c_str(),
+ activity_name.c_str(),
+ package_version);
+
+ std::optional<db::PrefetchFileModel> prefetch_file =
+ db::PrefetchFileModel::SelectByVersionedComponentName(db, vcn);
+
+ std::vector<db::AppLaunchHistoryModel> histories =
+ db::AppLaunchHistoryModel::SelectActivityHistoryForCompile(db, activity.id);
+ std::vector<compiler::CompilationInput> perfetto_traces =
+ GetPerfettoTraceInfo(db, histories);
+
+ if (prefetch_file) {
+ bool exists_on_disk = std::filesystem::exists(prefetch_file->file_path);
+
+ std::optional<size_t> prefetch_byte_sum =
+ prefetcher::ReadAhead::PrefetchSizeInBytes(prefetch_file->file_path);
+
+ if (exists_on_disk) {
+ printer.printFormatLine(" Compiled Status: Usable compiled trace");
+ } else {
+ printer.printFormatLine(" Compiled Status: Prefetch file deleted from disk.");
+ }
+
+ if (prefetch_byte_sum) {
+ printer.printFormatLine(" Bytes to be prefetched: %zu", *prefetch_byte_sum);
+ } else {
+ printer.printFormatLine(" Bytes to be prefetched: (bad file path)" );
+ }
+
+ printer.printFormatLine(" Time compiled: %s",
+ GetTimestampForPrefetchFile(*prefetch_file).c_str());
+ printer.printFormatLine(" %s", prefetch_file->file_path.c_str());
+ } else {
+ size_t size = perfetto_traces.size();
+
+ if (size >= kMinTracesForCompilation) {
+ printer.printFormatLine(" Compiled Status: Raw traces pending compilation (%zu)",
+ perfetto_traces.size());
+ } else {
+ size_t remaining = kMinTracesForCompilation - size;
+ printer.printFormatLine(" Compiled Status: Need %zu more traces for compilation",
+ remaining);
+ }
+ }
+
+ printer.printFormatLine(" Raw traces:");
+ printer.printFormatLine(" Trace count: %zu", perfetto_traces.size());
+
+ for (compiler::CompilationInput& compilation_input : perfetto_traces) {
+ std::string& raw_trace_file_name = compilation_input.filename;
+
+ printer.printFormatLine(" %s", raw_trace_file_name.c_str());
+ }
+}
+
+void DumpPackage(const db::DbHandle& db,
+ ::android::Printer& printer,
+ db::PackageModel package) {
+ std::vector<db::ActivityModel> activities =
+ db::ActivityModel::SelectByPackageId(db, package.id);
+
+ for (db::ActivityModel& activity : activities) {
+ DumpPackageActivity(db, printer, package, activity);
+ }
+}
+
+void DumpAllPackages(const db::DbHandle& db, ::android::Printer& printer) {
+ printer.printLine("Package history in database:");
+
+ std::vector<db::PackageModel> packages = db::PackageModel::SelectAll(db);
+ for (db::PackageModel package : packages) {
+ DumpPackage(db, printer, package);
+ }
+
+ printer.printLine("");
+}
+
+void Dump(const db::DbHandle& db, ::android::Printer& printer) {
+ bool locked = last_job_info_mutex_.try_lock();
+
+ LastJobInfo info = last_job_info_;
+
+ printer.printFormatLine("Background job:");
+ if (!locked) {
+ printer.printLine(""""" (possible deadlock)");
+ }
+ if (info.last_run_ns_ != time_t{0}) {
+ std::string time_str = TimeToString(info.last_run_ns_);
+
+ printer.printFormatLine(" Last run at: %s", time_str.c_str());
+ } else {
+ printer.printFormatLine(" Last run at: (None)");
+ }
+ printer.printFormatLine(" Activities last compiled: %zu", info.activities_last_compiled_);
+
+ printer.printLine("");
+
+ if (locked) {
+ last_job_info_mutex_.unlock();
+ }
+
+ DumpAllPackages(db, printer);
+}
+
} // namespace iorap::maintenance
diff --git a/src/maintenance/controller.h b/src/maintenance/controller.h
index 27e40bb..dcf95a9 100644
--- a/src/maintenance/controller.h
+++ b/src/maintenance/controller.h
@@ -21,6 +21,10 @@
#include <string>
#include <vector>
+namespace android {
+class Printer;
+} // namespace android
+
namespace iorap::maintenance {
// Enabling mock for testing purpose.
@@ -97,6 +101,9 @@
const ControllerParameters& params);
// Visible for testing.
bool CompileAppsOnDevice(const db::DbHandle& db, const ControllerParameters& params);
-} // iorap::compiler_controller
+
+void Dump(const db::DbHandle& db, ::android::Printer& printer);
+
+} // iorap::maintenance
#endif // IORAP_SRC_MAINTENANCE_COMPILER_CONTROLLER_H_
diff --git a/src/manager/event_manager.cc b/src/manager/event_manager.cc
index c29b626..49aa6a3 100644
--- a/src/manager/event_manager.cc
+++ b/src/manager/event_manager.cc
@@ -997,7 +997,9 @@
}
void Dump(/*borrow*/::android::Printer& printer) {
+ ::iorap::prefetcher::ReadAhead::Dump(printer);
::iorap::perfetto::PerfettoConsumerImpl::Dump(/*borrow*/printer);
+ ::iorap::maintenance::Dump(db::SchemaModel::GetSingleton(), printer);
}
rxcpp::composite_subscription InitializeRxGraph() {
diff --git a/src/prefetcher/read_ahead.cc b/src/prefetcher/read_ahead.cc
index 6327b35..a4ed8da 100644
--- a/src/prefetcher/read_ahead.cc
+++ b/src/prefetcher/read_ahead.cc
@@ -25,6 +25,7 @@
#include <android-base/scopeguard.h>
#include <android-base/properties.h>
#include <android-base/unique_fd.h>
+#include <deque>
#include <fcntl.h>
#include <functional>
#include <stdint.h>
@@ -33,6 +34,7 @@
#include <sys/types.h>
#include <sys/stat.h>
#include <unordered_map>
+#include <utils/Printer.h>
namespace iorap {
namespace prefetcher {
@@ -102,6 +104,53 @@
std::shared_ptr<Session> session;
};
+// Remember the last 5 files being prefetched.
+static constexpr size_t kRecentDataCount = 5;
+
+struct RecentData {
+ TaskId task_id;
+ size_t file_lengths_sum;
+};
+
+struct RecentDataKeeper {
+ std::deque<RecentData> recents_;
+ std::mutex mutex_;
+
+ void RecordRecent(TaskId task_id, size_t file_lengths_sum) {
+ std::lock_guard<std::mutex> guard{mutex_};
+
+ while (recents_.size() > kRecentDataCount) {
+ recents_.pop_front();
+ }
+ recents_.push_back(RecentData{std::move(task_id), file_lengths_sum});
+ }
+
+ void Dump(/*borrow*/::android::Printer& printer) {
+ bool locked = mutex_.try_lock();
+
+ printer.printFormatLine("Recent prefetches:");
+ if (!locked) {
+ printer.printLine(""""" (possible deadlock)");
+ }
+
+ for (const RecentData& data : recents_) {
+ printer.printFormatLine(" %s", data.task_id.path.c_str());
+ printer.printFormatLine(" Task ID: %zu", data.task_id.id);
+ printer.printFormatLine(" Bytes count: %zu", data.file_lengths_sum);
+ }
+
+ if (recents_.empty()) {
+ printer.printFormatLine(" (None)");
+ }
+
+ printer.printLine("");
+
+ if (locked) {
+ mutex_.unlock();
+ }
+ }
+};
+
struct ReadAhead::Impl {
Impl(bool use_sockets) {
// Flip this property to test in-process vs out-of-process for the prefetcher code.
@@ -122,12 +171,15 @@
std::unique_ptr<SessionManager> session_manager_;
SessionKind session_kind_;
std::unordered_map<size_t /*task index*/, TaskData> read_ahead_file_map_;
+ static RecentDataKeeper recent_data_keeper_;
bool UseSockets() const {
return session_kind_ == SessionKind::kOutOfProcessSocket;
}
};
+RecentDataKeeper ReadAhead::Impl::recent_data_keeper_{};
+
ReadAhead::ReadAhead() : ReadAhead(/*use_sockets*/false) {
}
@@ -279,6 +331,7 @@
// Go through every trace entry and readahead every (file,offset,len) tuple.
+ size_t length_sum = 0;
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()) {
@@ -295,12 +348,45 @@
// TODO: Do we need below at all? The always-on Dump already prints a % of failed entries.
// LOG(WARNING) << "Failed readahead, bad file length/offset in entry @ " << (entry_offset - 1);
}
+
+ length_sum += static_cast<size_t>(file_entry.file_length());
}
// TODO: maybe getprop and a single line by default?
session->Dump(LOG_STREAM(INFO), /*multiline*/true);
impl_->read_ahead_file_map_[id.id] = std::move(task_data);
+
+ ReadAhead::Impl::recent_data_keeper_.RecordRecent(id, length_sum);
+}
+
+void ReadAhead::Dump(::android::Printer& printer) {
+ ReadAhead::Impl::recent_data_keeper_.Dump(printer);
+}
+
+std::optional<size_t> ReadAhead::PrefetchSizeInBytes(const std::string& file_path) {
+ serialize::ArenaPtr<serialize::proto::TraceFile> trace_file_ptr =
+ serialize::ProtobufIO::Open(file_path);
+
+ if (trace_file_ptr == nullptr) {
+ LOG(WARNING) << "PrefetchSizeInBytes: bad file at " << file_path;
+ return std::nullopt;
+ }
+
+ size_t length_sum = 0;
+ const serialize::proto::TraceFileList& file_list = trace_file_ptr->list();
+ for (const serialize::proto::TraceFileEntry& file_entry : file_list.entries()) {
+
+ if (file_entry.file_length() < 0 || file_entry.file_offset() < 0) {
+ LOG(WARNING) << "ReadAhead entry negative file length or offset, illegal: "
+ << "index_id=" << file_entry.index_id() << ", skipping";
+ continue;
+ }
+
+ length_sum += static_cast<size_t>(file_entry.file_length());
+ }
+
+ return length_sum;
}
} // namespace prefetcher
diff --git a/src/prefetcher/read_ahead.h b/src/prefetcher/read_ahead.h
index cc267f2..03239b4 100644
--- a/src/prefetcher/read_ahead.h
+++ b/src/prefetcher/read_ahead.h
@@ -16,6 +16,11 @@
#define PREFETCHER_READAHEAD_H_
#include <memory>
+#include <optional>
+
+namespace android {
+class Printer;
+} // namespace android
namespace iorap {
namespace prefetcher {
@@ -36,6 +41,12 @@
// Complete a task, releasing any memory/file descriptors associated with it.
void FinishTask(const TaskId& id);
+ static void Dump(/*borrow*/::android::Printer& printer);
+
+ // Calculate the sum of file_lengths. Returns nullopt if the file path does not
+ // point to a valid compiled TraceFile.
+ static std::optional<size_t> PrefetchSizeInBytes(const std::string& file_path);
+
ReadAhead(bool use_sockets);
ReadAhead();