More diagnostics for slow operations
- Add more watchdogs and more context to metrics retrieval.
- Log first alias when too many keys are listed.
- Drop a couple of superfluous comments.
Bug: 319563050
Bug: 380879713
Test: adb logcat on device with large number of keys
Change-Id: I5484b131e45c5fc1d39810f26104db46cb7aae7a
diff --git a/keystore2/src/database.rs b/keystore2/src/database.rs
index c815622..9f27b5a 100644
--- a/keystore2/src/database.rs
+++ b/keystore2/src/database.rs
@@ -1245,7 +1245,7 @@
/// types that map to a table, information about the table's storage is
/// returned. Requests for storage types that are not DB tables return None.
pub fn get_storage_stat(&mut self, storage_type: MetricsStorage) -> Result<StorageStats> {
- let _wp = wd::watch("KeystoreDB::get_storage_stat");
+ let _wp = wd::watch_millis_with("KeystoreDB::get_storage_stat", 500, storage_type);
match storage_type {
MetricsStorage::DATABASE => self.get_total_size(),
diff --git a/keystore2/src/database/tests.rs b/keystore2/src/database/tests.rs
index 381a45a..4ada694 100644
--- a/keystore2/src/database/tests.rs
+++ b/keystore2/src/database/tests.rs
@@ -2832,6 +2832,7 @@
let batch_size = crate::utils::estimate_safe_amount_to_return(
domain,
namespace,
+ None,
&keys,
crate::utils::RESPONSE_SIZE_LIMIT,
);
diff --git a/keystore2/src/metrics.rs b/keystore2/src/metrics.rs
index 4757739..b884809 100644
--- a/keystore2/src/metrics.rs
+++ b/keystore2/src/metrics.rs
@@ -51,7 +51,7 @@
impl IKeystoreMetrics for Metrics {
fn pullMetrics(&self, atom_id: AtomID) -> BinderResult<Vec<KeystoreAtom>> {
- let _wp = wd::watch("IKeystoreMetrics::pullMetrics");
+ let _wp = wd::watch_millis_with("IKeystoreMetrics::pullMetrics", 500, atom_id);
self.pull_metrics(atom_id).map_err(into_logged_binder)
}
}
diff --git a/keystore2/src/metrics_store.rs b/keystore2/src/metrics_store.rs
index 7149d12..fd1f9b5 100644
--- a/keystore2/src/metrics_store.rs
+++ b/keystore2/src/metrics_store.rs
@@ -22,6 +22,7 @@
use crate::key_parameter::KeyParameterValue as KsKeyParamValue;
use crate::ks_err;
use crate::operation::Outcome;
+use crate::utils::watchdog as wd;
use android_hardware_security_keymint::aidl::android::hardware::security::keymint::{
Algorithm::Algorithm, BlockMode::BlockMode, Digest::Digest, EcCurve::EcCurve,
HardwareAuthenticatorType::HardwareAuthenticatorType, KeyOrigin::KeyOrigin,
@@ -104,11 +105,13 @@
// StorageStats is an original pulled atom (i.e. not a pushed atom converted to a
// pulled atom). Therefore, it is handled separately.
if AtomID::STORAGE_STATS == atom_id {
+ let _wp = wd::watch("MetricsStore::get_atoms calling pull_storage_stats");
return pull_storage_stats();
}
// Process keystore crash stats.
if AtomID::CRASH_STATS == atom_id {
+ let _wp = wd::watch("MetricsStore::get_atoms calling read_keystore_crash_count");
return match read_keystore_crash_count()? {
Some(count) => Ok(vec![KeystoreAtom {
payload: KeystoreAtomPayload::CrashStats(CrashStats {
@@ -120,8 +123,6 @@
};
}
- // It is safe to call unwrap here since the lock can not be poisoned based on its usage
- // in this module and the lock is not acquired in the same thread before.
let metrics_store_guard = self.metrics_store.lock().unwrap();
metrics_store_guard.get(&atom_id).map_or(Ok(Vec::<KeystoreAtom>::new()), |atom_count_map| {
Ok(atom_count_map
@@ -133,8 +134,6 @@
/// Insert an atom object to the metrics_store indexed by the atom ID.
fn insert_atom(&self, atom_id: AtomID, atom: KeystoreAtomPayload) {
- // It is ok to unwrap here since the mutex cannot be poisoned according to the way it is
- // used in this module. And the lock is not acquired by this thread before.
let mut metrics_store_guard = self.metrics_store.lock().unwrap();
let atom_count_map = metrics_store_guard.entry(atom_id).or_default();
if atom_count_map.len() < MetricsStore::SINGLE_ATOM_STORE_MAX_SIZE {
diff --git a/keystore2/src/utils.rs b/keystore2/src/utils.rs
index c6dc11e..35290df 100644
--- a/keystore2/src/utils.rs
+++ b/keystore2/src/utils.rs
@@ -541,39 +541,40 @@
pub(crate) fn estimate_safe_amount_to_return(
domain: Domain,
namespace: i64,
+ start_past_alias: Option<&str>,
key_descriptors: &[KeyDescriptor],
response_size_limit: usize,
) -> usize {
- let mut items_to_return = 0;
- let mut returned_bytes: usize = 0;
+ let mut count = 0;
+ let mut bytes: usize = 0;
// Estimate the transaction size to avoid returning more items than what
// could fit in a binder transaction.
for kd in key_descriptors.iter() {
// 4 bytes for the Domain enum
// 8 bytes for the Namespace long.
- returned_bytes += 4 + 8;
+ bytes += 4 + 8;
// Size of the alias string. Includes 4 bytes for length encoding.
if let Some(alias) = &kd.alias {
- returned_bytes += 4 + alias.len();
+ bytes += 4 + alias.len();
}
// Size of the blob. Includes 4 bytes for length encoding.
if let Some(blob) = &kd.blob {
- returned_bytes += 4 + blob.len();
+ bytes += 4 + blob.len();
}
// The binder transaction size limit is 1M. Empirical measurements show
// that the binder overhead is 60% (to be confirmed). So break after
// 350KB and return a partial list.
- if returned_bytes > response_size_limit {
+ if bytes > response_size_limit {
log::warn!(
- "{domain:?}:{namespace}: Key descriptors list ({} items) may exceed binder \
- size, returning {items_to_return} items est {returned_bytes} bytes.",
+ "{domain:?}:{namespace}: Key descriptors list ({} items after {start_past_alias:?}) \
+ may exceed binder size, returning {count} items est. {bytes} bytes",
key_descriptors.len(),
);
break;
}
- items_to_return += 1;
+ count += 1;
}
- items_to_return
+ count
}
/// Estimate for maximum size of a Binder response in bytes.
@@ -602,8 +603,13 @@
start_past_alias,
);
- let safe_amount_to_return =
- estimate_safe_amount_to_return(domain, namespace, &merged_key_entries, RESPONSE_SIZE_LIMIT);
+ let safe_amount_to_return = estimate_safe_amount_to_return(
+ domain,
+ namespace,
+ start_past_alias,
+ &merged_key_entries,
+ RESPONSE_SIZE_LIMIT,
+ );
Ok(merged_key_entries[..safe_amount_to_return].to_vec())
}
diff --git a/keystore2/src/utils/tests.rs b/keystore2/src/utils/tests.rs
index 618ea47..e514b2a 100644
--- a/keystore2/src/utils/tests.rs
+++ b/keystore2/src/utils/tests.rs
@@ -53,9 +53,9 @@
let key_aliases = vec!["key1", "key2", "key3"];
let key_descriptors = create_key_descriptors_from_aliases(&key_aliases);
- assert_eq!(estimate_safe_amount_to_return(Domain::APP, 1017, &key_descriptors, 20), 1);
- assert_eq!(estimate_safe_amount_to_return(Domain::APP, 1017, &key_descriptors, 50), 2);
- assert_eq!(estimate_safe_amount_to_return(Domain::APP, 1017, &key_descriptors, 100), 3);
+ assert_eq!(estimate_safe_amount_to_return(Domain::APP, 1017, None, &key_descriptors, 20), 1);
+ assert_eq!(estimate_safe_amount_to_return(Domain::APP, 1017, None, &key_descriptors, 50), 2);
+ assert_eq!(estimate_safe_amount_to_return(Domain::APP, 1017, None, &key_descriptors, 100), 3);
Ok(())
}