Merge "Metrics logging for DNS queries." into nyc-dev

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<DnsEvent> CREATOR = new Parcelable.Creator<DnsEvent>() {
+        @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));
+    }
+}

core/java/android/net/metrics/IpConnectivityEvent.java

@@ -24,32 +24,40 @@ import android.os.Parcelable;
  * {@hide}
  */
 public class IpConnectivityEvent implements Parcelable {
+    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_IPRM_BASE = 0*1024;
+    public static final int IPCE_DHCP_BASE                 = 1 * 1024;
-    public static final int IPCE_DHCP_BASE = 1*1024;
+    public static final int IPCE_NETMON_BASE               = 2 * 1024;
-    public static final int IPCE_NETMON_BASE = 2*1024;
+    public static final int IPCE_CONSRV_BASE               = 3 * 1024;
-    public static final int IPCE_CONSRV_BASE = 3*1024;
+    public static final int IPCE_IPMGR_BASE                = 4 * 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_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_DNS_LOOKUPS               = IPCE_DNS_BASE + 0;
+
     private static ConnectivityMetricsLogger mMetricsLogger = new ConnectivityMetricsLogger();
 
     public int describeContents() {

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

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<Integer, DnsEventBatch> 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);
+    }
+}

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<ConnectivityMetricsEvent> 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());
+                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) {