Add stats logging to ServiceManager and NPMS

ServiceManager:
- Do an event log every N getService() calls with total time spent
in getService().
where N = 100 for core UIDs and 200 for other apps.

- Do an event log if getService() takes longer than N ms.
where N = 10 for core UIDs and 50 for other apps.

... with some extra throttling.

NPMS:
- Do the basic "stats logger" log for updateNetworkEnabledNL() and
isUidNetworkingBlocked()

This CL also enhances StatsLogegr so it now can show the slowest call
and the max # of calls per-second.

Bug: 77853238
Test: Manual test:
- Insert a SIM card
- Set data limit
- toggle airplane mode
- toggle wifi
- toggle mobile data

Then
- "dumpsys netpolicy" and "dumpsys activity processes" and check the stats
- also check "adb logcat -b all | grep ' service_manager'"

Change-Id: I5789541063f95d0eac501189816c8604a4571ba0

diff --git a/Android.bp b/Android.bp
index 9c76e14..22fe23d 100644 (file)
--- a/Android.bp
+++ b/Android.bp
@@ -603,6 +603,7 @@ java_library {
         "core/java/android/content/EventLogTags.logtags",
         "core/java/android/speech/tts/EventLogTags.logtags",
         "core/java/android/net/EventLogTags.logtags",
+        "core/java/android/os/EventLogTags.logtags",
         "core/java/android/webkit/EventLogTags.logtags",
         "core/java/com/android/internal/app/EventLogTags.logtags",
         "core/java/com/android/internal/logging/EventLogTags.logtags",

diff --git a/core/java/android/os/EventLogTags.logtags b/core/java/android/os/EventLogTags.logtags
new file mode 100644 (file)
index 0000000..b143a74
--- /dev/null
+++ b/core/java/android/os/EventLogTags.logtags
@@ -0,0 +1,6 @@
+# See system/core/logcat/event.logtags for a description of the format of this file.
+
+option java_package android.os
+
+230000 service_manager_stats (call_count|1),(total_time|1|3),(duration|1|3)
+230001 service_manager_slow (time|1|3),(service|3)

diff --git a/core/java/android/os/ServiceManager.java b/core/java/android/os/ServiceManager.java
index 3be76d6..165276d 100644 (file)
--- a/core/java/android/os/ServiceManager.java
+++ b/core/java/android/os/ServiceManager.java
@@ -18,7 +18,9 @@ package android.os;
 
 import android.util.Log;
 
+import com.android.internal.annotations.GuardedBy;
 import com.android.internal.os.BinderInternal;
+import com.android.internal.util.StatLogger;
 
 import java.util.HashMap;
 import java.util.Map;
@@ -26,9 +28,76 @@ import java.util.Map;
 /** @hide */
 public final class ServiceManager {
     private static final String TAG = "ServiceManager";
+    private static final Object sLock = new Object();
+
     private static IServiceManager sServiceManager;
+
+    /**
+     * Cache for the "well known" services, such as WM and AM.
+     */
     private static HashMap<String, IBinder> sCache = new HashMap<String, IBinder>();
 
+    /**
+     * We do the "slow log" at most once every this interval.
+     */
+    private static final int SLOW_LOG_INTERVAL_MS = 5000;
+
+    /**
+     * We do the "stats log" at most once every this interval.
+     */
+    private static final int STATS_LOG_INTERVAL_MS = 5000;
+
+    /**
+     * Threshold in uS for a "slow" call, used on core UIDs. We use a more relax value to
+     * avoid logspam.
+     */
+    private static final long GET_SERVICE_SLOW_THRESHOLD_US_CORE =
+            SystemProperties.getInt("debug.servicemanager.slow_call_core_ms", 10) * 1000;
+
+    /**
+     * Threshold in uS for a "slow" call, used on non-core UIDs. We use a more relax value to
+     * avoid logspam.
+     */
+    private static final long GET_SERVICE_SLOW_THRESHOLD_US_NON_CORE =
+            SystemProperties.getInt("debug.servicemanager.slow_call_ms", 50) * 1000;
+
+    /**
+     * We log stats logging ever this many getService() calls.
+     */
+    private static final int GET_SERVICE_LOG_EVERY_CALLS_CORE =
+            SystemProperties.getInt("debug.servicemanager.log_calls_core", 100);
+
+    /**
+     * We log stats logging ever this many getService() calls.
+     */
+    private static final int GET_SERVICE_LOG_EVERY_CALLS_NON_CORE =
+            SystemProperties.getInt("debug.servicemanager.log_calls", 200);
+
+    @GuardedBy("sLock")
+    private static int sGetServiceAccumulatedUs;
+
+    @GuardedBy("sLock")
+    private static int sGetServiceAccumulatedCallCount;
+
+    @GuardedBy("sLock")
+    private static long sLastStatsLogUptime;
+
+    @GuardedBy("sLock")
+    private static long sLastSlowLogUptime;
+
+    @GuardedBy("sLock")
+    private static long sLastSlowLogActualTime;
+
+    interface Stats {
+        int GET_SERVICE = 0;
+
+        int COUNT = GET_SERVICE + 1;
+    }
+
+    public static final StatLogger sStatLogger = new StatLogger(new String[] {
+            "getService()",
+    });
+
     private static IServiceManager getIServiceManager() {
         if (sServiceManager != null) {
             return sServiceManager;
@@ -52,7 +121,7 @@ public final class ServiceManager {
             if (service != null) {
                 return service;
             } else {
-                return Binder.allowBlocking(getIServiceManager().getService(name));
+                return Binder.allowBlocking(rawGetService(name));
             }
         } catch (RemoteException e) {
             Log.e(TAG, "error in getService", e);
@@ -177,4 +246,59 @@ public final class ServiceManager {
             super("No service published for: " + name);
         }
     }
+
+    private static IBinder rawGetService(String name) throws RemoteException {
+        final long start = sStatLogger.getTime();
+
+        final IBinder binder = getIServiceManager().getService(name);
+
+        final int time = (int) sStatLogger.logDurationStat(Stats.GET_SERVICE, start);
+
+        final int myUid = Process.myUid();
+        final boolean isCore = UserHandle.isCore(myUid);
+
+        final long slowThreshold = isCore
+                ? GET_SERVICE_SLOW_THRESHOLD_US_CORE
+                : GET_SERVICE_SLOW_THRESHOLD_US_NON_CORE;
+
+        synchronized (sLock) {
+            sGetServiceAccumulatedUs += time;
+            sGetServiceAccumulatedCallCount++;
+
+            final long nowUptime = SystemClock.uptimeMillis();
+
+            // Was a slow call?
+            if (time >= slowThreshold) {
+                // We do a slow log:
+                // - At most once in every SLOW_LOG_INTERVAL_MS
+                // - OR it was slower than the previously logged slow call.
+                if ((nowUptime > (sLastSlowLogUptime + SLOW_LOG_INTERVAL_MS))
+                        || (sLastSlowLogActualTime < time)) {
+                    EventLogTags.writeServiceManagerSlow(time / 1000, name);
+
+                    sLastSlowLogUptime = nowUptime;
+                    sLastSlowLogActualTime = time;
+                }
+            }
+
+            // Every GET_SERVICE_LOG_EVERY_CALLS calls, log the total time spent in getService().
+
+            final int logInterval = isCore
+                    ? GET_SERVICE_LOG_EVERY_CALLS_CORE
+                    : GET_SERVICE_LOG_EVERY_CALLS_NON_CORE;
+
+            if ((sGetServiceAccumulatedCallCount >= logInterval)
+                    && (nowUptime >= (sLastStatsLogUptime + STATS_LOG_INTERVAL_MS))) {
+
+                EventLogTags.writeServiceManagerStats(
+                        sGetServiceAccumulatedCallCount, // Total # of getService() calls.
+                        sGetServiceAccumulatedUs / 1000, // Total time spent in getService() calls.
+                        (int) (nowUptime - sLastStatsLogUptime)); // Uptime duration since last log.
+                sGetServiceAccumulatedCallCount = 0;
+                sGetServiceAccumulatedUs = 0;
+                sLastStatsLogUptime = nowUptime;
+            }
+        }
+        return binder;
+    }
 }

diff --git a/services/core/java/com/android/server/StatLogger.java b/core/java/com/android/internal/util/StatLogger.java
similarity index 58%
rename from services/core/java/com/android/server/StatLogger.java
rename to core/java/com/android/internal/util/StatLogger.java
index d85810d..1dac136 100644 (file)
--- a/services/core/java/com/android/server/StatLogger.java
+++ b/core/java/com/android/internal/util/StatLogger.java
@@ -14,14 +14,14 @@
  * limitations under the License.
  */
 
-package com.android.server;
+package com.android.internal.util;
 
 import android.os.SystemClock;
 import android.util.Slog;
 import android.util.proto.ProtoOutputStream;
 
 import com.android.internal.annotations.GuardedBy;
-import com.android.internal.util.IndentingPrintWriter;
+import com.android.server.StatLoggerProto;
 import com.android.server.StatLoggerProto.Event;
 
 import java.io.PrintWriter;
@@ -30,8 +30,6 @@ import java.io.PrintWriter;
  * Simple class to keep track of the number of times certain events happened and their durations for
  * benchmarking.
  *
- * TODO Update shortcut service to switch to it.
- *
  * @hide
  */
 public class StatLogger {
@@ -47,12 +45,35 @@ public class StatLogger {
     @GuardedBy("mLock")
     private final long[] mDurationStats;
 
+    @GuardedBy("mLock")
+    private final int[] mCallsPerSecond;
+
+    @GuardedBy("mLock")
+    private final long[] mDurationPerSecond;
+
+    @GuardedBy("mLock")
+    private final int[] mMaxCallsPerSecond;
+
+    @GuardedBy("mLock")
+    private final long[] mMaxDurationPerSecond;
+
+    @GuardedBy("mLock")
+    private final long[] mMaxDurationStats;
+
+    @GuardedBy("mLock")
+    private long mNextTickTime = SystemClock.elapsedRealtime() + 1000;
+
     private final String[] mLabels;
 
     public StatLogger(String[] eventLabels) {
         SIZE = eventLabels.length;
         mCountStats = new int[SIZE];
         mDurationStats = new long[SIZE];
+        mCallsPerSecond = new int[SIZE];
+        mMaxCallsPerSecond = new int[SIZE];
+        mDurationPerSecond = new long[SIZE];
+        mMaxDurationPerSecond = new long[SIZE];
+        mMaxDurationStats = new long[SIZE];
         mLabels = eventLabels;
     }
 
@@ -67,19 +88,46 @@ public class StatLogger {
 
     /**
      * @see {@link #getTime()}
+     *
+     * @return the duration in microseconds.
      */
-    public void logDurationStat(int eventId, long start) {
+    public long logDurationStat(int eventId, long start) {
         synchronized (mLock) {
+            final long duration = getTime() - start;
             if (eventId >= 0 && eventId < SIZE) {
                 mCountStats[eventId]++;
-                mDurationStats[eventId] += (getTime() - start);
+                mDurationStats[eventId] += duration;
             } else {
                 Slog.wtf(TAG, "Invalid event ID: " + eventId);
+                return duration;
+            }
+            if (mMaxDurationStats[eventId] < duration) {
+                mMaxDurationStats[eventId] = duration;
+            }
+
+            // Keep track of the per-second max.
+            final long nowRealtime = SystemClock.elapsedRealtime();
+            if (nowRealtime > mNextTickTime) {
+                if (mMaxCallsPerSecond[eventId] < mCallsPerSecond[eventId]) {
+                    mMaxCallsPerSecond[eventId] = mCallsPerSecond[eventId];
+                }
+                if (mMaxDurationPerSecond[eventId] < mDurationPerSecond[eventId]) {
+                    mMaxDurationPerSecond[eventId] = mDurationPerSecond[eventId];
+                }
+
+                mCallsPerSecond[eventId] = 0;
+                mDurationPerSecond[eventId] = 0;
+
+                mNextTickTime = nowRealtime + 1000;
             }
+
+            mCallsPerSecond[eventId]++;
+            mDurationPerSecond[eventId] += duration;
+
+            return duration;
         }
     }
 
-    @Deprecated
     public void dump(PrintWriter pw, String prefix) {
         dump(new IndentingPrintWriter(pw, "  ").setIndent(prefix));
     }
@@ -91,9 +139,14 @@ public class StatLogger {
             for (int i = 0; i < SIZE; i++) {
                 final int count = mCountStats[i];
                 final double durationMs = mDurationStats[i] / 1000.0;
-                pw.println(String.format("%s: count=%d, total=%.1fms, avg=%.3fms",
+
+                pw.println(String.format(
+                        "%s: count=%d, total=%.1fms, avg=%.3fms, max calls/s=%d max dur/s=%.1fms"
+                        + " max time=%.1fms",
                         mLabels[i], count, durationMs,
-                        (count == 0 ? 0 : ((double) durationMs) / count)));
+                        (count == 0 ? 0 : durationMs / count),
+                        mMaxCallsPerSecond[i], mMaxDurationPerSecond[i] / 1000.0,
+                        mMaxDurationStats[i] / 1000.0));
             }
             pw.decreaseIndent();
         }

diff --git a/services/core/java/com/android/server/AlarmManagerService.java b/services/core/java/com/android/server/AlarmManagerService.java
index 8ce4e64..6f4ae15 100644 (file)
--- a/services/core/java/com/android/server/AlarmManagerService.java
+++ b/services/core/java/com/android/server/AlarmManagerService.java
@@ -88,6 +88,7 @@ import com.android.internal.annotations.VisibleForTesting;
 import com.android.internal.util.ArrayUtils;
 import com.android.internal.util.DumpUtils;
 import com.android.internal.util.LocalLog;
+import com.android.internal.util.StatLogger;
 import com.android.server.AppStateTracker.Listener;
 
 import java.io.ByteArrayOutputStream;

diff --git a/services/core/java/com/android/server/AppStateTracker.java b/services/core/java/com/android/server/AppStateTracker.java
index cec4f1a..23c5779 100644 (file)
--- a/services/core/java/com/android/server/AppStateTracker.java
+++ b/services/core/java/com/android/server/AppStateTracker.java
@@ -55,6 +55,7 @@ import com.android.internal.app.IAppOpsService;
 import com.android.internal.util.ArrayUtils;
 import com.android.internal.util.IndentingPrintWriter;
 import com.android.internal.util.Preconditions;
+import com.android.internal.util.StatLogger;
 import com.android.server.ForceAppStandbyTrackerProto.ExemptedPackage;
 import com.android.server.ForceAppStandbyTrackerProto.RunAnyInBackgroundRestrictedPackages;
 

diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index 75bad46..4c1281e 100644 (file)
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -16997,6 +16997,11 @@ public class ActivityManagerService extends IActivityManager.Stub
                     pw.println("ms");
                 }
                 mUidObservers.finishBroadcast();
+
+                pw.println();
+                pw.println("  ServiceManager statistics:");
+                ServiceManager.sStatLogger.dump(pw, "    ");
+                pw.println();
             }
         }
         pw.println("  mForceBackgroundCheck=" + mForceBackgroundCheck);

diff --git a/services/core/java/com/android/server/net/NetworkPolicyManagerService.java b/services/core/java/com/android/server/net/NetworkPolicyManagerService.java
index 1782ae5..253a19f 100644 (file)
--- a/services/core/java/com/android/server/net/NetworkPolicyManagerService.java
+++ b/services/core/java/com/android/server/net/NetworkPolicyManagerService.java
@@ -215,6 +215,7 @@ import com.android.internal.util.DumpUtils;
 import com.android.internal.util.FastXmlSerializer;
 import com.android.internal.util.IndentingPrintWriter;
 import com.android.internal.util.Preconditions;
+import com.android.internal.util.StatLogger;
 import com.android.server.EventLogTags;
 import com.android.server.LocalServices;
 import com.android.server.ServiceThread;
@@ -539,6 +540,19 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
 
     // TODO: migrate notifications to SystemUI
 
+
+    interface Stats {
+        int UPDATE_NETWORK_ENABLED = 0;
+        int IS_UID_NETWORKING_BLOCKED = 1;
+
+        int COUNT = IS_UID_NETWORKING_BLOCKED + 1;
+    }
+
+    public final StatLogger mStatLogger = new StatLogger(new String[] {
+            "updateNetworkEnabledNL()",
+            "isUidNetworkingBlocked()",
+    });
+
     public NetworkPolicyManagerService(Context context, IActivityManager activityManager,
             INetworkManagementService networkManagement) {
         this(context, activityManager, networkManagement, AppGlobals.getPackageManager(),
@@ -1551,6 +1565,8 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
         // TODO: reset any policy-disabled networks when any policy is removed
         // completely, which is currently rare case.
 
+        final long startTime = mStatLogger.getTime();
+
         for (int i = mNetworkPolicy.size()-1; i >= 0; i--) {
             final NetworkPolicy policy = mNetworkPolicy.valueAt(i);
             // shortcut when policy has no limit
@@ -1572,6 +1588,8 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
 
             setNetworkTemplateEnabled(policy.template, networkEnabled);
         }
+
+        mStatLogger.logDurationStat(Stats.UPDATE_NETWORK_ENABLED, startTime);
     }
 
     /**
@@ -3256,6 +3274,9 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
                 }
                 fout.decreaseIndent();
 
+                fout.println();
+                mStatLogger.dump(fout);
+
                 mLogger.dumpLogs(fout);
             }
         }
@@ -4615,8 +4636,14 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
 
     @Override
     public boolean isUidNetworkingBlocked(int uid, boolean isNetworkMetered) {
+        final long startTime = mStatLogger.getTime();
+
         mContext.enforceCallingOrSelfPermission(MANAGE_NETWORK_POLICY, TAG);
-        return isUidNetworkingBlockedInternal(uid, isNetworkMetered);
+        final boolean ret = isUidNetworkingBlockedInternal(uid, isNetworkMetered);
+
+        mStatLogger.logDurationStat(Stats.IS_UID_NETWORKING_BLOCKED, startTime);
+
+        return ret;
     }
 
     private boolean isUidNetworkingBlockedInternal(int uid, boolean isNetworkMetered) {
@@ -4691,11 +4718,17 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
          */
         @Override
         public boolean isUidNetworkingBlocked(int uid, String ifname) {
+            final long startTime = mStatLogger.getTime();
+
             final boolean isNetworkMetered;
             synchronized (mNetworkPoliciesSecondLock) {
                 isNetworkMetered = mMeteredIfaces.contains(ifname);
             }
-            return isUidNetworkingBlockedInternal(uid, isNetworkMetered);
+            final boolean ret = isUidNetworkingBlockedInternal(uid, isNetworkMetered);
+
+            mStatLogger.logDurationStat(Stats.IS_UID_NETWORKING_BLOCKED, startTime);
+
+            return ret;
         }
 
         @Override

diff --git a/services/core/java/com/android/server/pm/ShortcutService.java b/services/core/java/com/android/server/pm/ShortcutService.java
index 15b4617..599e5a5 100644 (file)
--- a/services/core/java/com/android/server/pm/ShortcutService.java
+++ b/services/core/java/com/android/server/pm/ShortcutService.java
@@ -48,7 +48,6 @@ import android.content.pm.ResolveInfo;
 import android.content.pm.ShortcutInfo;
 import android.content.pm.ShortcutServiceInternal;
 import android.content.pm.ShortcutServiceInternal.ShortcutChangeListener;
-import android.content.pm.UserInfo;
 import android.content.res.Resources;
 import android.content.res.XmlResourceParser;
 import android.graphics.Bitmap;
@@ -100,7 +99,7 @@ import com.android.internal.util.DumpUtils;
 import com.android.internal.util.FastXmlSerializer;
 import com.android.internal.util.Preconditions;
 import com.android.server.LocalServices;
-import com.android.server.StatLogger;
+import com.android.internal.util.StatLogger;
 import com.android.server.SystemService;
 import com.android.server.pm.ShortcutUser.PackageWithUser;
 

diff --git a/services/devicepolicy/java/com/android/server/devicepolicy/DevicePolicyManagerService.java b/services/devicepolicy/java/com/android/server/devicepolicy/DevicePolicyManagerService.java
index 82d2f3c..e07b89f 100644 (file)
--- a/services/devicepolicy/java/com/android/server/devicepolicy/DevicePolicyManagerService.java
+++ b/services/devicepolicy/java/com/android/server/devicepolicy/DevicePolicyManagerService.java
@@ -220,7 +220,7 @@ import com.android.internal.util.XmlUtils;
 import com.android.internal.widget.LockPatternUtils;
 import com.android.server.LocalServices;
 import com.android.server.LockGuard;
-import com.android.server.StatLogger;
+import com.android.internal.util.StatLogger;
 import com.android.server.SystemServerInitThreadPool;
 import com.android.server.SystemService;
 import com.android.server.devicepolicy.DevicePolicyManagerService.ActiveAdmin.TrustAgentInfo;