DefaultNetworkEvent metrics: rehaul

This patch changes instrumentation of default networks and default
network events:
- stop logging events for default network transitions,
  but instead consistently log one event per continuous segment
  when one given network was the default, including logging an
  event for when there is no default network.
- keep a separate rolling buffer of DefaultNetworkEvent for
  dumpsys and bug reports.

These changes allow to simplify post aggregation of default network
event metrics by removing any need to do time series processing.
Instead, metrics and counters can be implemented withouth any ambiguity
by following the recipe:

% of x = sum(duration | x = true) / sum (all durations)

where x can be various conditions such as:
- the default network was validated
- the default network was WiFi
- the default network was IPv6
- there was no default network
- ...

Most importantly, this new logging scheme allows to measure much more
reliably:
- the % of the time that a device had Internet, in the sense that the
default network was validated.
- the time transitions between default networks, keyed by previous and
new transports/link layer, which allows to derive wakelock durations
and wakelock power costs from default network switches.

This patch also simplifies the dumpsys interface of the connmetrics
service and reduces the commands to three:
- "flush" for metrics upload.
- "proto" for printing buffered event in text proto format.
- "list" for listing all events and statistics.

Bug: 34901696
Bug: 65700460
Test: runtest frameworks-net
Change-Id: I0521f1681a60cca07ac3bfd5741d64ce44de4cdd
This commit is contained in:
Hugo Benichi
2017-10-20 09:25:29 +09:00
parent bccc497249
commit f123c85f29
4 changed files with 130 additions and 146 deletions

View File

@@ -2109,9 +2109,14 @@ public class ConnectivityService extends IConnectivityManager.Stub
final boolean valid =
(msg.arg1 == NetworkMonitor.NETWORK_TEST_RESULT_VALID);
final boolean wasValidated = nai.lastValidated;
final boolean wasDefault = isDefaultNetwork(nai);
if (DBG) log(nai.name() + " validation " + (valid ? "passed" : "failed") +
(msg.obj == null ? "" : " with redirect to " + (String)msg.obj));
if (valid != nai.lastValidated) {
if (wasDefault) {
metricsLogger().defaultNetworkMetrics().logDefaultNetworkValidity(
SystemClock.elapsedRealtime(), valid);
}
final int oldScore = nai.getCurrentScore();
nai.lastValidated = valid;
nai.everValidated |= valid;
@@ -2283,7 +2288,8 @@ public class ConnectivityService extends IConnectivityManager.Stub
// Let rematchAllNetworksAndRequests() below record a new default network event
// if there is a fallback. Taken together, the two form a X -> 0, 0 -> Y sequence
// whose timestamps tell how long it takes to recover a default network.
metricsLogger().defaultNetworkMetrics().logDefaultNetworkEvent(null, nai);
long now = SystemClock.elapsedRealtime();
metricsLogger().defaultNetworkMetrics().logDefaultNetworkEvent(now, null, nai);
}
notifyIfacesChangedForNetworkStats();
// TODO - we shouldn't send CALLBACK_LOST to requests that can be satisfied
@@ -5013,7 +5019,7 @@ public class ConnectivityService extends IConnectivityManager.Stub
makeDefault(newNetwork);
// Log 0 -> X and Y -> X default network transitions, where X is the new default.
metricsLogger().defaultNetworkMetrics().logDefaultNetworkEvent(
newNetwork, oldDefaultNetwork);
now, newNetwork, oldDefaultNetwork);
// Have a new default network, release the transition wakelock in
scheduleReleaseNetworkTransitionWakelock();
}

View File

