From f123c85f29b17ac32fb1c4c6035cbac850005447 Mon Sep 17 00:00:00 2001 From: Hugo Benichi Date: Fri, 20 Oct 2017 09:25:29 +0900 Subject: [PATCH] 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 --- .../android/server/ConnectivityService.java | 10 +- .../IpConnectivityEventBuilderTest.java | 38 ++-- .../IpConnectivityMetricsTest.java | 203 ++++++++---------- .../NetdEventListenerServiceTest.java | 25 ++- 4 files changed, 130 insertions(+), 146 deletions(-) diff --git a/services/core/java/com/android/server/ConnectivityService.java b/services/core/java/com/android/server/ConnectivityService.java index 25c96d14e9..a05e1cc673 100644 --- a/services/core/java/com/android/server/ConnectivityService.java +++ b/services/core/java/com/android/server/ConnectivityService.java @@ -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(); } diff --git a/tests/net/java/com/android/server/connectivity/IpConnectivityEventBuilderTest.java b/tests/net/java/com/android/server/connectivity/IpConnectivityEventBuilderTest.java index ad6ebf9337..a65bb24362 100644 --- a/tests/net/java/com/android/server/connectivity/IpConnectivityEventBuilderTest.java +++ b/tests/net/java/com/android/server/connectivity/IpConnectivityEventBuilderTest.java @@ -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"); diff --git a/tests/net/java/com/android/server/connectivity/IpConnectivityMetricsTest.java b/tests/net/java/com/android/server/connectivity/IpConnectivityMetricsTest.java index 6c1decc3b3..b48ff8da2b 100644 --- a/tests/net/java/com/android/server/connectivity/IpConnectivityMetricsTest.java +++ b/tests/net/java/com/android/server/connectivity/IpConnectivityMetricsTest.java @@ -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", - " 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: 100", - " >", - " no_default_network_duration_ms: 0", - " previous_network_id <", - " network_id: 0", - " >", - " previous_network_ip_support: 0", - " transport_types: 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 <", - " network_id: 100", - " >", - " previous_network_ip_support: 3", - " transport_types: 1", - " >", - ">", - "events <", - " if_name: \"\"", - " link_layer: 0", + " 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: 0", - " >", " no_default_network_duration_ms: 0", - " previous_network_id <", - " network_id: 101", - " >", - " previous_network_ip_support: 1", + " previous_default_network_link_layer: 0", + " previous_network_ip_support: 0", + " validation_duration_ms: 0", " >", ">", "events <", " if_name: \"\"", - " link_layer: 0", + " link_layer: 2", + " network_id: 100", + " time_ms: 0", + " transports: 1", + " default_network_event <", + " default_network_duration_ms: 2002", + " final_score: 50", + " initial_score: 10", + " ip_support: 3", + " no_default_network_duration_ms: 0", + " previous_default_network_link_layer: 0", + " previous_network_ip_support: 0", + " validation_duration_ms: 2002", + " >", + ">", + "events <", + " if_name: \"\"", + " 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: 8008", + " final_score: 0", + " initial_score: 0", + " ip_support: 0", + " no_default_network_duration_ms: 0", + " previous_default_network_link_layer: 4", + " previous_network_ip_support: 0", + " validation_duration_ms: 0", + " >", + ">", + "events <", + " if_name: \"\"", + " link_layer: 2", " network_id: 102", " 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: 102", - " >", + " default_network_duration_ms: 16016", + " final_score: 50", + " initial_score: 10", + " ip_support: 3", " no_default_network_duration_ms: 0", - " previous_network_id <", - " network_id: 0", - " >", + " previous_default_network_link_layer: 4", " previous_network_ip_support: 0", - " transport_types: 0", - " >", - ">", - "events <", - " if_name: \"\"", - " link_layer: 0", - " network_id: 103", - " 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: 103", - " >", - " no_default_network_duration_ms: 0", - " previous_network_id <", - " network_id: 102", - " >", - " previous_network_ip_support: 3", - " transport_types: 1", + " 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", + " link_layer: 2", + " network_id: 100", " 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: 101", - " >", + " default_network_duration_ms: 100", + " final_score: 50", + " initial_score: 50", + " ip_support: 2", " no_default_network_duration_ms: 0", - " previous_network_id <", - " network_id: 100", - " >", - " previous_network_ip_support: 2", - " transport_types: 1", + " previous_default_network_link_layer: 0", + " previous_network_ip_support: 0", + " validation_duration_ms: 100", " >", ">", "events <", diff --git a/tests/net/java/com/android/server/connectivity/NetdEventListenerServiceTest.java b/tests/net/java/com/android/server/connectivity/NetdEventListenerServiceTest.java index 6723601fc5..83194d9e6f 100644 --- a/tests/net/java/com/android/server/connectivity/NetdEventListenerServiceTest.java +++ b/tests/net/java/com/android/server/connectivity/NetdEventListenerServiceTest.java @@ -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[] remove(T[] array, T[] filtered) { + List 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); + } }