[incremental] report new metrics from Incremental Service

BUG: 184844615
Test: atest service.incremental_test
Change-Id: Ibbfe68851a4adfd620db9652f1fda550a3c6fb2c
This commit is contained in:
Songchun Fan
2021-05-03 17:13:52 -07:00
parent d48a25ee64
commit 0dc7772746
5 changed files with 207 additions and 23 deletions

View File

@@ -186,7 +186,30 @@ interface IIncrementalService {
* 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";
/**
* Metrics key for total count of delayed reads caused by pending reads. The value is an int.
*/
const @utf8InCpp String METRICS_TOTAL_DELAYED_READS = "totalDelayedReads";
/**
* Metrics key for total count of delayed reads caused by pending reads. The value is an int.
*/
const @utf8InCpp String METRICS_TOTAL_DELAYED_READS_MILLIS = "totalDelayedReadsMillis";
/**
* Metrics key for total count of failed reads. The value is an int.
*/
const @utf8InCpp String METRICS_TOTAL_FAILED_READS = "totalFailedReads";
/**
* Metrics key for the uid of the last read error. The value is an int.
*/
const @utf8InCpp String METRICS_LAST_READ_ERROR_UID = "lastReadErrorUid";
/**
* Metrics key for duration in milliseconds since the last read error. The value is a long.
*/
const @utf8InCpp String METRICS_MILLIS_SINCE_LAST_READ_ERROR = "millisSinceLastReadError";
/**
* Metrics key for the error number of the last read error. The value is an int.
*/
const @utf8InCpp String METRICS_LAST_READ_ERROR_NUMBER = "lastReadErrorNo";
/**
* Return a bundle containing the requested metrics keys and their values.
*/

View File

@@ -71,4 +71,46 @@ public class IncrementalMetrics {
public long getDataLoaderBindDelayMillis() {
return mData.getLong(IIncrementalService.METRICS_DATA_LOADER_BIND_DELAY_MILLIS, -1);
}
/**
* @return total count of delayed reads caused by pending reads
*/
public int getTotalDelayedReads() {
return mData.getInt(IIncrementalService.METRICS_TOTAL_DELAYED_READS, -1);
}
/**
* @return total count of failed reads
*/
public int getTotalFailedReads() {
return mData.getInt(IIncrementalService.METRICS_TOTAL_FAILED_READS, -1);
}
/**
* @return total duration in milliseconds of delayed reads
*/
public long getTotalDelayedReadsDurationMillis() {
return mData.getInt(IIncrementalService.METRICS_TOTAL_DELAYED_READS_MILLIS, -1);
}
/**
* @return the uid of the last read error
*/
public int getLastReadErrorUid() {
return mData.getInt(IIncrementalService.METRICS_LAST_READ_ERROR_UID, -1);
}
/**
* @return duration in milliseconds since the last read error
*/
public long getMillisSinceLastReadError() {
return mData.getLong(IIncrementalService.METRICS_MILLIS_SINCE_LAST_READ_ERROR, -1);
}
/**
* @return the error number of the last read error
*/
public int getLastReadErrorNumber() {
return mData.getInt(IIncrementalService.METRICS_LAST_READ_ERROR_NUMBER, -1);
}
}

View File

@@ -391,16 +391,14 @@ static const char* toString(IncrementalService::BindKind kind) {
}
template <class Duration>
static long elapsedMcs(Duration start, Duration end) {
static int64_t elapsedMcs(Duration start, Duration end) {
return std::chrono::duration_cast<std::chrono::microseconds>(end - start).count();
}
static uint64_t elapsedUsSinceMonoTs(uint64_t monoTsUs) {
timespec now;
if (clock_gettime(CLOCK_MONOTONIC, &now) != 0) {
return 0;
}
uint64_t nowUs = now.tv_sec * 1000000LL + now.tv_nsec / 1000;
int64_t IncrementalService::elapsedUsSinceMonoTs(uint64_t monoTsUs) {
const auto now = mClock->now();
const auto nowUs = static_cast<uint64_t>(
duration_cast<std::chrono::microseconds>(now.time_since_epoch()).count());
return nowUs - monoTsUs;
}
@@ -2450,10 +2448,37 @@ void IncrementalService::getMetrics(StorageId storageId, android::os::Persistabl
LOG(ERROR) << "getMetrics failed, invalid storageId: " << storageId;
return;
}
const auto kMetricsReadLogsEnabled =
const auto& kMetricsReadLogsEnabled =
os::incremental::BnIncrementalService::METRICS_READ_LOGS_ENABLED();
result->putBoolean(String16(kMetricsReadLogsEnabled.data()), ifs->readLogsEnabled() != 0);
result->putBoolean(String16(kMetricsReadLogsEnabled.c_str()), ifs->readLogsEnabled() != 0);
const auto incfsMetrics = mIncFs->getMetrics(path::basename(ifs->root));
if (incfsMetrics) {
const auto& kMetricsTotalDelayedReads =
os::incremental::BnIncrementalService::METRICS_TOTAL_DELAYED_READS();
const auto totalDelayedReads =
incfsMetrics->readsDelayedMin + incfsMetrics->readsDelayedPending;
result->putInt(String16(kMetricsTotalDelayedReads.c_str()), totalDelayedReads);
const auto& kMetricsTotalFailedReads =
os::incremental::BnIncrementalService::METRICS_TOTAL_FAILED_READS();
const auto totalFailedReads = incfsMetrics->readsFailedTimedOut +
incfsMetrics->readsFailedHashVerification + incfsMetrics->readsFailedOther;
result->putInt(String16(kMetricsTotalFailedReads.c_str()), totalFailedReads);
const auto& kMetricsTotalDelayedReadsMillis =
os::incremental::BnIncrementalService::METRICS_TOTAL_DELAYED_READS_MILLIS();
const int64_t totalDelayedReadsMillis =
(incfsMetrics->readsDelayedMinUs + incfsMetrics->readsDelayedPendingUs) / 1000;
result->putLong(String16(kMetricsTotalDelayedReadsMillis.c_str()), totalDelayedReadsMillis);
}
const auto lastReadError = mIncFs->getLastReadError(ifs->control);
if (lastReadError && lastReadError->timestampUs != 0) {
const auto& kMetricsMillisSinceLastReadError =
os::incremental::BnIncrementalService::METRICS_MILLIS_SINCE_LAST_READ_ERROR();
result->putLong(String16(kMetricsMillisSinceLastReadError.c_str()),
(int64_t)elapsedUsSinceMonoTs(lastReadError->timestampUs) / 1000);
const auto& kMetricsLastReadErrorNo =
os::incremental::BnIncrementalService::METRICS_LAST_READ_ERROR_NUMBER();
result->putInt(String16(kMetricsLastReadErrorNo.c_str()), lastReadError->errorNo);
}
std::unique_lock l(ifs->lock);
if (!ifs->dataLoaderStub) {
return;
@@ -2998,24 +3023,24 @@ BootClockTsUs IncrementalService::DataLoaderStub::getOldestTsFromLastPendingRead
void IncrementalService::DataLoaderStub::getMetrics(android::os::PersistableBundle* result) {
const auto duration = elapsedMsSinceOldestPendingRead();
if (duration >= 0) {
const auto kMetricsMillisSinceOldestPendingRead =
const auto& kMetricsMillisSinceOldestPendingRead =
os::incremental::BnIncrementalService::METRICS_MILLIS_SINCE_OLDEST_PENDING_READ();
result->putLong(String16(kMetricsMillisSinceOldestPendingRead.data()), duration);
result->putLong(String16(kMetricsMillisSinceOldestPendingRead.c_str()), duration);
}
const auto kMetricsStorageHealthStatusCode =
const auto& kMetricsStorageHealthStatusCode =
os::incremental::BnIncrementalService::METRICS_STORAGE_HEALTH_STATUS_CODE();
result->putInt(String16(kMetricsStorageHealthStatusCode.data()), mHealthStatus);
const auto kMetricsDataLoaderStatusCode =
result->putInt(String16(kMetricsStorageHealthStatusCode.c_str()), mHealthStatus);
const auto& kMetricsDataLoaderStatusCode =
os::incremental::BnIncrementalService::METRICS_DATA_LOADER_STATUS_CODE();
result->putInt(String16(kMetricsDataLoaderStatusCode.data()), mCurrentStatus);
const auto kMetricsMillisSinceLastDataLoaderBind =
result->putInt(String16(kMetricsDataLoaderStatusCode.c_str()), 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 =
result->putLong(String16(kMetricsMillisSinceLastDataLoaderBind.c_str()),
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()));
result->putLong(String16(kMetricsDataLoaderBindDelayMillis.c_str()),
mPreviousBindDelay.count());
}
long IncrementalService::DataLoaderStub::elapsedMsSinceOldestPendingRead() {

View File

@@ -472,6 +472,7 @@ private:
StorageLoadingProgressListener&& progressListener);
void trimReservedSpaceV1(const IncFsMount& ifs);
int64_t elapsedUsSinceMonoTs(uint64_t monoTsUs);
private:
const std::unique_ptr<VoldServiceWrapper> mVold;

View File

@@ -635,6 +635,14 @@ public:
void advanceMs(int deltaMs) { mClock += std::chrono::milliseconds(deltaMs); }
TimePoint getClock() const { return mClock; }
std::optional<timespec> getClockMono() const {
const auto nsSinceEpoch =
std::chrono::duration_cast<std::chrono::nanoseconds>(mClock.time_since_epoch())
.count();
timespec ts = {.tv_sec = static_cast<time_t>(nsSinceEpoch / 1000000000LL),
.tv_nsec = static_cast<long>(nsSinceEpoch % 1000000000LL)};
return ts;
}
TimePoint mClock = Clock::now();
};
@@ -2203,4 +2211,89 @@ TEST_F(IncrementalServiceTest, testInvalidMetricsKeys) {
ASSERT_EQ(6, (int)result.size());
}
TEST_F(IncrementalServiceTest, testMetricsWithNoLastReadError) {
mVold->setIncFsMountOptionsSuccess();
ON_CALL(*mIncFs, getMetrics(_))
.WillByDefault(Return(Metrics{
.readsDelayedMin = 10,
.readsDelayedMinUs = 5000,
.readsDelayedPending = 10,
.readsDelayedPendingUs = 5000,
.readsFailedHashVerification = 10,
.readsFailedOther = 10,
.readsFailedTimedOut = 10,
}));
ON_CALL(*mIncFs, getLastReadError(_)).WillByDefault(Return(LastReadError{}));
TemporaryDir tempDir;
int storageId =
mIncrementalService->createStorage(tempDir.path, mDataLoaderParcel,
IncrementalService::CreateOptions::CreateNew);
ASSERT_GE(storageId, 0);
ASSERT_TRUE(mIncrementalService->startLoading(storageId, std::move(mDataLoaderParcel), {}, {},
{}, {}));
android::os::PersistableBundle result{};
mIncrementalService->getMetrics(storageId, &result);
ASSERT_EQ(9, (int)result.size());
int expectedtotalDelayedReads = 20, totalDelayedReads = -1;
ASSERT_TRUE(result.getInt(String16(BnIncrementalService::METRICS_TOTAL_DELAYED_READS().c_str()),
&totalDelayedReads));
ASSERT_EQ(expectedtotalDelayedReads, totalDelayedReads);
int expectedtotalFailedReads = 30, totalFailedReads = -1;
ASSERT_TRUE(result.getInt(String16(BnIncrementalService::METRICS_TOTAL_FAILED_READS().c_str()),
&totalFailedReads));
ASSERT_EQ(expectedtotalFailedReads, totalFailedReads);
int64_t expectedtotalDelayedReadsMillis = 10, totalDelayedReadsMillis = -1;
ASSERT_TRUE(result.getLong(String16(BnIncrementalService::METRICS_TOTAL_DELAYED_READS_MILLIS()
.c_str()),
&totalDelayedReadsMillis));
ASSERT_EQ(expectedtotalDelayedReadsMillis, totalDelayedReadsMillis);
int64_t expectedMillisSinceLastReadError = -1, millisSinceLastReadError = -1;
ASSERT_FALSE(
result.getLong(String16(BnIncrementalService::METRICS_MILLIS_SINCE_LAST_READ_ERROR()
.c_str()),
&millisSinceLastReadError));
ASSERT_EQ(expectedMillisSinceLastReadError, millisSinceLastReadError);
int expectedLastReadErrorNumber = -1, lastReadErrorNumber = -1;
ASSERT_FALSE(
result.getInt(String16(BnIncrementalService::METRICS_LAST_READ_ERROR_NUMBER().c_str()),
&lastReadErrorNumber));
ASSERT_EQ(expectedLastReadErrorNumber, lastReadErrorNumber);
}
TEST_F(IncrementalServiceTest, testMetricsWithLastReadError) {
mVold->setIncFsMountOptionsSuccess();
ON_CALL(*mIncFs, getMetrics(_)).WillByDefault(Return(Metrics{}));
mClock->advanceMs(5);
const auto now = mClock->getClock();
ON_CALL(*mIncFs, getLastReadError(_))
.WillByDefault(Return(LastReadError{.timestampUs = static_cast<uint64_t>(
duration_cast<std::chrono::microseconds>(
now.time_since_epoch())
.count()),
.errorNo = static_cast<uint32_t>(-ETIME)}));
TemporaryDir tempDir;
int storageId =
mIncrementalService->createStorage(tempDir.path, mDataLoaderParcel,
IncrementalService::CreateOptions::CreateNew);
ASSERT_GE(storageId, 0);
ASSERT_TRUE(mIncrementalService->startLoading(storageId, std::move(mDataLoaderParcel), {}, {},
{}, {}));
mClock->advanceMs(10);
android::os::PersistableBundle result{};
mIncrementalService->getMetrics(storageId, &result);
ASSERT_EQ(11, (int)result.size());
int64_t expectedMillisSinceLastReadError = 10, millisSinceLastReadError = -1;
ASSERT_TRUE(result.getLong(String16(BnIncrementalService::METRICS_MILLIS_SINCE_LAST_READ_ERROR()
.c_str()),
&millisSinceLastReadError));
ASSERT_EQ(expectedMillisSinceLastReadError, millisSinceLastReadError);
int expectedLastReadErrorNumber = -ETIME, lastReadErrorNumber = -1;
ASSERT_TRUE(
result.getInt(String16(BnIncrementalService::METRICS_LAST_READ_ERROR_NUMBER().c_str()),
&lastReadErrorNumber));
ASSERT_EQ(expectedLastReadErrorNumber, lastReadErrorNumber);
}
} // namespace android::os::incremental