From d1cb256b3efd2c00f1c44541b5589c2ea17b3cb8 Mon Sep 17 00:00:00 2001 From: Pavel Zhamaitsiak Date: Thu, 31 Mar 2016 18:43:14 -0700 Subject: [PATCH] ConnectivityMetricsLogger: Switch to "pull" model If subscriber is in external app, its process can be killed. This would lead to loss of events. To avoid that, we will be storing events in the logger service. Clients can periodically pull data from it. Another option for client apps is to register PendingIntent which will be sent when certain number of new events has been received. If events are logged at unexpectedly high rate from particular component, then throttling mechanism will activate and new events will be blocked for some time from that component. Change-Id: I710409626eb5a42bcd3fe8126eac6b756fa1ab8b --- Android.mk | 1 - .../android/net/ConnectivityMetricsEvent.aidl | 1 + .../android/net/ConnectivityMetricsEvent.java | 38 ++ .../net/ConnectivityMetricsLogger.java | 70 +++- .../net/IConnectivityMetricsLogger.aidl | 23 +- .../IConnectivityMetricsLoggerSubscriber.aidl | 25 -- .../connectivity/MetricsLoggerService.java | 348 +++++++++++++----- 7 files changed, 379 insertions(+), 127 deletions(-) delete mode 100644 core/java/android/net/IConnectivityMetricsLoggerSubscriber.aidl diff --git a/Android.mk b/Android.mk index bfe85f6eba693..c9cf3fc6785e4 100644 --- a/Android.mk +++ b/Android.mk @@ -190,7 +190,6 @@ LOCAL_SRC_FILES += \ core/java/android/net/ICaptivePortal.aidl \ core/java/android/net/IConnectivityManager.aidl \ core/java/android/net/IConnectivityMetricsLogger.aidl \ - core/java/android/net/IConnectivityMetricsLoggerSubscriber.aidl \ core/java/android/net/IEthernetManager.aidl \ core/java/android/net/IEthernetServiceListener.aidl \ core/java/android/net/INetworkManagementEventObserver.aidl \ diff --git a/core/java/android/net/ConnectivityMetricsEvent.aidl b/core/java/android/net/ConnectivityMetricsEvent.aidl index da175614b5886..a027d7c38140f 100644 --- a/core/java/android/net/ConnectivityMetricsEvent.aidl +++ b/core/java/android/net/ConnectivityMetricsEvent.aidl @@ -17,3 +17,4 @@ package android.net; parcelable ConnectivityMetricsEvent; +parcelable ConnectivityMetricsEvent.Reference; diff --git a/core/java/android/net/ConnectivityMetricsEvent.java b/core/java/android/net/ConnectivityMetricsEvent.java index d040a8563440a..3a5dd92e69b59 100644 --- a/core/java/android/net/ConnectivityMetricsEvent.java +++ b/core/java/android/net/ConnectivityMetricsEvent.java @@ -79,4 +79,42 @@ public class ConnectivityMetricsEvent implements Parcelable { return String.format("ConnectivityMetricsEvent(%d, %d, %d)", timestamp, componentTag, eventTag); } + + /** {@hide} */ + public static class Reference implements Parcelable { + + public long value; + + public Reference(long ref) { + this.value = ref; + } + + /** Implement the Parcelable interface */ + public static final Parcelable.Creator CREATOR + = new Parcelable.Creator (){ + public Reference createFromParcel(Parcel source) { + return new Reference(source.readLong()); + } + + public Reference[] newArray(int size) { + return new Reference[size]; + } + }; + + /** Implement the Parcelable interface */ + @Override + public int describeContents() { + return 0; + } + + /** Implement the Parcelable interface */ + @Override + public void writeToParcel(Parcel dest, int flags) { + dest.writeLong(value); + } + + public void readFromParcel(Parcel in) { + value = in.readLong(); + } + } } diff --git a/core/java/android/net/ConnectivityMetricsLogger.java b/core/java/android/net/ConnectivityMetricsLogger.java index 3ef805017f149..eafb8acb8aebf 100644 --- a/core/java/android/net/ConnectivityMetricsLogger.java +++ b/core/java/android/net/ConnectivityMetricsLogger.java @@ -15,6 +15,7 @@ */ package android.net; +import android.os.Bundle; import android.os.Parcelable; import android.os.RemoteException; import android.os.ServiceManager; @@ -28,14 +29,24 @@ public class ConnectivityMetricsLogger { public static final String CONNECTIVITY_METRICS_LOGGER_SERVICE = "connectivity_metrics_logger"; // Component Tags - public static final int COMPONENT_TAG_CONNECTIVITY = 1; - public static final int COMPONENT_TAG_BLUETOOTH = 2; - public static final int COMPONENT_TAG_WIFI = 3; - public static final int COMPONENT_TAG_TELECOM = 4; - public static final int COMPONENT_TAG_TELEPHONY = 5; + public static final int COMPONENT_TAG_CONNECTIVITY = 0; + public static final int COMPONENT_TAG_BLUETOOTH = 1; + public static final int COMPONENT_TAG_WIFI = 2; + public static final int COMPONENT_TAG_TELECOM = 3; + public static final int COMPONENT_TAG_TELEPHONY = 4; + + public static final int NUMBER_OF_COMPONENTS = 5; + + // Event Tag + public static final int TAG_SKIPPED_EVENTS = -1; + + public static final String DATA_KEY_EVENTS_COUNT = "count"; private IConnectivityMetricsLogger mService; + private long mServiceUnblockedTimestampMillis = 0; + private int mNumSkippedEvents = 0; + public ConnectivityMetricsLogger() { mService = IConnectivityMetricsLogger.Stub.asInterface(ServiceManager.getService( CONNECTIVITY_METRICS_LOGGER_SERVICE)); @@ -46,12 +57,51 @@ public class ConnectivityMetricsLogger { if (DBG) { Log.d(TAG, "logEvent(" + componentTag + "," + eventTag + ") Service not ready"); } - } else { - try { - mService.logEvent(new ConnectivityMetricsEvent(timestamp, componentTag, eventTag, data)); - } catch (RemoteException e) { - Log.e(TAG, "Error logging event " + e.getMessage()); + return; + } + + if (mServiceUnblockedTimestampMillis > 0) { + if (System.currentTimeMillis() < mServiceUnblockedTimestampMillis) { + // Service is throttling events. + // Don't send new events because they will be dropped. + mNumSkippedEvents++; + return; } } + + ConnectivityMetricsEvent skippedEventsEvent = null; + if (mNumSkippedEvents > 0) { + // Log number of skipped events + Bundle b = new Bundle(); + b.putInt(DATA_KEY_EVENTS_COUNT, mNumSkippedEvents); + skippedEventsEvent = new ConnectivityMetricsEvent(mServiceUnblockedTimestampMillis, + componentTag, TAG_SKIPPED_EVENTS, b); + + mServiceUnblockedTimestampMillis = 0; + } + + ConnectivityMetricsEvent event = new ConnectivityMetricsEvent(timestamp, componentTag, + eventTag, data); + + try { + long result; + if (skippedEventsEvent == null) { + result = mService.logEvent(event); + } else { + result = mService.logEvents(new ConnectivityMetricsEvent[] + {skippedEventsEvent, event}); + } + + if (result == 0) { + mNumSkippedEvents = 0; + } else { + mNumSkippedEvents++; + if (result > 0) { // events are throttled + mServiceUnblockedTimestampMillis = result; + } + } + } catch (RemoteException e) { + Log.e(TAG, "Error logging event " + e.getMessage()); + } } } diff --git a/core/java/android/net/IConnectivityMetricsLogger.aidl b/core/java/android/net/IConnectivityMetricsLogger.aidl index 27786712a5c5c..a83a019352535 100644 --- a/core/java/android/net/IConnectivityMetricsLogger.aidl +++ b/core/java/android/net/IConnectivityMetricsLogger.aidl @@ -16,15 +16,28 @@ package android.net; +import android.app.PendingIntent; import android.net.ConnectivityMetricsEvent; -import android.net.IConnectivityMetricsLoggerSubscriber; /** {@hide} */ interface IConnectivityMetricsLogger { - void logEvent(in ConnectivityMetricsEvent event); - void logEvents(in ConnectivityMetricsEvent[] events); + /** + * @return 0 on success + * <0 if error happened + * >0 timestamp after which new events will be accepted + */ + long logEvent(in ConnectivityMetricsEvent event); + long logEvents(in ConnectivityMetricsEvent[] events); - boolean subscribe(in IConnectivityMetricsLoggerSubscriber subscriber); - void unsubscribe(in IConnectivityMetricsLoggerSubscriber subscriber); + /** + * @param reference of the last event previously returned. The function will return + * events following it. + * If 0 then all events will be returned. + * After the function call it will contain reference of the last event. + */ + ConnectivityMetricsEvent[] getEvents(inout ConnectivityMetricsEvent.Reference reference); + + boolean register(in PendingIntent newEventsIntent); + void unregister(in PendingIntent newEventsIntent); } diff --git a/core/java/android/net/IConnectivityMetricsLoggerSubscriber.aidl b/core/java/android/net/IConnectivityMetricsLoggerSubscriber.aidl deleted file mode 100644 index a2c62cdaee97d..0000000000000 --- a/core/java/android/net/IConnectivityMetricsLoggerSubscriber.aidl +++ /dev/null @@ -1,25 +0,0 @@ -/* - * 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; - -import android.net.ConnectivityMetricsEvent; - -/** {@hide} */ -oneway interface IConnectivityMetricsLoggerSubscriber { - - void onEvents(in ConnectivityMetricsEvent[] events); -} diff --git a/services/core/java/com/android/server/connectivity/MetricsLoggerService.java b/services/core/java/com/android/server/connectivity/MetricsLoggerService.java index f6dc9b98c1367..03dd7dcee6005 100644 --- a/services/core/java/com/android/server/connectivity/MetricsLoggerService.java +++ b/services/core/java/com/android/server/connectivity/MetricsLoggerService.java @@ -18,18 +18,21 @@ package com.android.server.connectivity; import com.android.server.SystemService; +import android.app.PendingIntent; import android.content.Context; +import android.content.pm.PackageManager; import android.net.ConnectivityMetricsEvent; import android.net.ConnectivityMetricsLogger; import android.net.IConnectivityMetricsLogger; -import android.net.IConnectivityMetricsLoggerSubscriber; -import android.os.IBinder; -import android.os.RemoteException; -import android.util.ArrayMap; +import android.os.Binder; +import android.os.Parcel; +import android.text.format.DateUtils; import android.util.Log; +import java.io.FileDescriptor; +import java.io.PrintWriter; +import java.util.ArrayDeque; import java.util.ArrayList; -import java.util.List; /** {@hide} */ public class MetricsLoggerService extends SystemService { @@ -43,134 +46,307 @@ public class MetricsLoggerService extends SystemService { @Override public void onStart() { + resetThrottlingCounters(System.currentTimeMillis()); } @Override public void onBootPhase(int phase) { if (phase == SystemService.PHASE_SYSTEM_SERVICES_READY) { - Log.d(TAG, "onBootPhase: PHASE_SYSTEM_SERVICES_READY"); + if (DBG) Log.d(TAG, "onBootPhase: PHASE_SYSTEM_SERVICES_READY"); publishBinderService(ConnectivityMetricsLogger.CONNECTIVITY_METRICS_LOGGER_SERVICE, mBinder); } } - private final int MAX_NUMBER_OF_EVENTS = 100; - private final int MAX_TIME_OFFSET = 15*60*1000; // 15 minutes - private final List mEvents = new ArrayList<>(); - private long mLastSentEventTimeMillis = System.currentTimeMillis(); + // TODO: read from system property + private final int MAX_NUMBER_OF_EVENTS = 1000; - private final void enforceConnectivityInternalPermission() { + // TODO: read from system property + private final int EVENTS_NOTIFICATION_THRESHOLD = 300; + + // TODO: read from system property + private final int THROTTLING_TIME_INTERVAL_MILLIS = 60 * 60 * 1000; // 1 hour + + // TODO: read from system property + private final int THROTTLING_MAX_NUMBER_OF_MESSAGES_PER_COMPONENT = 1000; + + private int mEventCounter = 0; + + /** + * Reference of the last event in the list of cached events. + * + * When client of this service retrieves events by calling getEvents, it is passing + * ConnectivityMetricsEvent.Reference object. After getEvents returns, that object will + * contain this reference. The client can save it and use next time it calls getEvents. + * This way only new events will be returned. + */ + private long mLastEventReference = 0; + + private final int mThrottlingCounters[] = + new int[ConnectivityMetricsLogger.NUMBER_OF_COMPONENTS]; + + private long mThrottlingIntervalBoundaryMillis; + + private final ArrayDeque mEvents = new ArrayDeque<>(); + + private void enforceConnectivityInternalPermission() { getContext().enforceCallingPermission( android.Manifest.permission.CONNECTIVITY_INTERNAL, "MetricsLoggerService"); } + private void enforceDumpPermission() { + getContext().enforceCallingPermission( + android.Manifest.permission.DUMP, + "MetricsLoggerService"); + } + + private void resetThrottlingCounters(long currentTimeMillis) { + for (int i = 0; i < mThrottlingCounters.length; i++) { + mThrottlingCounters[i] = 0; + } + mThrottlingIntervalBoundaryMillis = + currentTimeMillis + THROTTLING_TIME_INTERVAL_MILLIS; + } + + private void addEvent(ConnectivityMetricsEvent e) { + if (VDBG) { + Log.v(TAG, "writeEvent(" + e.toString() + ")"); + } + + while (mEvents.size() >= MAX_NUMBER_OF_EVENTS) { + mEvents.removeFirst(); + } + + mEvents.addLast(e); + } + /** * Implementation of the IConnectivityMetricsLogger interface. */ private final IConnectivityMetricsLogger.Stub mBinder = new IConnectivityMetricsLogger.Stub() { - private final ArrayMap mSubscribers = new ArrayMap<>(); + private final ArrayList mPendingIntents = new ArrayList<>(); - - private ConnectivityMetricsEvent[] prepareEventsToSendIfReady() { - ConnectivityMetricsEvent[] eventsToSend = null; - final long currentTimeMillis = System.currentTimeMillis(); - final long timeOffset = currentTimeMillis - mLastSentEventTimeMillis; - if (timeOffset >= MAX_TIME_OFFSET - || timeOffset < 0 // system time has changed - || mEvents.size() >= MAX_NUMBER_OF_EVENTS) { - // batch events - mLastSentEventTimeMillis = currentTimeMillis; - eventsToSend = new ConnectivityMetricsEvent[mEvents.size()]; - mEvents.toArray(eventsToSend); - mEvents.clear(); + @Override + protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) { + if (getContext().checkCallingOrSelfPermission(android.Manifest.permission.DUMP) + != PackageManager.PERMISSION_GRANTED) { + pw.println("Permission Denial: can't dump ConnectivityMetricsLoggerService " + + "from from pid=" + Binder.getCallingPid() + ", uid=" + + Binder.getCallingUid()); + return; } - return eventsToSend; - } - private void maybeSendEventsToSubscribers(ConnectivityMetricsEvent[] eventsToSend) { - if (eventsToSend == null || eventsToSend.length == 0) return; - synchronized (mSubscribers) { - for (IConnectivityMetricsLoggerSubscriber s : mSubscribers.keySet()) { - try { - s.onEvents(eventsToSend); - } catch (RemoteException ex) { - Log.e(TAG, "RemoteException " + ex); - } - } - } - } + boolean dumpSerializedSize = false; + boolean dumpEvents = false; + for (String arg : args) { + switch (arg) { + case "--events": + dumpEvents = true; + break; - public void logEvent(ConnectivityMetricsEvent event) { - ConnectivityMetricsEvent[] events = new ConnectivityMetricsEvent[]{event}; - logEvents(events); - } + case "--size": + dumpSerializedSize = true; + break; - public void logEvents(ConnectivityMetricsEvent[] events) { - enforceConnectivityInternalPermission(); - ConnectivityMetricsEvent[] eventsToSend; - - if (VDBG) { - for (ConnectivityMetricsEvent e : events) { - Log.v(TAG, "writeEvent(" + e.toString() + ")"); + case "--all": + dumpEvents = true; + dumpSerializedSize = true; + break; } } synchronized (mEvents) { - for (ConnectivityMetricsEvent e : events) { - mEvents.add(e); + pw.println("Number of events: " + mEvents.size()); + pw.println("Time span: " + + DateUtils.formatElapsedTime( + (System.currentTimeMillis() - mEvents.peekFirst().timestamp) + / 1000)); + + if (dumpSerializedSize) { + long dataSize = 0; + Parcel p = Parcel.obtain(); + for (ConnectivityMetricsEvent e : mEvents) { + dataSize += 16; // timestamp and 2 stamps + + p.writeParcelable(e.data, 0); + } + dataSize += p.dataSize(); + p.recycle(); + pw.println("Serialized data size: " + dataSize); } - eventsToSend = prepareEventsToSendIfReady(); + if (dumpEvents) { + pw.println(); + pw.println("Events:"); + for (ConnectivityMetricsEvent e : mEvents) { + pw.println(e.toString()); + } + } } - maybeSendEventsToSubscribers(eventsToSend); + if (!mPendingIntents.isEmpty()) { + pw.println(); + pw.println("Pending intents:"); + for (PendingIntent pi : mPendingIntents) { + pw.println(pi.toString()); + } + } } - public boolean subscribe(IConnectivityMetricsLoggerSubscriber subscriber) { - enforceConnectivityInternalPermission(); - if (VDBG) Log.v(TAG, "subscribe"); + public long logEvent(ConnectivityMetricsEvent event) { + ConnectivityMetricsEvent[] events = new ConnectivityMetricsEvent[]{event}; + return logEvents(events); + } - synchronized (mSubscribers) { - if (mSubscribers.containsKey(subscriber)) { - Log.e(TAG, "subscriber is already subscribed"); - return false; + /** + * @param events + * + * Note: All events must belong to the same component. + * + * @return 0 on success + * <0 if error happened + * >0 timestamp after which new events will be accepted + */ + public long logEvents(ConnectivityMetricsEvent[] events) { + enforceConnectivityInternalPermission(); + + if (events == null || events.length == 0) { + Log.wtf(TAG, "No events passed to logEvents()"); + return -1; + } + + int componentTag = events[0].componentTag; + if (componentTag < 0 || + componentTag >= ConnectivityMetricsLogger.NUMBER_OF_COMPONENTS) { + Log.wtf(TAG, "Unexpected tag: " + componentTag); + return -1; + } + + synchronized (mThrottlingCounters) { + long currentTimeMillis = System.currentTimeMillis(); + if (currentTimeMillis > mThrottlingIntervalBoundaryMillis) { + resetThrottlingCounters(currentTimeMillis); } - final IConnectivityMetricsLoggerSubscriber s = subscriber; - IBinder.DeathRecipient dr = new IBinder.DeathRecipient() { - @Override - public void binderDied() { - if (VDBG) Log.v(TAG, "subscriber died"); - synchronized (mSubscribers) { - mSubscribers.remove(s); + + mThrottlingCounters[componentTag] += events.length; + + if (mThrottlingCounters[componentTag] > + THROTTLING_MAX_NUMBER_OF_MESSAGES_PER_COMPONENT) { + Log.w(TAG, "Too many events from #" + componentTag + + ". Block until " + mThrottlingIntervalBoundaryMillis); + + return mThrottlingIntervalBoundaryMillis; + } + } + + boolean sendPendingIntents = false; + + synchronized (mEvents) { + for (ConnectivityMetricsEvent e : events) { + if (e.componentTag != componentTag) { + Log.wtf(TAG, "Unexpected tag: " + e.componentTag); + return -1; + } + + addEvent(e); + } + + mLastEventReference += events.length; + + mEventCounter += events.length; + if (mEventCounter >= EVENTS_NOTIFICATION_THRESHOLD) { + mEventCounter = 0; + sendPendingIntents = true; + } + } + + if (sendPendingIntents) { + synchronized (mPendingIntents) { + for (PendingIntent pi : mPendingIntents) { + if (VDBG) Log.v(TAG, "Send pending intent"); + try { + pi.send(getContext(), 0, null, null, null); + } catch (PendingIntent.CanceledException e) { + Log.e(TAG, "Pending intent canceled: " + pi); + mPendingIntents.remove(pi); } } - }; - - try { - subscriber.asBinder().linkToDeath(dr, 0); - mSubscribers.put(subscriber, dr); - } catch (RemoteException e) { - Log.e(TAG, "subscribe failed: " + e); - return false; } } + return 0; + } + + /** + * Retrieve events + * + * @param reference of the last event previously returned. The function will return + * events following it. + * If 0 then all events will be returned. + * After the function call it will contain reference of the + * last returned event. + * @return events + */ + public ConnectivityMetricsEvent[] getEvents(ConnectivityMetricsEvent.Reference reference) { + enforceDumpPermission(); + long ref = reference.value; + if (VDBG) Log.v(TAG, "getEvents(" + ref + ")"); + + ConnectivityMetricsEvent[] result; + synchronized (mEvents) { + if (ref > mLastEventReference) { + Log.e(TAG, "Invalid reference"); + reference.value = mLastEventReference; + return null; + } + if (ref < mLastEventReference - mEvents.size()) { + ref = mLastEventReference - mEvents.size(); + } + + int numEventsToSkip = + mEvents.size() // Total number of events + - (int)(mLastEventReference - ref); // Number of events to return + + result = new ConnectivityMetricsEvent[mEvents.size() - numEventsToSkip]; + int i = 0; + for (ConnectivityMetricsEvent e : mEvents) { + if (numEventsToSkip > 0) { + numEventsToSkip--; + } else { + result[i++] = e; + } + } + } + + reference.value = mLastEventReference; + + return result; + } + + public boolean register(PendingIntent newEventsIntent) { + enforceDumpPermission(); + if (VDBG) Log.v(TAG, "register(" + newEventsIntent + ")"); + + synchronized (mPendingIntents) { + if (mPendingIntents.remove(newEventsIntent)) { + Log.w(TAG, "Replacing registered pending intent"); + } + mPendingIntents.add(newEventsIntent); + } + return true; } - public void unsubscribe(IConnectivityMetricsLoggerSubscriber subscriber) { - enforceConnectivityInternalPermission(); - if (VDBG) Log.v(TAG, "unsubscribe"); - synchronized (mSubscribers) { - IBinder.DeathRecipient dr = mSubscribers.remove(subscriber); - if (dr == null) { - Log.e(TAG, "subscriber is not subscribed"); - return; + public void unregister(PendingIntent newEventsIntent) { + enforceDumpPermission(); + if (VDBG) Log.v(TAG, "unregister(" + newEventsIntent + ")"); + + synchronized (mPendingIntents) { + if (!mPendingIntents.remove(newEventsIntent)) { + Log.e(TAG, "Pending intent is not registered"); } - subscriber.asBinder().unlinkToDeath(dr, 0); } } };