From 43724734d76c900fba9a004e28ff0ea4bd9d07ec Mon Sep 17 00:00:00 2001 From: Lorenzo Colitti Date: Tue, 12 Apr 2016 23:29:19 +0900 Subject: [PATCH] Metrics logging for DNS queries. Bug: 28204408 Change-Id: I05fc9b580aa20d99e8766057e17a38b5eb6267e8 --- core/java/android/net/metrics/DnsEvent.java | 77 +++++++++ .../net/metrics/IpConnectivityEvent.java | 50 +++--- services/core/Android.mk | 5 +- .../connectivity/DnsEventListenerService.java | 156 ++++++++++++++++++ .../connectivity/MetricsLoggerService.java | 17 +- 5 files changed, 279 insertions(+), 26 deletions(-) create mode 100644 core/java/android/net/metrics/DnsEvent.java create mode 100644 services/core/java/com/android/server/connectivity/DnsEventListenerService.java diff --git a/core/java/android/net/metrics/DnsEvent.java b/core/java/android/net/metrics/DnsEvent.java new file mode 100644 index 0000000000000..200b81645409d --- /dev/null +++ b/core/java/android/net/metrics/DnsEvent.java @@ -0,0 +1,77 @@ +/* + * Copyright (C) 2016 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package android.net.metrics; + +import android.os.Parcel; +import android.os.Parcelable; + +/** + * {@hide} + */ +public class DnsEvent extends IpConnectivityEvent implements Parcelable { + public final int netId; + + // The event type is currently only 1 or 2, so we store it as a byte. + public final byte[] eventTypes; + // Current getaddrinfo codes go from 1 to EAI_MAX = 15. gethostbyname returns errno, but there + // are fewer than 255 errno values. So we store the result code in a byte as well. + public final byte[] returnCodes; + // The latency is an integer because a) short arrays aren't parcelable and b) a short can only + // store a maximum latency of 32757 or 65535 ms, which is too short for pathologically slow + // queries. + public final int[] latenciesMs; + + private DnsEvent(int netId, byte[] eventTypes, byte[] returnCodes, int[] latenciesMs) { + this.netId = netId; + this.eventTypes = eventTypes; + this.returnCodes = returnCodes; + this.latenciesMs = latenciesMs; + } + + private DnsEvent(Parcel in) { + netId = in.readInt(); + eventTypes = in.createByteArray(); + returnCodes = in.createByteArray(); + latenciesMs = in.createIntArray(); + } + + @Override + public void writeToParcel(Parcel out, int flags) { + out.writeInt(netId); + out.writeByteArray(eventTypes); + out.writeByteArray(returnCodes); + out.writeIntArray(latenciesMs); + } + + public static final Parcelable.Creator CREATOR = new Parcelable.Creator() { + @Override + public DnsEvent createFromParcel(Parcel in) { + return new DnsEvent(in); + } + + @Override + public DnsEvent[] newArray(int size) { + return new DnsEvent[size]; + } + }; + + public static void logEvent( + int netId, byte[] eventTypes, byte[] returnCodes, int[] latenciesMs) { + IpConnectivityEvent.logEvent(IPCE_DNS_LOOKUPS, + new DnsEvent(netId, eventTypes, returnCodes, latenciesMs)); + } +} diff --git a/core/java/android/net/metrics/IpConnectivityEvent.java b/core/java/android/net/metrics/IpConnectivityEvent.java index 59c1cfe25be02..f0a3c902a355e 100644 --- a/core/java/android/net/metrics/IpConnectivityEvent.java +++ b/core/java/android/net/metrics/IpConnectivityEvent.java @@ -24,31 +24,39 @@ import android.os.Parcelable; * {@hide} */ public class IpConnectivityEvent implements Parcelable { - // IPRM = IpReachabilityMonitor - // DHCP = DhcpClient + public static final String TAG = "IpConnectivityEvent"; + + // IPRM = IpReachabilityMonitor + // DHCP = DhcpClient // NETMON = NetworkMonitorEvent // CONSRV = ConnectivityServiceEvent - // IPMGR = IpManager - public static final String TAG = "IpConnectivityEvent"; - public static final int IPCE_IPRM_BASE = 0*1024; - public static final int IPCE_DHCP_BASE = 1*1024; - public static final int IPCE_NETMON_BASE = 2*1024; - public static final int IPCE_CONSRV_BASE = 3*1024; - public static final int IPCE_IPMGR_BASE = 4*1024; + // IPMGR = IpManager + public static final int IPCE_IPRM_BASE = 0 * 1024; + public static final int IPCE_DHCP_BASE = 1 * 1024; + public static final int IPCE_NETMON_BASE = 2 * 1024; + public static final int IPCE_CONSRV_BASE = 3 * 1024; + public static final int IPCE_IPMGR_BASE = 4 * 1024; + public static final int IPCE_DNS_BASE = 5 * 1024; + + public static final int IPCE_IPRM_PROBE_RESULT = IPCE_IPRM_BASE + 0; + public static final int IPCE_IPRM_MESSAGE_RECEIVED = IPCE_IPRM_BASE + 1; + public static final int IPCE_IPRM_REACHABILITY_LOST = IPCE_IPRM_BASE + 2; + + public static final int IPCE_DHCP_RECV_ERROR = IPCE_DHCP_BASE + 0; + public static final int IPCE_DHCP_PARSE_ERROR = IPCE_DHCP_BASE + 1; + public static final int IPCE_DHCP_TIMEOUT = IPCE_DHCP_BASE + 2; + public static final int IPCE_DHCP_STATE_CHANGE = IPCE_DHCP_BASE + 3; + + public static final int IPCE_NETMON_STATE_CHANGE = IPCE_NETMON_BASE + 0; + public static final int IPCE_NETMON_CHECK_RESULT = IPCE_NETMON_BASE + 1; - public static final int IPCE_IPRM_PROBE_RESULT = IPCE_IPRM_BASE + 0; - public static final int IPCE_IPRM_MESSAGE_RECEIVED = IPCE_IPRM_BASE + 1; - public static final int IPCE_IPRM_REACHABILITY_LOST = IPCE_IPRM_BASE + 2; - public static final int IPCE_DHCP_RECV_ERROR = IPCE_DHCP_BASE + 0; - public static final int IPCE_DHCP_PARSE_ERROR = IPCE_DHCP_BASE + 1; - public static final int IPCE_DHCP_TIMEOUT = IPCE_DHCP_BASE + 2; - public static final int IPCE_DHCP_STATE_CHANGE = IPCE_DHCP_BASE + 3; - public static final int IPCE_NETMON_STATE_CHANGE = IPCE_NETMON_BASE + 0; - public static final int IPCE_NETMON_CHECK_RESULT = IPCE_NETMON_BASE + 1; public static final int IPCE_CONSRV_DEFAULT_NET_CHANGE = IPCE_CONSRV_BASE + 0; - public static final int IPCE_IPMGR_PROVISIONING_OK = IPCE_IPMGR_BASE + 0; - public static final int IPCE_IPMGR_PROVISIONING_FAIL = IPCE_IPMGR_BASE + 1; - public static final int IPCE_IPMGR_COMPLETE_LIFECYCLE = IPCE_IPMGR_BASE + 2; + + public static final int IPCE_IPMGR_PROVISIONING_OK = IPCE_IPMGR_BASE + 0; + public static final int IPCE_IPMGR_PROVISIONING_FAIL = IPCE_IPMGR_BASE + 1; + public static final int IPCE_IPMGR_COMPLETE_LIFECYCLE = IPCE_IPMGR_BASE + 2; + + public static final int IPCE_DNS_LOOKUPS = IPCE_DNS_BASE + 0; private static ConnectivityMetricsLogger mMetricsLogger = new ConnectivityMetricsLogger(); diff --git a/services/core/Android.mk b/services/core/Android.mk index 99c5dd69cda39..a248aa3322258 100644 --- a/services/core/Android.mk +++ b/services/core/Android.mk @@ -4,11 +4,14 @@ include $(CLEAR_VARS) LOCAL_MODULE := services.core +LOCAL_AIDL_INCLUDES := system/netd/server/binder + LOCAL_SRC_FILES += \ $(call all-java-files-under,java) \ java/com/android/server/EventLogTags.logtags \ java/com/android/server/am/EventLogTags.logtags \ - ../../../../system/netd/server/binder/android/net/INetd.aidl + ../../../../system/netd/server/binder/android/net/INetd.aidl \ + ../../../../system/netd/server/binder/android/net/metrics/IDnsEventListener.aidl \ LOCAL_JAVA_LIBRARIES := services.net telephony-common LOCAL_STATIC_JAVA_LIBRARIES := tzdata_update diff --git a/services/core/java/com/android/server/connectivity/DnsEventListenerService.java b/services/core/java/com/android/server/connectivity/DnsEventListenerService.java new file mode 100644 index 0000000000000..d3f8af045395f --- /dev/null +++ b/services/core/java/com/android/server/connectivity/DnsEventListenerService.java @@ -0,0 +1,156 @@ +/* + * Copyright (C) 2016 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.server.connectivity; + +import android.content.Context; +import android.net.metrics.DnsEvent; +import android.net.ConnectivityManager; +import android.net.ConnectivityManager.NetworkCallback; +import android.net.Network; +import android.net.NetworkRequest; +import android.net.metrics.IDnsEventListener; +import android.util.Log; + +import com.android.internal.annotations.GuardedBy; +import com.android.internal.util.IndentingPrintWriter; + +import java.io.PrintWriter; +import java.util.Arrays; +import java.util.SortedMap; +import java.util.TreeMap; + + +/** + * Implementation of the IDnsEventListener interface. + */ +public class DnsEventListenerService extends IDnsEventListener.Stub { + + public static final String SERVICE_NAME = "dns_listener"; + + private static final String TAG = DnsEventListenerService.class.getSimpleName(); + private static final boolean DBG = true; + private static final boolean VDBG = false; + + private static final int MAX_LOOKUPS_PER_DNS_EVENT = 100; + + // Stores the results of a number of consecutive DNS lookups on the same network. + // This class is not thread-safe and it is the responsibility of the service to call its methods + // on one thread at a time. + private static class DnsEventBatch { + private final int mNetId; + + private final byte[] mEventTypes = new byte[MAX_LOOKUPS_PER_DNS_EVENT]; + private final byte[] mReturnCodes = new byte[MAX_LOOKUPS_PER_DNS_EVENT]; + private final int[] mLatenciesMs = new int[MAX_LOOKUPS_PER_DNS_EVENT]; + private int mEventCount; + + public DnsEventBatch(int netId) { + mNetId = netId; + } + + public void addResult(byte eventType, byte returnCode, int latencyMs) { + mEventTypes[mEventCount] = eventType; + mReturnCodes[mEventCount] = returnCode; + mLatenciesMs[mEventCount] = latencyMs; + mEventCount++; + if (mEventCount == MAX_LOOKUPS_PER_DNS_EVENT) { + logAndClear(); + } + } + + public void logAndClear() { + // Did we lose a race with addResult? + if (mEventCount == 0) { + return; + } + + byte[] returnCodes = Arrays.copyOf(mReturnCodes, mEventCount); + int[] latenciesMs = Arrays.copyOf(mLatenciesMs, mEventCount); + DnsEvent.logEvent(mNetId, mEventTypes, mReturnCodes, mLatenciesMs); + maybeLog(String.format("Logging %d results for netId %d", mEventCount, mNetId)); + mEventCount = 0; + } + + // For debugging and unit tests only. + public String toString() { + return String.format("%s %d %d", getClass().getSimpleName(), mNetId, mEventCount); + } + } + + // Only sorted for ease of debugging. Because we only typically have a handful of networks up + // at any given time, performance is not a concern. + @GuardedBy("this") + private SortedMap mEventBatches = new TreeMap<>(); + + // We register a NetworkCallback to ensure that when a network disconnects, we flush the DNS + // queries we've logged on that network. Because we do not do this periodically, we might lose + // up to MAX_LOOKUPS_PER_DNS_EVENT lookup stats on each network when the system is shutting + // down. We believe this to be sufficient for now. + private final ConnectivityManager mCm; + private final NetworkCallback mNetworkCallback = new NetworkCallback() { + @Override + public void onLost(Network network) { + synchronized (DnsEventListenerService.this) { + DnsEventBatch batch = mEventBatches.remove(network.netId); + if (batch != null) { + batch.logAndClear(); + } + } + } + }; + + public DnsEventListenerService(Context context) { + // We are started when boot is complete, so ConnectivityService should already be running. + final NetworkRequest request = new NetworkRequest.Builder() + .clearCapabilities() + .build(); + mCm = context.getSystemService(ConnectivityManager.class); + mCm.registerNetworkCallback(request, mNetworkCallback); + } + + @Override + // Called concurrently by multiple binder threads. + public synchronized void onDnsEvent(int netId, int eventType, int returnCode, int latencyMs) { + maybeVerboseLog(String.format("onDnsEvent(%d, %d, %d, %d)", + netId, eventType, returnCode, latencyMs)); + + DnsEventBatch batch = mEventBatches.get(netId); + if (batch == null) { + batch = new DnsEventBatch(netId); + mEventBatches.put(netId, batch); + } + batch.addResult((byte) eventType, (byte) returnCode, latencyMs); + } + + public synchronized void dump(PrintWriter writer) { + IndentingPrintWriter pw = new IndentingPrintWriter(writer, " "); + pw.println(TAG + ":"); + pw.increaseIndent(); + for (DnsEventBatch batch : mEventBatches.values()) { + pw.println(batch.toString()); + } + pw.decreaseIndent(); + } + + private static void maybeLog(String s) { + if (DBG) Log.d(TAG, s); + } + + private static void maybeVerboseLog(String s) { + if (VDBG) Log.d(TAG, s); + } +} diff --git a/services/core/java/com/android/server/connectivity/MetricsLoggerService.java b/services/core/java/com/android/server/connectivity/MetricsLoggerService.java index f91db7813d42b..0c259aeb524a5 100644 --- a/services/core/java/com/android/server/connectivity/MetricsLoggerService.java +++ b/services/core/java/com/android/server/connectivity/MetricsLoggerService.java @@ -55,6 +55,8 @@ public class MetricsLoggerService extends SystemService { if (DBG) Log.d(TAG, "onBootPhase: PHASE_SYSTEM_SERVICES_READY"); publishBinderService(ConnectivityMetricsLogger.CONNECTIVITY_METRICS_LOGGER_SERVICE, mBinder); + mDnsListener = new DnsEventListenerService(getContext()); + publishBinderService(mDnsListener.SERVICE_NAME, mDnsListener); } } @@ -89,6 +91,8 @@ public class MetricsLoggerService extends SystemService { private final ArrayDeque mEvents = new ArrayDeque<>(); + private DnsEventListenerService mDnsListener; + private void enforceConnectivityInternalPermission() { getContext().enforceCallingOrSelfPermission( android.Manifest.permission.CONNECTIVITY_INTERNAL, @@ -159,10 +163,12 @@ public class MetricsLoggerService extends SystemService { synchronized (mEvents) { pw.println("Number of events: " + mEvents.size()); - pw.println("Time span: " + - DateUtils.formatElapsedTime( - (System.currentTimeMillis() - mEvents.peekFirst().timestamp) - / 1000)); + if (mEvents.size() > 0) { + pw.println("Time span: " + + DateUtils.formatElapsedTime( + (System.currentTimeMillis() - mEvents.peekFirst().timestamp) + / 1000)); + } if (dumpSerializedSize) { long dataSize = 0; @@ -193,6 +199,9 @@ public class MetricsLoggerService extends SystemService { pw.println(pi.toString()); } } + + pw.println(); + mDnsListener.dump(pw); } public long logEvent(ConnectivityMetricsEvent event) {