hps: Log a metric for boot time
Log a metric for successful and failed boots, recording the time taken.
BUG=b:194251526
TEST=env FEATURES=test emerge-amd64-generic hpsd
TEST=hps boot ; chrome://histograms/HPS
Change-Id: I95e94dcf69fdf3a6ec65a18852183990cf46eb94
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform2/+/3397559
Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
Reviewed-by: Jakub Młynarczyk <jakubm@chromium.org>
Tested-by: Evan Benn <evanbenn@chromium.org>
Commit-Queue: Evan Benn <evanbenn@chromium.org>
diff --git a/hps/hps_impl.cc b/hps/hps_impl.cc
index 4aedaeb..50687c2 100644
--- a/hps/hps_impl.cc
+++ b/hps/hps_impl.cc
@@ -69,6 +69,7 @@
this->Reboot();
+ this->boot_start_time_ = base::TimeTicks::Now();
// If the boot process sent an update, reboot and try again
// A full update takes 3 boots, so try 3 times.
for (int i = 0; i < 3; ++i) {
@@ -224,7 +225,9 @@
<< "ms";
return true;
} else {
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kBadMagic);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kBadMagic,
+ base::TimeTicks::Now() - this->boot_start_time_);
LOG(FATAL) << base::StringPrintf("Bad magic number 0x%04x",
magic.value());
return false;
@@ -242,7 +245,9 @@
// Else return BootResult::kFail.
hps::HPS_impl::BootResult HPS_impl::CheckStage0() {
if (!CheckMagic()) {
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kNoResponse);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kNoResponse,
+ base::TimeTicks::Now() - this->boot_start_time_);
return BootResult::kFail;
}
@@ -254,7 +259,7 @@
}
if (status.value() & R2::kFault || !(status.value() & R2::kOK)) {
- this->Fault();
+ this->OnBootFault();
return BootResult::kFail;
}
@@ -274,7 +279,9 @@
if (!this->write_protect_off_ && !(status.value() & R2::kStage1Verified)) {
// Stage1 not verified, so need to update it.
LOG(INFO) << "Stage1 flash not verified";
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kMcuNotVerified);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kMcuNotVerified,
+ base::TimeTicks::Now() - this->boot_start_time_);
return BootResult::kUpdate;
}
@@ -298,7 +305,9 @@
// Versions do not match, need to update.
LOG(INFO) << "Stage1 version mismatch, module: " << version
<< " expected: " << this->stage1_version_;
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kMcuVersionMismatch);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kMcuVersionMismatch,
+ base::TimeTicks::Now() - this->boot_start_time_);
return BootResult::kUpdate;
}
}
@@ -311,7 +320,9 @@
// Else return BootResult::kFail.
hps::HPS_impl::BootResult HPS_impl::CheckStage1() {
if (!CheckMagic()) {
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kStage1NotStarted);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kStage1NotStarted,
+ base::TimeTicks::Now() - this->boot_start_time_);
return BootResult::kFail;
}
@@ -323,12 +334,14 @@
}
if (status.value() & R2::kFault || !(status.value() & R2::kOK)) {
- this->Fault();
+ this->OnBootFault();
return BootResult::kFail;
}
if (!(status.value() & R2::kStage1)) {
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kStage1NotStarted);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kStage1NotStarted,
+ base::TimeTicks::Now() - this->boot_start_time_);
LOG(FATAL) << "Stage 1 did not start";
return BootResult::kFail;
}
@@ -354,7 +367,9 @@
if (status.value() & R2::kAppl) {
VLOG(1) << "Application boot after " << timer.Elapsed().InMilliseconds()
<< "ms";
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kSuccess);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kSuccess,
+ base::TimeTicks::Now() - this->boot_start_time_);
return BootResult::kOk;
}
@@ -367,17 +382,21 @@
if (error.value() & RError::kSpiNotVer) {
VLOG(1) << "SPI verification failed after "
<< timer.Elapsed().InMilliseconds() << "ms";
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kSpiNotVerified);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kSpiNotVerified,
+ base::TimeTicks::Now() - this->boot_start_time_);
return BootResult::kUpdate;
} else if (error.value()) {
- this->Fault();
+ this->OnBootFault();
return BootResult::kFail;
}
Sleep(kApplSleep);
} while (timer.Elapsed() < kApplTimeout);
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kApplNotStarted);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kApplNotStarted,
+ base::TimeTicks::Now() - this->boot_start_time_);
LOG(FATAL) << "Application did not start";
return BootResult::kFail;
}
@@ -392,9 +411,11 @@
return true;
}
-// Fault bit seen, attempt to dump status information
-void HPS_impl::Fault() {
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kFault);
+// Fault bit seen during boot, attempt to dump status information and abort.
+// Only call this function in the boot process.
+void HPS_impl::OnBootFault() {
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kFault, base::TimeTicks::Now() - this->boot_start_time_);
std::optional<uint16_t> errors = this->device_->ReadReg(HpsReg::kError);
if (!errors) {
LOG(FATAL) << "Fault: cause unknown";
@@ -412,7 +433,9 @@
hps_metrics_.SendHpsUpdateDuration(HpsBank::kMcuFlash, timer.Elapsed());
return BootResult::kUpdate;
} else {
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kMcuUpdateFailure);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kMcuUpdateFailure,
+ base::TimeTicks::Now() - this->boot_start_time_);
return BootResult::kFail;
}
}
@@ -427,7 +450,9 @@
hps_metrics_.SendHpsUpdateDuration(HpsBank::kSpiFlash, timer.Elapsed());
return BootResult::kUpdate;
} else {
- hps_metrics_.SendHpsTurnOnResult(HpsTurnOnResult::kSpiUpdateFailure);
+ hps_metrics_.SendHpsTurnOnResult(
+ HpsTurnOnResult::kSpiUpdateFailure,
+ base::TimeTicks::Now() - this->boot_start_time_);
return BootResult::kFail;
}
}
diff --git a/hps/hps_impl.h b/hps/hps_impl.h
index 00817a8..a8fd156 100644
--- a/hps/hps_impl.h
+++ b/hps/hps_impl.h
@@ -72,12 +72,13 @@
BootResult CheckStage1();
BootResult CheckApplication();
bool Reboot();
- void Fault();
+ void OnBootFault();
bool WaitForBankReady(uint8_t bank);
BootResult SendStage1Update();
BootResult SendApplicationUpdate();
bool WriteFile(uint8_t bank, const base::FilePath& source);
std::unique_ptr<DevInterface> device_;
+ base::TimeTicks boot_start_time_;
HpsMetrics hps_metrics_;
uint16_t hw_rev_;
uint32_t stage1_version_;
diff --git a/hps/hps_metrics.cc b/hps/hps_metrics.cc
index 677b976..0f4176b 100644
--- a/hps/hps_metrics.cc
+++ b/hps/hps_metrics.cc
@@ -8,10 +8,39 @@
constexpr int kHpsUpdateMcuMaxDurationMilliSeconds = 60 * 1000;
constexpr int kHpsUpdateSpiMaxDurationMilliSeconds = 40 * 60 * 1000;
+constexpr int kHpsBootMaxDurationMilliSeconds =
+ kHpsUpdateMcuMaxDurationMilliSeconds +
+ kHpsUpdateSpiMaxDurationMilliSeconds + 10 * 60 * 1000;
HpsMetrics::HpsMetrics() : metrics_lib_(std::make_unique<MetricsLibrary>()) {}
-bool HpsMetrics::SendHpsTurnOnResult(HpsTurnOnResult result) {
+bool HpsMetrics::SendHpsTurnOnResult(HpsTurnOnResult result,
+ base::TimeDelta duration) {
+ switch (result) {
+ case HpsTurnOnResult::kSuccess:
+ metrics_lib_->SendToUMA(kHpsBootSuccessDuration,
+ static_cast<int>(duration.InMilliseconds()), 1,
+ kHpsBootMaxDurationMilliSeconds, 50);
+ break;
+ // The kHpsBoot*Duration is only for terminal boot status, (fail or
+ // succeed). So for the 'send an update' results, do not send the duration.
+ case HpsTurnOnResult::kMcuVersionMismatch:
+ case HpsTurnOnResult::kSpiNotVerified:
+ case HpsTurnOnResult::kMcuNotVerified:
+ break;
+ case HpsTurnOnResult::kStage1NotStarted:
+ case HpsTurnOnResult::kApplNotStarted:
+ case HpsTurnOnResult::kNoResponse:
+ case HpsTurnOnResult::kTimeout:
+ case HpsTurnOnResult::kBadMagic:
+ case HpsTurnOnResult::kFault:
+ case HpsTurnOnResult::kMcuUpdateFailure:
+ case HpsTurnOnResult::kSpiUpdateFailure:
+ metrics_lib_->SendToUMA(kHpsBootFailedDuration,
+ static_cast<int>(duration.InMilliseconds()), 1,
+ kHpsBootMaxDurationMilliSeconds, 50);
+ break;
+ }
return metrics_lib_->SendEnumToUMA(hps::kHpsTurnOnResult, result);
}
diff --git a/hps/hps_metrics.h b/hps/hps_metrics.h
index 7c48e02..564199a 100644
--- a/hps/hps_metrics.h
+++ b/hps/hps_metrics.h
@@ -16,6 +16,9 @@
namespace hps {
constexpr char kHpsTurnOnResult[] = "ChromeOS.HPS.TurnOn.Result";
+constexpr char kHpsBootFailedDuration[] = "ChromeOS.HPS.TurnOn.Failed.Duration";
+constexpr char kHpsBootSuccessDuration[] =
+ "ChromeOS.HPS.TurnOn.Success.Duration";
constexpr char kHpsUpdateMcuDuration[] = "ChromeOS.HPS.Update.Mcu.Duration";
constexpr char kHpsUpdateSpiDuration[] = "ChromeOS.HPS.Update.Spi.Duration";
@@ -46,7 +49,7 @@
~HpsMetrics() = default;
- bool SendHpsTurnOnResult(HpsTurnOnResult result);
+ bool SendHpsTurnOnResult(HpsTurnOnResult result, base::TimeDelta duration);
bool SendHpsUpdateDuration(HpsBank bank, base::TimeDelta duration);
void SetMetricsLibraryForTesting(
diff --git a/hps/hps_metrics_test.cc b/hps/hps_metrics_test.cc
index 0a450a6..f5abf6a 100644
--- a/hps/hps_metrics_test.cc
+++ b/hps/hps_metrics_test.cc
@@ -49,11 +49,36 @@
ASSERT_EQ(all_results.size(),
static_cast<int>(HpsTurnOnResult::kMaxValue) + 1);
+ constexpr int kDuration = 49;
for (auto result : all_results) {
+ switch (result) {
+ case HpsTurnOnResult::kSuccess:
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootSuccessDuration, kDuration, _, _, _))
+ .Times(1);
+ break;
+ case HpsTurnOnResult::kMcuVersionMismatch:
+ case HpsTurnOnResult::kSpiNotVerified:
+ case HpsTurnOnResult::kMcuNotVerified:
+ break;
+ case HpsTurnOnResult::kStage1NotStarted:
+ case HpsTurnOnResult::kApplNotStarted:
+ case HpsTurnOnResult::kNoResponse:
+ case HpsTurnOnResult::kTimeout:
+ case HpsTurnOnResult::kBadMagic:
+ case HpsTurnOnResult::kFault:
+ case HpsTurnOnResult::kMcuUpdateFailure:
+ case HpsTurnOnResult::kSpiUpdateFailure:
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootFailedDuration, kDuration, _, _, _))
+ .Times(1);
+ break;
+ }
EXPECT_CALL(*GetMetricsLibraryMock(),
SendEnumToUMA(kHpsTurnOnResult, static_cast<int>(result), _))
.Times(1);
- hps_metrics_.SendHpsTurnOnResult(result);
+ hps_metrics_.SendHpsTurnOnResult(
+ result, base::TimeDelta::FromMilliseconds(kDuration));
}
}
diff --git a/hps/hps_test.cc b/hps/hps_test.cc
index c5aacef..ba2da9e 100644
--- a/hps/hps_test.cc
+++ b/hps/hps_test.cc
@@ -289,6 +289,9 @@
hps_->Init(version, mcu, spi1, spi2);
// Boot the module.
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootSuccessDuration, _, _, _, _))
+ .Times(1);
EXPECT_CALL(
*GetMetricsLibraryMock(),
SendEnumToUMA(hps::kHpsTurnOnResult,
@@ -323,6 +326,9 @@
hps_->Init(version, mcu, spi1, spi2);
// Boot the module.
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootSuccessDuration, _, _, _, _))
+ .Times(2);
EXPECT_CALL(
*GetMetricsLibraryMock(),
SendEnumToUMA(hps::kHpsTurnOnResult,
@@ -363,6 +369,9 @@
EXPECT_CALL(*GetMetricsLibraryMock(),
SendToUMA(hps::kHpsUpdateMcuDuration, _, _, _, _))
.Times(1);
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootSuccessDuration, _, _, _, _))
+ .Times(1);
EXPECT_CALL(
*GetMetricsLibraryMock(),
SendEnumToUMA(hps::kHpsTurnOnResult,
@@ -409,6 +418,9 @@
EXPECT_CALL(*GetMetricsLibraryMock(),
SendToUMA(hps::kHpsUpdateSpiDuration, _, _, _, _))
.Times(1);
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootSuccessDuration, _, _, _, _))
+ .Times(1);
EXPECT_CALL(
*GetMetricsLibraryMock(),
SendEnumToUMA(hps::kHpsTurnOnResult,
@@ -467,6 +479,9 @@
EXPECT_CALL(*GetMetricsLibraryMock(),
SendToUMA(hps::kHpsUpdateSpiDuration, _, _, _, _))
.Times(1);
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootSuccessDuration, _, _, _, _))
+ .Times(1);
EXPECT_CALL(
*GetMetricsLibraryMock(),
SendEnumToUMA(hps::kHpsTurnOnResult,
@@ -506,6 +521,9 @@
hps_->Init(version, mcu, spi1, spi2);
// Boot the module.
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootSuccessDuration, _, _, _, _))
+ .Times(1);
EXPECT_CALL(
*GetMetricsLibraryMock(),
SendEnumToUMA(hps::kHpsTurnOnResult,
@@ -556,6 +574,9 @@
EXPECT_CALL(*GetMetricsLibraryMock(),
SendToUMA(hps::kHpsUpdateMcuDuration, _, _, _, _))
.Times(1);
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootSuccessDuration, _, _, _, _))
+ .Times(1);
EXPECT_CALL(
*GetMetricsLibraryMock(),
SendEnumToUMA(hps::kHpsTurnOnResult,
@@ -613,6 +634,9 @@
EXPECT_CALL(*GetMetricsLibraryMock(),
SendToUMA(hps::kHpsUpdateSpiDuration, _, _, _, _))
.Times(1);
+ EXPECT_CALL(*GetMetricsLibraryMock(),
+ SendToUMA(kHpsBootSuccessDuration, _, _, _, _))
+ .Times(1);
EXPECT_CALL(
*GetMetricsLibraryMock(),
SendEnumToUMA(hps::kHpsTurnOnResult,