@@ -198,37 +198,33 @@ public class IpConnectivityEventBuilderTest {
@Test
public void testDefaultNetworkEventSerialization() {
DefaultNetworkEvent ev = new DefaultNetworkEvent();
DefaultNetworkEvent ev = new DefaultNetworkEvent(1001);
ev.netId = 102;
ev.prevNetId = 101;
ev.transportTypes = new int[]{1, 2, 3};
ev.prevIPv4 = true;
ev.prevIPv6 = true;
ev.transports = 2;
ev.previousTransports = 4;
ev.ipv4 = true;
ev.initialScore = 20;
ev.finalScore = 60;
ev.durationMs = 54;
ev.validatedMs = 27;
String want = String.join("\n",
"dropped_events: 0",
"events <",
" if_name: \"\"",
" link_layer: 0",
" link_layer: 4",
" network_id: 102",
" time_ms: 0",
" transports: 0",
" transports: 2",
" default_network_event <",
" default_network_duration_ms: 0",
" final_score: 0",
" initial_score: 0",
" ip_support: 0",
" network_id <",
" network_id: 102",
" >",
" default_network_duration_ms: 54",
" final_score: 60",
" initial_score: 20",
" ip_support: 1",
" no_default_network_duration_ms: 0",
" previous_network_id <",
" network_id: 101",
" >",
" previous_network_ip_support: 3",
" transport_types: 1",
" transport_types: 2",
" transport_types: 3",
" previous_default_network_link_layer: 1",
" previous_network_ip_support: 0",
" validation_duration_ms: 27",
" >",
">",
"version: 2\n");

View File

@@ -188,119 +188,99 @@ public class IpConnectivityMetricsTest {
{makeNai(102, 50, true, true, cell), makeNai(103, 20, true, false, wifi)},
};
long timeMs = mService.mDefaultNetworkMetrics.creationTimeMs;
long durationMs = 1001;
for (NetworkAgentInfo[] pair : defaultNetworks) {
mService.mDefaultNetworkMetrics.logDefaultNetworkEvent(pair[1], pair[0]);
timeMs += durationMs;
durationMs += durationMs;
mService.mDefaultNetworkMetrics.logDefaultNetworkEvent(timeMs, pair[1], pair[0]);
}
String want = String.join("\n",
"dropped_events: 0",
"events <",
" if_name: \"\"",
" link_layer: 0",
" network_id: 100",
" link_layer: 5",
" network_id: 0",
" time_ms: 0",
" transports: 0",
" default_network_event <",
" default_network_duration_ms: 0",
" default_network_duration_ms: 1001",
" final_score: 0",
" initial_score: 0",
" ip_support: 0",
" network_id <",
" network_id: 100",
" >",
" no_default_network_duration_ms: 0",
" previous_network_id <",
" network_id: 0",
" >",
" previous_default_network_link_layer: 0",
" previous_network_ip_support: 0",
" transport_types: 0",
" validation_duration_ms: 0",
" >",
">",
"events <",
" if_name: \"\"",
" link_layer: 0",
" network_id: 101",
" time_ms: 0",
" transports: 0",
" default_network_event <",
" default_network_duration_ms: 0",
" final_score: 0",
" initial_score: 0",
" ip_support: 0",
" network_id <",
" network_id: 101",
" >",
" no_default_network_duration_ms: 0",
" previous_network_id <",
" link_layer: 2",
" network_id: 100",
" >",
" previous_network_ip_support: 3",
" transport_types: 1",
" >",
">",
"events <",
" if_name: \"\"",
" link_layer: 0",
" network_id: 0",
" time_ms: 0",
" transports: 0",
" transports: 1",
" default_network_event <",
" default_network_duration_ms: 0",
" final_score: 0",
" initial_score: 0",
" ip_support: 0",
" network_id <",
" network_id: 0",
" >",
" default_network_duration_ms: 2002",
" final_score: 50",
" initial_score: 10",
" ip_support: 3",
" no_default_network_duration_ms: 0",
" previous_network_id <",
" network_id: 101",
" >",
" previous_network_ip_support: 1",
" >",
">",
"events <",
" if_name: \"\"",
" link_layer: 0",
" network_id: 102",
" time_ms: 0",
" transports: 0",
" default_network_event <",
" default_network_duration_ms: 0",
" final_score: 0",
" initial_score: 0",
" ip_support: 0",
" network_id <",
" network_id: 102",
" >",
" no_default_network_duration_ms: 0",
" previous_network_id <",
" network_id: 0",
" >",
" previous_default_network_link_layer: 0",
" previous_network_ip_support: 0",
" transport_types: 0",
" validation_duration_ms: 2002",
" >",
">",
"events <",
" if_name: \"\"",
" link_layer: 0",
" network_id: 103",
" link_layer: 4",
" network_id: 101",
" time_ms: 0",
" transports: 2",
" default_network_event <",
" default_network_duration_ms: 4004",
" final_score: 60",
" initial_score: 20",
" ip_support: 1",
" no_default_network_duration_ms: 0",
" previous_default_network_link_layer: 2",
" previous_network_ip_support: 0",
" validation_duration_ms: 4004",
" >",
">",
"events <",
" if_name: \"\"",
" link_layer: 5",
" network_id: 0",
" time_ms: 0",
" transports: 0",
" default_network_event <",
" default_network_duration_ms: 0",
" default_network_duration_ms: 8008",
" final_score: 0",
" initial_score: 0",
" ip_support: 0",
" network_id <",
" network_id: 103",
" >",
" no_default_network_duration_ms: 0",
" previous_network_id <",
" network_id: 102",
" previous_default_network_link_layer: 4",
" previous_network_ip_support: 0",
" validation_duration_ms: 0",
" >",
" previous_network_ip_support: 3",
" transport_types: 1",
">",
"events <",
" if_name: \"\"",
" link_layer: 2",
" network_id: 102",
" time_ms: 0",
" transports: 1",
" default_network_event <",
" default_network_duration_ms: 16016",
" final_score: 50",
" initial_score: 10",
" ip_support: 3",
" no_default_network_duration_ms: 0",
" previous_default_network_link_layer: 4",
" previous_network_ip_support: 0",
" validation_duration_ms: 16016",
" >",
">",
"version: 2\n");
@@ -379,12 +359,13 @@ public class IpConnectivityMetricsTest {
wakeupEvent("wlan0", 10008);
wakeupEvent("rmnet0", 1000);
long timeMs = mService.mDefaultNetworkMetrics.creationTimeMs;
final long cell = BitUtils.packBits(new int[]{NetworkCapabilities.TRANSPORT_CELLULAR});
final long wifi = BitUtils.packBits(new int[]{NetworkCapabilities.TRANSPORT_WIFI});
NetworkAgentInfo cellNai = makeNai(100, 50, false, true, cell);
NetworkAgentInfo wifiNai = makeNai(101, 60, true, false, wifi);
mService.mDefaultNetworkMetrics.logDefaultNetworkEvent(cellNai, null);
mService.mDefaultNetworkMetrics.logDefaultNetworkEvent(wifiNai, cellNai);
mService.mDefaultNetworkMetrics.logDefaultNetworkEvent(timeMs + 200, cellNai, null);
mService.mDefaultNetworkMetrics.logDefaultNetworkEvent(timeMs + 300, wifiNai, cellNai);
String want = String.join("\n",
"dropped_events: 0",
@@ -473,46 +454,36 @@ public class IpConnectivityMetricsTest {
">",
"events <",
" if_name: \"\"",
" link_layer: 0",
" network_id: 100",
" link_layer: 5",
" network_id: 0",
" time_ms: 0",
" transports: 0",
" default_network_event <",
" default_network_duration_ms: 0",
" default_network_duration_ms: 200",
" final_score: 0",
" initial_score: 0",
" ip_support: 0",
" network_id <",
" network_id: 100",
" >",
" no_default_network_duration_ms: 0",
" previous_network_id <",
" network_id: 0",
" >",
" previous_default_network_link_layer: 0",
" previous_network_ip_support: 0",
" transport_types: 0",
" validation_duration_ms: 0",
" >",
">",
"events <",
" if_name: \"\"",
" link_layer: 0",
" network_id: 101",
" time_ms: 0",
" transports: 0",
" default_network_event <",
" default_network_duration_ms: 0",
" final_score: 0",
" initial_score: 0",
" ip_support: 0",
" network_id <",
" network_id: 101",
" >",
" no_default_network_duration_ms: 0",
" previous_network_id <",
" link_layer: 2",
" network_id: 100",
" >",
" previous_network_ip_support: 2",
" transport_types: 1",
" time_ms: 0",
" transports: 1",
" default_network_event <",
" default_network_duration_ms: 100",
" final_score: 50",
" initial_score: 50",
" ip_support: 2",
" no_default_network_duration_ms: 0",
" previous_default_network_link_layer: 0",
" previous_network_ip_support: 0",
" validation_duration_ms: 100",
" >",
">",
"events <",

View File

@@ -82,9 +82,8 @@ public class NetdEventListenerServiceTest {
public void testWakeupEventLogging() throws Exception {
final int BUFFER_LENGTH = NetdEventListenerService.WAKEUP_EVENT_BUFFER_LENGTH;
// Assert no events
String[] events1 = listNetdEvent();
assertEquals(new String[]{""}, events1);
// Baseline without any event
String[] baseline = listNetdEvent();
long now = System.currentTimeMillis();
String prefix = "iface:wlan0";
@@ -93,7 +92,7 @@ public class NetdEventListenerServiceTest {
mNetdEventListenerService.onWakeupEvent(prefix, uid, uid, now);
}
String[] events2 = listNetdEvent();
String[] events2 = remove(listNetdEvent(), baseline);
int expectedLength2 = uids.length + 1; // +1 for the WakeupStats line
assertEquals(expectedLength2, events2.length);
assertContains(events2[0], "WakeupStats");
@@ -111,7 +110,7 @@ public class NetdEventListenerServiceTest {
mNetdEventListenerService.onWakeupEvent(prefix, uid, uid, ts);
}
String[] events3 = listNetdEvent();
String[] events3 = remove(listNetdEvent(), baseline);
int expectedLength3 = BUFFER_LENGTH + 1; // +1 for the WakeupStats line
assertEquals(expectedLength3, events3.length);
assertContains(events2[0], "WakeupStats");
@@ -126,7 +125,7 @@ public class NetdEventListenerServiceTest {
uid = 45678;
mNetdEventListenerService.onWakeupEvent(prefix, uid, uid, now);
String[] events4 = listNetdEvent();
String[] events4 = remove(listNetdEvent(), baseline);
String lastEvent = events4[events4.length - 1];
assertContains(lastEvent, "WakeupEvent");
assertContains(lastEvent, "wlan0");
@@ -423,7 +422,7 @@ public class NetdEventListenerServiceTest {
final PrintWriter pw = new PrintWriter(new FileOutputStream("/dev/null"));
new Thread(() -> {
while (System.currentTimeMillis() < stop) {
mNetdEventListenerService.dump(pw);
mNetdEventListenerService.list(pw);
}
}).start();
}
@@ -461,4 +460,16 @@ public class NetdEventListenerServiceTest {
static void assertContains(String got, String want) {
assertTrue(got + " did not contain \"" + want + "\"", got.contains(want));
}
static <T> T[] remove(T[] array, T[] filtered) {
List<T> c = Arrays.asList(filtered);
int next = 0;
for (int i = 0; i < array.length; i++) {
if (c.contains(array[i])) {
continue;
}
array[next++] = array[i];
}
return Arrays.copyOf(array, next);
}
}