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/services/core/java/com/android/server/AlarmManagerService.java b/services/core/java/com/android/server/AlarmManagerService.java
index 8ce4e64..6f4ae15 100644
--- 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.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
--- 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.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/StatLogger.java b/services/core/java/com/android/server/StatLogger.java
deleted file mode 100644
index d85810d..0000000
--- a/services/core/java/com/android/server/StatLogger.java
+++ /dev/null
@@ -1,120 +0,0 @@
-/*
- * Copyright (C) 2018 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;
-
-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.Event;
-
-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 {
- private static final String TAG = "StatLogger";
-
- private final Object mLock = new Object();
-
- private final int SIZE;
-
- @GuardedBy("mLock")
- private final int[] mCountStats;
-
- @GuardedBy("mLock")
- private final long[] mDurationStats;
-
- private final String[] mLabels;
-
- public StatLogger(String[] eventLabels) {
- SIZE = eventLabels.length;
- mCountStats = new int[SIZE];
- mDurationStats = new long[SIZE];
- mLabels = eventLabels;
- }
-
- /**
- * Return the current time in the internal time unit.
- * Call it before an event happens, and
- * give it back to the {@link #logDurationStat(int, long)}} after the event.
- */
- public long getTime() {
- return SystemClock.elapsedRealtimeNanos() / 1000;
- }
-
- /**
- * @see {@link #getTime()}
- */
- public void logDurationStat(int eventId, long start) {
- synchronized (mLock) {
- if (eventId >= 0 && eventId < SIZE) {
- mCountStats[eventId]++;
- mDurationStats[eventId] += (getTime() - start);
- } else {
- Slog.wtf(TAG, "Invalid event ID: " + eventId);
- }
- }
- }
-
- @Deprecated
- public void dump(PrintWriter pw, String prefix) {
- dump(new IndentingPrintWriter(pw, " ").setIndent(prefix));
- }
-
- public void dump(IndentingPrintWriter pw) {
- synchronized (mLock) {
- pw.println("Stats:");
- pw.increaseIndent();
- 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",
- mLabels[i], count, durationMs,
- (count == 0 ? 0 : ((double) durationMs) / count)));
- }
- pw.decreaseIndent();
- }
- }
-
- public void dumpProto(ProtoOutputStream proto, long fieldId) {
- synchronized (mLock) {
- final long outer = proto.start(fieldId);
-
- for (int i = 0; i < mLabels.length; i++) {
- final long inner = proto.start(StatLoggerProto.EVENTS);
-
- proto.write(Event.EVENT_ID, i);
- proto.write(Event.LABEL, mLabels[i]);
- proto.write(Event.COUNT, mCountStats[i]);
- proto.write(Event.TOTAL_DURATION_MICROS, mDurationStats[i]);
-
- proto.end(inner);
- }
-
- proto.end(outer);
- }
- }
-}
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
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -16997,6 +16997,11 @@
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
--- 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.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 @@
// 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 @@
// 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 @@
setNetworkTemplateEnabled(policy.template, networkEnabled);
}
+
+ mStatLogger.logDurationStat(Stats.UPDATE_NETWORK_ENABLED, startTime);
}
/**
@@ -3256,6 +3274,9 @@
}
fout.decreaseIndent();
+ fout.println();
+ mStatLogger.dump(fout);
+
mLogger.dumpLogs(fout);
}
}
@@ -4615,8 +4636,14 @@
@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 @@
*/
@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
--- 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.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.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;