[incremental] expose more metrics fields

Exposing more data loader states as per
go/incremental-crash-reports-1-pager.

BUG: 184844615
Test: atest service.incremental_test
Test: atest android.cts.statsdatom.incremental.AppErrorAtomTests
Change-Id: I532513453411b2ccdb21311d0bc3dee0641837db
This commit is contained in:
Songchun Fan
2021-04-21 17:49:27 -07:00
parent 2ee0270cba
commit 9471be56b4
5 changed files with 164 additions and 30 deletions

View File

@@ -166,6 +166,27 @@ interface IIncrementalService {
* Metrics key for the duration in milliseconds between now and the oldest pending read. The value is a long.
*/
const @utf8InCpp String METRICS_MILLIS_SINCE_OLDEST_PENDING_READ = "millisSinceOldestPendingRead";
/**
* Metrics key for whether read logs are enabled. The value is a boolean.
*/
const @utf8InCpp String METRICS_READ_LOGS_ENABLED = "readLogsEnabled";
/**
* Metrics key for the storage health status. The value is an int.
*/
const @utf8InCpp String METRICS_STORAGE_HEALTH_STATUS_CODE = "storageHealthStatusCode";
/**
* Metrics key for the data loader status. The value is an int.
*/
const @utf8InCpp String METRICS_DATA_LOADER_STATUS_CODE = "dataLoaderStatusCode";
/**
* Metrics key for duration since last data loader binding attempt. The value is a long.
*/
const @utf8InCpp String METRICS_MILLIS_SINCE_LAST_DATA_LOADER_BIND = "millisSinceLastDataLoaderBind";
/**
* Metrics key for delay in milliseconds to retry data loader binding. The value is a long.
*/
const @utf8InCpp String METRICS_DATA_LOADER_BIND_DELAY_MILLIS = "dataLoaderBindDelayMillis";
/**
* Return a bundle containing the requested metrics keys and their values.
*/

View File

@@ -36,4 +36,39 @@ public class IncrementalMetrics {
public long getMillisSinceOldestPendingRead() {
return mData.getLong(IIncrementalService.METRICS_MILLIS_SINCE_OLDEST_PENDING_READ, -1);
}
/**
* @return Whether read logs are enabled
*/
public boolean getReadLogsEnabled() {
return mData.getBoolean(IIncrementalService.METRICS_READ_LOGS_ENABLED, false);
}
/**
* @return storage health status code. @see android.os.incremental.IStorageHealthListener
*/
public int getStorageHealthStatusCode() {
return mData.getInt(IIncrementalService.METRICS_STORAGE_HEALTH_STATUS_CODE, -1);
}
/**
* @return data loader status code. @see android.content.pm.IDataLoaderStatusListener
*/
public int getDataLoaderStatusCode() {
return mData.getInt(IIncrementalService.METRICS_DATA_LOADER_STATUS_CODE, -1);
}
/**
* @return duration since last data loader binding attempt
*/
public long getMillisSinceLastDataLoaderBind() {
return mData.getLong(IIncrementalService.METRICS_MILLIS_SINCE_LAST_DATA_LOADER_BIND, -1);
}
/**
* @return delay in milliseconds to retry data loader binding
*/
public long getDataLoaderBindDelayMillis() {
return mData.getLong(IIncrementalService.METRICS_DATA_LOADER_BIND_DELAY_MILLIS, -1);
}
}

View File

@@ -2394,26 +2394,20 @@ void IncrementalService::removeIfsStateCallbacks(StorageId storageId) {
}
void IncrementalService::getMetrics(StorageId storageId, android::os::PersistableBundle* result) {
const auto duration = getMillsSinceOldestPendingRead(storageId);
if (duration >= 0) {
const auto kMetricsMillisSinceOldestPendingRead =
os::incremental::BnIncrementalService::METRICS_MILLIS_SINCE_OLDEST_PENDING_READ();
result->putLong(String16(kMetricsMillisSinceOldestPendingRead.data()), duration);
}
}
long IncrementalService::getMillsSinceOldestPendingRead(StorageId storageId) {
const auto ifs = getIfs(storageId);
if (!ifs) {
LOG(ERROR) << "getMillsSinceOldestPendingRead failed, invalid storageId: " << storageId;
return -EINVAL;
LOG(ERROR) << "getMetrics failed, invalid storageId: " << storageId;
return;
}
const auto kMetricsReadLogsEnabled =
os::incremental::BnIncrementalService::METRICS_READ_LOGS_ENABLED();
result->putBoolean(String16(kMetricsReadLogsEnabled.data()), ifs->readLogsEnabled() != 0);
std::unique_lock l(ifs->lock);
if (!ifs->dataLoaderStub) {
LOG(ERROR) << "getMillsSinceOldestPendingRead failed, no data loader: " << storageId;
return -EINVAL;
return;
}
return ifs->dataLoaderStub->elapsedMsSinceOldestPendingRead();
ifs->dataLoaderStub->getMetrics(result);
}
IncrementalService::DataLoaderStub::DataLoaderStub(
@@ -2767,6 +2761,7 @@ void IncrementalService::DataLoaderStub::onHealthStatus(const StorageHealthListe
if (healthListener) {
healthListener->onHealthStatus(id(), healthStatus);
}
mHealthStatus = healthStatus;
}
void IncrementalService::DataLoaderStub::updateHealthStatus(bool baseline) {
@@ -2938,6 +2933,29 @@ BootClockTsUs IncrementalService::DataLoaderStub::getOldestTsFromLastPendingRead
return result;
}
void IncrementalService::DataLoaderStub::getMetrics(android::os::PersistableBundle* result) {
const auto duration = elapsedMsSinceOldestPendingRead();
if (duration >= 0) {
const auto kMetricsMillisSinceOldestPendingRead =
os::incremental::BnIncrementalService::METRICS_MILLIS_SINCE_OLDEST_PENDING_READ();
result->putLong(String16(kMetricsMillisSinceOldestPendingRead.data()), duration);
}
const auto kMetricsStorageHealthStatusCode =
os::incremental::BnIncrementalService::METRICS_STORAGE_HEALTH_STATUS_CODE();
result->putInt(String16(kMetricsStorageHealthStatusCode.data()), mHealthStatus);
const auto kMetricsDataLoaderStatusCode =
os::incremental::BnIncrementalService::METRICS_DATA_LOADER_STATUS_CODE();
result->putInt(String16(kMetricsDataLoaderStatusCode.data()), mCurrentStatus);
const auto kMetricsMillisSinceLastDataLoaderBind =
os::incremental::BnIncrementalService::METRICS_MILLIS_SINCE_LAST_DATA_LOADER_BIND();
result->putLong(String16(kMetricsMillisSinceLastDataLoaderBind.data()),
(long)(elapsedMcs(mPreviousBindTs, mService.mClock->now()) / 1000));
const auto kMetricsDataLoaderBindDelayMillis =
os::incremental::BnIncrementalService::METRICS_DATA_LOADER_BIND_DELAY_MILLIS();
result->putLong(String16(kMetricsDataLoaderBindDelayMillis.data()),
(long)(mPreviousBindDelay.count()));
}
long IncrementalService::DataLoaderStub::elapsedMsSinceOldestPendingRead() {
const auto oldestPendingReadKernelTs = getOldestTsFromLastPendingReads();
if (oldestPendingReadKernelTs == kMaxBootClockTsUs) {
@@ -3007,7 +3025,7 @@ void IncrementalService::DataLoaderStub::onDump(int fd) {
dprintf(fd, " bootClockTsUs: %lld\n", (long long)pendingRead.bootClockTsUs);
}
dprintf(fd, " bind: %llds ago (delay: %llds)\n",
(long long)(elapsedMcs(mPreviousBindTs, Clock::now()) / 1000000),
(long long)(elapsedMcs(mPreviousBindTs, mService.mClock->now()) / 1000000),
(long long)(mPreviousBindDelay.count() / 1000));
dprintf(fd, " }\n");
const auto& params = mParams;

View File

@@ -249,7 +249,7 @@ private:
bool isSystemDataLoader() const;
void setHealthListener(const StorageHealthCheckParams& healthCheckParams,
StorageHealthListener&& healthListener);
long elapsedMsSinceOldestPendingRead();
void getMetrics(android::os::PersistableBundle* _aidl_return);
private:
binder::Status onStatusChanged(MountId mount, int newStatus) final;
@@ -281,6 +281,7 @@ private:
BootClockTsUs getOldestPendingReadTs();
BootClockTsUs getOldestTsFromLastPendingReads();
Milliseconds elapsedMsSinceKernelTs(TimePoint now, BootClockTsUs kernelTsUs);
long elapsedMsSinceOldestPendingRead();
// If the stub has to bind to the DL.
// Returns {} if bind operation is already in progress.
@@ -298,6 +299,7 @@ private:
content::pm::FileSystemControlParcel mControl;
DataLoaderStatusListener mStatusListener;
StorageHealthListener mHealthListener;
std::atomic<int> mHealthStatus = IStorageHealthListener::HEALTH_STATUS_OK;
std::condition_variable mStatusCondition;
int mCurrentStatus = content::pm::IDataLoaderStatusListener::DATA_LOADER_DESTROYED;
@@ -468,7 +470,6 @@ private:
bool updateLoadingProgress(int32_t storageId,
StorageLoadingProgressListener&& progressListener);
long getMillsSinceOldestPendingRead(StorageId storage);
void trimReservedSpaceV1(const IncFsMount& ifs);

View File

@@ -775,16 +775,53 @@ public:
mDataLoaderManager->getDataLoaderSuccess();
}
void checkMillisSinceOldestPendingRead(int storageId, long expected) {
void checkHealthMetrics(int storageId, long expectedMillisSinceOldestPendingRead,
int expectedStorageHealthStatusCode) {
android::os::PersistableBundle result{};
mIncrementalService->getMetrics(storageId, &result);
int64_t value = -1;
ASSERT_EQ(6, (int)result.size());
int64_t millisSinceOldestPendingRead = -1;
ASSERT_TRUE(result.getLong(String16(BnIncrementalService::
METRICS_MILLIS_SINCE_OLDEST_PENDING_READ()
.c_str()),
&value));
ASSERT_EQ(expected, value);
ASSERT_EQ(1, (int)result.size());
&millisSinceOldestPendingRead));
ASSERT_EQ(expectedMillisSinceOldestPendingRead, millisSinceOldestPendingRead);
int storageHealthStatusCode = -1;
ASSERT_TRUE(
result.getInt(String16(BnIncrementalService::METRICS_STORAGE_HEALTH_STATUS_CODE()
.c_str()),
&storageHealthStatusCode));
ASSERT_EQ(expectedStorageHealthStatusCode, storageHealthStatusCode);
int dataLoaderStatusCode = -1;
ASSERT_TRUE(result.getInt(String16(BnIncrementalService::METRICS_DATA_LOADER_STATUS_CODE()
.c_str()),
&dataLoaderStatusCode));
ASSERT_EQ(IDataLoaderStatusListener::DATA_LOADER_STARTED, dataLoaderStatusCode);
}
void checkBindingMetrics(int storageId, int64_t expectedMillisSinceLastDataLoaderBind,
int64_t expectedDataLoaderBindDelayMillis) {
android::os::PersistableBundle result{};
mIncrementalService->getMetrics(storageId, &result);
ASSERT_EQ(6, (int)result.size());
int dataLoaderStatus = -1;
ASSERT_TRUE(result.getInt(String16(BnIncrementalService::METRICS_DATA_LOADER_STATUS_CODE()
.c_str()),
&dataLoaderStatus));
ASSERT_EQ(IDataLoaderStatusListener::DATA_LOADER_STARTED, dataLoaderStatus);
int64_t millisSinceLastDataLoaderBind = -1;
ASSERT_TRUE(result.getLong(String16(BnIncrementalService::
METRICS_MILLIS_SINCE_LAST_DATA_LOADER_BIND()
.c_str()),
&millisSinceLastDataLoaderBind));
ASSERT_EQ(expectedMillisSinceLastDataLoaderBind, millisSinceLastDataLoaderBind);
int64_t dataLoaderBindDelayMillis = -1;
ASSERT_TRUE(
result.getLong(String16(
BnIncrementalService::METRICS_DATA_LOADER_BIND_DELAY_MILLIS()
.c_str()),
&dataLoaderBindDelayMillis));
ASSERT_EQ(expectedDataLoaderBindDelayMillis, dataLoaderBindDelayMillis);
}
protected:
@@ -904,38 +941,55 @@ TEST_F(IncrementalServiceTest, testDataLoaderDestroyedAndDelayed) {
ON_CALL(*mDataLoaderManager, bindToDataLoader(_, _, _, _, _))
.WillByDefault(Invoke(mDataLoaderManager,
&MockDataLoaderManager::bindToDataLoaderOkWith1sDelay));
checkBindingMetrics(storageId, 0, 0);
mClock->advanceMs(mDataLoaderManager->bindDelayMs());
checkBindingMetrics(storageId, 0, 0);
mDataLoaderManager->setDataLoaderStatusDestroyed();
ON_CALL(*mDataLoaderManager, bindToDataLoader(_, _, _, _, _))
.WillByDefault(Invoke(mDataLoaderManager,
&MockDataLoaderManager::bindToDataLoaderOkWith10sDelay));
checkBindingMetrics(storageId, 0, mDataLoaderManager->bindDelayMs());
mClock->advanceMs(mDataLoaderManager->bindDelayMs());
checkBindingMetrics(storageId, mDataLoaderManager->bindDelayMs(),
mDataLoaderManager->bindDelayMs());
mDataLoaderManager->setDataLoaderStatusDestroyed();
ON_CALL(*mDataLoaderManager, bindToDataLoader(_, _, _, _, _))
.WillByDefault(Invoke(mDataLoaderManager,
&MockDataLoaderManager::bindToDataLoaderOkWith100sDelay));
checkBindingMetrics(storageId, 0, mDataLoaderManager->bindDelayMs());
mClock->advanceMs(mDataLoaderManager->bindDelayMs());
checkBindingMetrics(storageId, mDataLoaderManager->bindDelayMs(),
mDataLoaderManager->bindDelayMs());
mDataLoaderManager->setDataLoaderStatusDestroyed();
ON_CALL(*mDataLoaderManager, bindToDataLoader(_, _, _, _, _))
.WillByDefault(Invoke(mDataLoaderManager,
&MockDataLoaderManager::bindToDataLoaderOkWith1000sDelay));
checkBindingMetrics(storageId, 0, mDataLoaderManager->bindDelayMs());
mClock->advanceMs(mDataLoaderManager->bindDelayMs());
checkBindingMetrics(storageId, mDataLoaderManager->bindDelayMs(),
mDataLoaderManager->bindDelayMs());
mDataLoaderManager->setDataLoaderStatusDestroyed();
ON_CALL(*mDataLoaderManager, bindToDataLoader(_, _, _, _, _))
.WillByDefault(Invoke(mDataLoaderManager,
&MockDataLoaderManager::bindToDataLoaderOkWith10000sDelay));
checkBindingMetrics(storageId, 0, mDataLoaderManager->bindDelayMs());
// Try the reduced delay, just in case.
mClock->advanceMs(mDataLoaderManager->bindDelayMs() / 2);
checkBindingMetrics(storageId, mDataLoaderManager->bindDelayMs() / 2,
mDataLoaderManager->bindDelayMs());
mDataLoaderManager->setDataLoaderStatusDestroyed();
ON_CALL(*mDataLoaderManager, bindToDataLoader(_, _, _, _, _))
.WillByDefault(Invoke(mDataLoaderManager,
&MockDataLoaderManager::bindToDataLoaderOkWith10000sDelay));
checkBindingMetrics(storageId, 0, mDataLoaderManager->bindDelayMs());
mClock->advanceMs(mDataLoaderManager->bindDelayMs());
checkBindingMetrics(storageId, mDataLoaderManager->bindDelayMs(),
mDataLoaderManager->bindDelayMs());
mDataLoaderManager->setDataLoaderStatusDestroyed();
}
@@ -1218,7 +1272,7 @@ TEST_F(IncrementalServiceTest, testStartDataLoaderUnhealthyStorage) {
ASSERT_NE(nullptr, mLooper->mCallbackData);
ASSERT_EQ(storageId, listener->mStorageId);
ASSERT_EQ(IStorageHealthListener::HEALTH_STATUS_OK, listener->mStatus);
checkMillisSinceOldestPendingRead(storageId, 0);
checkHealthMetrics(storageId, 0, listener->mStatus);
// Looper/epoll callback.
mIncFs->waitForPendingReadsSuccess(kFirstTimestampUs);
@@ -1244,7 +1298,7 @@ TEST_F(IncrementalServiceTest, testStartDataLoaderUnhealthyStorage) {
ASSERT_EQ(nullptr, mLooper->mCallbackData);
ASSERT_EQ(storageId, listener->mStorageId);
ASSERT_EQ(IStorageHealthListener::HEALTH_STATUS_BLOCKED, listener->mStatus);
checkMillisSinceOldestPendingRead(storageId, params.blockedTimeoutMs);
checkHealthMetrics(storageId, params.blockedTimeoutMs, listener->mStatus);
// Timed callback present.
ASSERT_EQ(storageId, mTimedQueue->mId);
@@ -1261,7 +1315,7 @@ TEST_F(IncrementalServiceTest, testStartDataLoaderUnhealthyStorage) {
ASSERT_EQ(nullptr, mLooper->mCallbackData);
ASSERT_EQ(storageId, listener->mStorageId);
ASSERT_EQ(IStorageHealthListener::HEALTH_STATUS_UNHEALTHY, listener->mStatus);
checkMillisSinceOldestPendingRead(storageId, params.unhealthyTimeoutMs);
checkHealthMetrics(storageId, params.unhealthyTimeoutMs, listener->mStatus);
// Timed callback present.
ASSERT_EQ(storageId, mTimedQueue->mId);
@@ -1278,7 +1332,7 @@ TEST_F(IncrementalServiceTest, testStartDataLoaderUnhealthyStorage) {
ASSERT_EQ(nullptr, mLooper->mCallbackData);
ASSERT_EQ(storageId, listener->mStorageId);
ASSERT_EQ(IStorageHealthListener::HEALTH_STATUS_UNHEALTHY, listener->mStatus);
checkMillisSinceOldestPendingRead(storageId, params.unhealthyTimeoutMs);
checkHealthMetrics(storageId, params.unhealthyTimeoutMs, listener->mStatus);
// Timed callback present.
ASSERT_EQ(storageId, mTimedQueue->mId);
@@ -1295,7 +1349,7 @@ TEST_F(IncrementalServiceTest, testStartDataLoaderUnhealthyStorage) {
ASSERT_NE(nullptr, mLooper->mCallbackData);
ASSERT_EQ(storageId, listener->mStorageId);
ASSERT_EQ(IStorageHealthListener::HEALTH_STATUS_OK, listener->mStatus);
checkMillisSinceOldestPendingRead(storageId, 0);
checkHealthMetrics(storageId, 0, listener->mStatus);
}
TEST_F(IncrementalServiceTest, testSetIncFsMountOptionsSuccess) {
@@ -2025,7 +2079,7 @@ TEST_F(IncrementalServiceTest, testInvalidMetricsQuery) {
ASSERT_TRUE(result.empty());
}
TEST_F(IncrementalServiceTest, testNoMetrics) {
TEST_F(IncrementalServiceTest, testNoDataLoaderMetrics) {
mVold->setIncFsMountOptionsSuccess();
TemporaryDir tempDir;
int storageId =
@@ -2040,7 +2094,12 @@ TEST_F(IncrementalServiceTest, testNoMetrics) {
.c_str()),
&value));
ASSERT_EQ(expected, value);
ASSERT_EQ(0, (int)result.size());
ASSERT_EQ(1, (int)result.size());
bool expectedReadLogsEnabled = false;
ASSERT_TRUE(
result.getBoolean(String16(BnIncrementalService::METRICS_READ_LOGS_ENABLED().c_str()),
&expectedReadLogsEnabled));
ASSERT_EQ(mVold->readLogsEnabled(), expectedReadLogsEnabled);
}
TEST_F(IncrementalServiceTest, testInvalidMetricsKeys) {
@@ -2057,7 +2116,7 @@ TEST_F(IncrementalServiceTest, testInvalidMetricsKeys) {
int64_t expected = -1, value = -1;
ASSERT_FALSE(result.getLong(String16("invalid"), &value));
ASSERT_EQ(expected, value);
ASSERT_EQ(1, (int)result.size());
ASSERT_EQ(6, (int)result.size());
}
} // namespace android::os::incremental