diff --git a/Android.bp b/Android.bp index 93d1f7ba80164..a6290f11c433f 100644 --- 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 index 0000000000000..b143a74430661 --- /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 3be76d6049f4a..165276d5c17e8 100644 --- 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 sCache = new HashMap(); + /** + * 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 d85810d31e73a..1dac136cb048b 100644 --- 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 8ce4e64b19255..6f4ae15bd9736 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.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 cec4f1a0bdd73..23c57797c1f56 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.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 7602c26fe3095..b54ae16954d7c 100644 --- a/services/core/java/com/android/server/am/ActivityManagerService.java +++ b/services/core/java/com/android/server/am/ActivityManagerService.java @@ -16930,6 +16930,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 0c6555b94e9a7..a85960a186b77 100644 --- a/services/core/java/com/android/server/net/NetworkPolicyManagerService.java +++ b/services/core/java/com/android/server/net/NetworkPolicyManagerService.java @@ -220,6 +220,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; @@ -548,6 +549,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(), @@ -1591,6 +1605,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 @@ -1612,6 +1628,8 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub { setNetworkTemplateEnabled(policy.template, networkEnabled); } + + mStatLogger.logDurationStat(Stats.UPDATE_NETWORK_ENABLED, startTime); } /** @@ -3301,6 +3319,9 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub { } fout.decreaseIndent(); + fout.println(); + mStatLogger.dump(fout); + mLogger.dumpLogs(fout); } } @@ -4660,8 +4681,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) { @@ -4736,11 +4763,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 15b4617294952..599e5a573437d 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.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 82d2f3c102770..e07b89f232b1f 100644 --- 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;