shill: Adds UMA for scan-connect time.
This metric covers time from start of scan through end of a successful
connect.
BUG=chromium:245807
TEST=unittest and manual. For manual tests, do the following:
1) reboot your chrome device
b) browse to chrome://histograms
iii) Verify that there's an entry for
"Network.Shill.Wifi.TimeToScanAndConnect"
Change-Id: I3ef3f142c65b2e1d8449cf9b5405c63891261fc2
Reviewed-on: https://gerrit.chromium.org/gerrit/57271
Commit-Queue: Wade Guthrie <wdg@chromium.org>
Reviewed-by: Wade Guthrie <wdg@chromium.org>
Tested-by: Wade Guthrie <wdg@chromium.org>
diff --git a/metrics.cc b/metrics.cc
index 71b4f95..c3d1278 100644
--- a/metrics.cc
+++ b/metrics.cc
@@ -71,6 +71,9 @@
const int Metrics::kMetricTimeToConnectMillisecondsMin = 1;
const int Metrics::kMetricTimeToConnectMillisecondsNumBuckets = 60;
+const char Metrics::kMetricTimeToScanAndConnectMilliseconds[] =
+ "Network.Shill.%s.TimeToScanAndConnect";
+
const char Metrics::kMetricTimeToDropSeconds[] = "Network.Shill.TimeToDrop";;
const int Metrics::kMetricTimeToDropSecondsMax = 8 * 60 * 60; // 8 hours
const int Metrics::kMetricTimeToDropSecondsMin = 1;
@@ -770,6 +773,16 @@
kMetricTimeToConnectMillisecondsMin,
kMetricTimeToConnectMillisecondsMax,
kMetricTimeToConnectMillisecondsNumBuckets));
+ histogram = GetFullMetricName(kMetricTimeToScanAndConnectMilliseconds,
+ technology);
+ device_metrics->scan_connect_timer.reset(
+ new chromeos_metrics::TimerReporter(
+ histogram,
+ kMetricTimeToScanMillisecondsMin,
+ kMetricTimeToScanMillisecondsMax +
+ kMetricTimeToConnectMillisecondsMax,
+ kMetricTimeToScanMillisecondsNumBuckets +
+ kMetricTimeToConnectMillisecondsNumBuckets));
device_metrics->auto_connect_timer.reset(
new chromeos_metrics::TimerReporter(
kMetricCellularAutoConnectTotalTime,
@@ -840,6 +853,7 @@
if (device_metrics == NULL)
return;
device_metrics->scan_timer->Start();
+ device_metrics->scan_connect_timer->Start();
}
void Metrics::NotifyDeviceScanFinished(int interface_index) {
@@ -858,6 +872,13 @@
device_metrics->scan_timer->ReportMilliseconds();
}
+void Metrics::ResetScanTimer(int interface_index) {
+ DeviceMetrics *device_metrics = GetDeviceMetrics(interface_index);
+ if (device_metrics == NULL)
+ return;
+ device_metrics->scan_timer->Reset();
+}
+
void Metrics::NotifyDeviceConnectStarted(int interface_index,
bool is_auto_connecting) {
DeviceMetrics *device_metrics = GetDeviceMetrics(interface_index);
@@ -897,6 +918,20 @@
kMetricCellularAutoConnectTriesNumBuckets);
AutoConnectMetricsReset(device_metrics);
}
+
+ if (!device_metrics->scan_connect_timer->Stop())
+ return;
+ base::TimeDelta elapsed_time;
+ device_metrics->scan_connect_timer->GetElapsedTime(&elapsed_time);
+ device_metrics->scan_connect_timer->ReportMilliseconds();
+}
+
+void Metrics::ResetConnectTimer(int interface_index) {
+ DeviceMetrics *device_metrics = GetDeviceMetrics(interface_index);
+ if (device_metrics == NULL)
+ return;
+ device_metrics->connect_timer->Reset();
+ device_metrics->scan_connect_timer->Reset();
}
void Metrics::NotifyCellularDeviceDrop(int interface_index,
diff --git a/metrics.h b/metrics.h
index 979cdb5..330e0de 100644
--- a/metrics.h
+++ b/metrics.h
@@ -277,6 +277,7 @@
static const int kMetricTimeToConnectMillisecondsMax;
static const int kMetricTimeToConnectMillisecondsMin;
static const int kMetricTimeToConnectMillisecondsNumBuckets;
+ static const char kMetricTimeToScanAndConnectMilliseconds[];
static const char kMetricTimeToDropSeconds[];
static const int kMetricTimeToDropSecondsMax;
static const int kMetricTimeToDropSecondsMin;
@@ -512,17 +513,25 @@
void NotifyDeviceDisableFinished(int interface_index);
// Notifies this object that a device has started the scanning process.
- void NotifyDeviceScanStarted(int interface_index);
+ virtual void NotifyDeviceScanStarted(int interface_index);
// Notifies this object that a device has completed the scanning process.
virtual void NotifyDeviceScanFinished(int interface_index);
+ // Terminates an underay scan (does nothing if a scan wasn't underay).
+ void ResetScanTimer(int interface_index);
+
// Notifies this object that a device has started the connect process.
- void NotifyDeviceConnectStarted(int interface_index,
- bool is_auto_connecting);
+ virtual void NotifyDeviceConnectStarted(int interface_index,
+ bool is_auto_connecting);
// Notifies this object that a device has completed the connect process.
- void NotifyDeviceConnectFinished(int interface_index);
+ virtual void NotifyDeviceConnectFinished(int interface_index);
+
+ // Resets both the connect_timer and the scan_connect_timer the timer (the
+ // latter so that a future connect will not erroneously be associated with
+ // the previous scan).
+ virtual void ResetConnectTimer(int interface_index);
// Notifies this object that a cellular device has been dropped by the
// network.
@@ -551,6 +560,7 @@
friend class MetricsTest;
FRIEND_TEST(MetricsTest, CellularDropsPerHour);
FRIEND_TEST(MetricsTest, FrequencyToChannel);
+ FRIEND_TEST(MetricsTest, ResetConnectTimer);
FRIEND_TEST(MetricsTest, ServiceFailure);
FRIEND_TEST(MetricsTest, TimeOnlineTimeToDrop);
FRIEND_TEST(MetricsTest, TimeToConfig);
@@ -588,6 +598,7 @@
scoped_ptr<chromeos_metrics::TimerReporter> disable_timer;
scoped_ptr<chromeos_metrics::TimerReporter> scan_timer;
scoped_ptr<chromeos_metrics::TimerReporter> connect_timer;
+ scoped_ptr<chromeos_metrics::TimerReporter> scan_connect_timer;
scoped_ptr<chromeos_metrics::TimerReporter> auto_connect_timer;
int auto_connect_tries;
int num_drops;
@@ -642,6 +653,16 @@
DeviceMetrics *device_metrics = GetDeviceMetrics(interface_index);
device_metrics->scan_timer.reset(timer); // Passes ownership
}
+ void set_time_to_connect_timer(int interface_index,
+ chromeos_metrics::TimerReporter *timer) {
+ DeviceMetrics *device_metrics = GetDeviceMetrics(interface_index);
+ device_metrics->connect_timer.reset(timer); // Passes ownership
+ }
+ void set_time_to_scan_connect_timer(int interface_index,
+ chromeos_metrics::TimerReporter *timer) {
+ DeviceMetrics *device_metrics = GetDeviceMetrics(interface_index);
+ device_metrics->scan_connect_timer.reset(timer); // Passes ownership
+ }
// |library_| points to |metrics_library_| when shill runs normally.
// However, in order to allow for unit testing, we point |library_| to a
diff --git a/metrics_unittest.cc b/metrics_unittest.cc
index 370948d..a4af912 100644
--- a/metrics_unittest.cc
+++ b/metrics_unittest.cc
@@ -448,6 +448,77 @@
metrics_.NotifyDeviceScanFinished(kInterfaceIndex);
}
+TEST_F(MetricsTest, TimeToScanAndConnect) {
+ EXPECT_CALL(library_,
+ SendToUMA("Network.Shill.Wifi.TimeToScan",
+ Ge(0),
+ Metrics::kMetricTimeToScanMillisecondsMin,
+ Metrics::kMetricTimeToScanMillisecondsMax,
+ Metrics::kMetricTimeToScanMillisecondsNumBuckets));
+ const int kInterfaceIndex = 1;
+ metrics_.RegisterDevice(kInterfaceIndex, Technology::kWifi);
+ metrics_.NotifyDeviceScanStarted(kInterfaceIndex);
+ metrics_.NotifyDeviceScanFinished(kInterfaceIndex);
+
+ EXPECT_CALL(library_,
+ SendToUMA("Network.Shill.Wifi.TimeToConnect",
+ Ge(0),
+ Metrics::kMetricTimeToConnectMillisecondsMin,
+ Metrics::kMetricTimeToConnectMillisecondsMax,
+ Metrics::kMetricTimeToConnectMillisecondsNumBuckets));
+ EXPECT_CALL(library_,
+ SendToUMA("Network.Shill.Wifi.TimeToScanAndConnect",
+ Ge(0),
+ Metrics::kMetricTimeToScanMillisecondsMin,
+ Metrics::kMetricTimeToScanMillisecondsMax +
+ Metrics::kMetricTimeToConnectMillisecondsMax,
+ Metrics::kMetricTimeToScanMillisecondsNumBuckets +
+ Metrics::kMetricTimeToConnectMillisecondsNumBuckets));
+ metrics_.NotifyDeviceConnectStarted(kInterfaceIndex, false);
+ metrics_.NotifyDeviceConnectFinished(kInterfaceIndex);
+}
+
+TEST_F(MetricsTest, SpontaneousConnect) {
+ const int kInterfaceIndex = 1;
+ metrics_.RegisterDevice(kInterfaceIndex, Technology::kWifi);
+ EXPECT_CALL(library_,
+ SendToUMA("Network.Shill.Wifi.TimeToConnect",
+ Ge(0),
+ Metrics::kMetricTimeToConnectMillisecondsMin,
+ Metrics::kMetricTimeToConnectMillisecondsMax,
+ Metrics::kMetricTimeToConnectMillisecondsNumBuckets)).Times(0);
+ EXPECT_CALL(library_,
+ SendToUMA("Network.Shill.Wifi.TimeToScanAndConnect",
+ Ge(0),
+ Metrics::kMetricTimeToScanMillisecondsMin,
+ Metrics::kMetricTimeToScanMillisecondsMax +
+ Metrics::kMetricTimeToConnectMillisecondsMax,
+ Metrics::kMetricTimeToScanMillisecondsNumBuckets +
+ Metrics::kMetricTimeToConnectMillisecondsNumBuckets)).
+ Times(0);
+ // This simulates a connection that is not scan-based.
+ metrics_.NotifyDeviceConnectFinished(kInterfaceIndex);
+}
+
+TEST_F(MetricsTest, ResetConnectTimer) {
+ const int kInterfaceIndex = 1;
+ metrics_.RegisterDevice(kInterfaceIndex, Technology::kWifi);
+ chromeos_metrics::TimerReporterMock *mock_scan_timer =
+ new chromeos_metrics::TimerReporterMock;
+ metrics_.set_time_to_scan_timer(kInterfaceIndex, mock_scan_timer);
+ chromeos_metrics::TimerReporterMock *mock_connect_timer =
+ new chromeos_metrics::TimerReporterMock;
+ metrics_.set_time_to_connect_timer(kInterfaceIndex, mock_connect_timer);
+ chromeos_metrics::TimerReporterMock *mock_scan_connect_timer =
+ new chromeos_metrics::TimerReporterMock;
+ metrics_.set_time_to_scan_connect_timer(kInterfaceIndex,
+ mock_scan_connect_timer);
+ EXPECT_CALL(*mock_scan_timer, Reset()).Times(0);
+ EXPECT_CALL(*mock_connect_timer, Reset());
+ EXPECT_CALL(*mock_scan_connect_timer, Reset());
+ metrics_.ResetConnectTimer(kInterfaceIndex);
+}
+
TEST_F(MetricsTest, TimeToScanNoStart) {
EXPECT_CALL(library_,
SendToUMA("Network.Shill.Cellular.TimeToScan", _, _, _, _)).Times(0);
diff --git a/mock_metrics.h b/mock_metrics.h
index 40ac679..f3ed3a3 100644
--- a/mock_metrics.h
+++ b/mock_metrics.h
@@ -18,7 +18,13 @@
MOCK_METHOD0(Start, void());
MOCK_METHOD0(Stop, void());
+ MOCK_METHOD1(NotifyDeviceScanStarted, void (int interface_index));
MOCK_METHOD1(NotifyDeviceScanFinished, void(int interface_index));
+ MOCK_METHOD1(ResetScanTimer, void(int interface_index));
+ MOCK_METHOD2(NotifyDeviceConnectStarted, void(int interface_index,
+ bool is_auto_connecting));
+ MOCK_METHOD1(NotifyDeviceConnectFinished, void(int interface_index));
+ MOCK_METHOD1(ResetConnectTimer, void(int interface_index));
MOCK_METHOD1(NotifyDefaultServiceChanged, void(const Service *service));
MOCK_METHOD2(NotifyServiceStateChanged,
void(const Service *service, Service::ConnectState new_state));
diff --git a/wifi.cc b/wifi.cc
index 26025d1..9f1ffd3 100644
--- a/wifi.cc
+++ b/wifi.cc
@@ -1114,7 +1114,6 @@
// started before we decide whether the scan was fruitful.
dispatcher()->PostTask(Bind(&WiFi::UpdateScanStateAfterScanDone,
weak_ptr_factory_.GetWeakPtr()));
- metrics()->NotifyDeviceScanFinished(interface_index());
}
if (need_bss_flush_) {
CHECK(supplicant_interface_proxy_ != NULL);
@@ -1200,20 +1199,17 @@
if (!enabled()) {
LOG(INFO) << "Ignoring scan request while device is not enabled.";
SetScanState(kScanIdle, kScanMethodNone); // Probably redundant.
- metrics()->NotifyDeviceScanFinished(interface_index());
return;
}
if (!scan_session_) {
SLOG(WiFi, 2) << "No scan session -- returning";
SetScanState(kScanIdle, kScanMethodNone);
- metrics()->NotifyDeviceScanFinished(interface_index());
return;
}
if (!IsIdle()) {
SLOG(WiFi, 2) << "Ignoring scan request while connecting to an AP.";
scan_session_.reset();
SetScanState(kScanConnecting, scan_method_);
- metrics()->NotifyDeviceScanFinished(interface_index());
return;
}
if (scan_session_->HasMoreFrequencies()) {
@@ -1904,6 +1900,28 @@
adaptor()->EmitBoolChanged(flimflam::kScanningProperty,
GetScanPending(&error));
}
+ switch (new_state) {
+ case kScanIdle:
+ metrics()->ResetScanTimer(interface_index());
+ break;
+ case kScanConnecting:
+ metrics()->NotifyDeviceScanFinished(interface_index());
+ // TODO(wdg): Provide |is_auto_connecting| to this interface. For now,
+ // I'll lie (because I don't care about the auto-connect metrics).
+ metrics()->NotifyDeviceConnectStarted(interface_index(), false);
+ break;
+ case kScanConnected:
+ metrics()->NotifyDeviceConnectFinished(interface_index());
+ break;
+ case kScanFoundNothing:
+ // Note that finishing a scan that hasn't started (if, for example, we
+ // get here when we fail to complete a connection) does nothing.
+ metrics()->NotifyDeviceScanFinished(interface_index());
+ metrics()->ResetConnectTimer(interface_index());
+ break;
+ default:
+ break;
+ }
ReportScanResultToUma(new_state, old_method);
if (is_terminal_state) {
// Now that we've logged a terminal state, let's call ourselves to
diff --git a/wifi_unittest.cc b/wifi_unittest.cc
index 4c684e2..9647325 100644
--- a/wifi_unittest.cc
+++ b/wifi_unittest.cc
@@ -1474,16 +1474,31 @@
ScopeLogger::GetInstance()->EnableScopesByName("wifi");
ScopeLogger::GetInstance()->set_verbose_level(10);
+ // Scan.
VerifyScanState(WiFi::kScanIdle, WiFi::kScanMethodNone);
+ EXPECT_CALL(*metrics(), NotifyDeviceScanStarted(_));
StartWiFi();
EXPECT_CALL(*adaptor_, EmitBoolChanged(_, _)).Times(AnyNumber());
EXPECT_CALL(*adaptor_, EmitBoolChanged(flimflam::kScanningProperty, true));
dispatcher_.DispatchPendingEvents();
VerifyScanState(WiFi::kScanScanning, WiFi::kScanMethodProgressive);
+
const base::CancelableClosure &pending_timeout = GetPendingTimeout();
EXPECT_TRUE(pending_timeout.IsCancelled());
- MockWiFiServiceRefPtr service(
- SetupConnectingService(DBus::Path(), NULL, NULL));
+
+ // Initiate a connection.
+ WiFiEndpointRefPtr endpoint;
+ ::DBus::Path bss_path;
+ MockWiFiServiceRefPtr service =
+ SetupConnectingService(DBus::Path(), &endpoint, &bss_path);
+ ReportScanDoneKeepScanSession();
+ EXPECT_CALL(*metrics(), NotifyDeviceScanFinished(_));
+ EXPECT_CALL(*metrics(), NotifyDeviceConnectStarted(_, _));
+ EXPECT_CALL(*adaptor_, EmitBoolChanged(flimflam::kScanningProperty, false));
+ dispatcher_.DispatchPendingEvents();
+ VerifyScanState(WiFi::kScanConnecting, WiFi::kScanMethodProgressive);
+
+ // Timeout the connection attempt.
EXPECT_FALSE(pending_timeout.IsCancelled());
EXPECT_EQ(service, GetPendingService());
// Simulate a service with a wifi_ reference calling DisconnectFrom().
@@ -1494,7 +1509,10 @@
EXPECT_CALL(*service, SetState(Service::kStateIdle)).Times(0);
EXPECT_CALL(*GetSupplicantInterfaceProxy(), Disconnect()).Times(0);
- EXPECT_CALL(*adaptor_, EmitBoolChanged(flimflam::kScanningProperty, false));
+ // Innocuous redundant call to NotifyDeviceScanFinished.
+ EXPECT_CALL(*metrics(), NotifyDeviceScanFinished(_)).Times(AnyNumber());
+ EXPECT_CALL(*metrics(), ResetConnectTimer(_)).Times(AnyNumber());
+ EXPECT_CALL(*metrics(), NotifyDeviceConnectFinished(_)).Times(0);
EXPECT_CALL(log, Log(_, _, _)).Times(AnyNumber());
EXPECT_CALL(log, Log(_, _,
HasSubstr("-> PROGRESSIVE_FINISHED_NOCONNECTION")));
@@ -1742,9 +1760,14 @@
// frequency.
SetScanSize(1, 1);
+ // This test never connects
+ EXPECT_CALL(*metrics(), NotifyDeviceConnectStarted(_, _)).Times(0);
+ EXPECT_CALL(*metrics(), NotifyDeviceConnectFinished(_)).Times(0);
+
// Do the first scan (finds nothing).
EXPECT_CALL(*scan_session_, InitiateScan());
VerifyScanState(WiFi::kScanIdle, WiFi::kScanMethodNone);
+ EXPECT_CALL(*metrics(), NotifyDeviceScanStarted(_));
StartWiFi();
dispatcher_.DispatchPendingEvents(); // Launch ProgressiveScanTask
VerifyScanState(WiFi::kScanScanning, WiFi::kScanMethodProgressive);
@@ -2730,6 +2753,7 @@
ScopeLogger::GetInstance()->set_verbose_level(10);
EXPECT_CALL(*adaptor_, EmitBoolChanged(_, _)).Times(AnyNumber());
+ EXPECT_CALL(*metrics(), NotifyDeviceScanStarted(_));
VerifyScanState(WiFi::kScanIdle, WiFi::kScanMethodNone);
StartWiFi();
EXPECT_CALL(*adaptor_, EmitBoolChanged(flimflam::kScanningProperty, true));
@@ -2744,6 +2768,8 @@
ReportScanDoneKeepScanSession();
EXPECT_CALL(*adaptor_, EmitBoolChanged(flimflam::kScanningProperty, false));
+ EXPECT_CALL(*metrics(), NotifyDeviceScanFinished(_));
+ EXPECT_CALL(*metrics(), NotifyDeviceConnectStarted(_, _));
dispatcher_.DispatchPendingEvents(); // Launch ProgressiveScanTask
VerifyScanState(WiFi::kScanConnecting, WiFi::kScanMethodProgressive);
@@ -2751,6 +2777,7 @@
EXPECT_CALL(*service, NotifyCurrentEndpoint(EndpointMatch(endpoint)));
EXPECT_CALL(log, Log(_, _, _)).Times(AnyNumber());
EXPECT_CALL(log, Log(_, _, HasSubstr("-> PROGRESSIVE_CONNECTED")));
+ EXPECT_CALL(*metrics(), NotifyDeviceConnectFinished(_));
ReportCurrentBSSChanged(bss_path);
VerifyScanState(WiFi::kScanIdle, WiFi::kScanMethodNone);