"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",
--- /dev/null
+# 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)
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;
/** @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;
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);
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;
+ }
}
* 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;
* 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 {
@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;
}
/**
* @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));
}
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();
}
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;
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;
pw.println("ms");
}
mUidObservers.finishBroadcast();
+
+ pw.println();
+ pw.println(" ServiceManager statistics:");
+ ServiceManager.sStatLogger.dump(pw, " ");
+ pw.println();
}
}
pw.println(" mForceBackgroundCheck=" + mForceBackgroundCheck);
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;
// 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(),
// 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
setNetworkTemplateEnabled(policy.template, networkEnabled);
}
+
+ mStatLogger.logDurationStat(Stats.UPDATE_NETWORK_ENABLED, startTime);
}
/**
}
fout.decreaseIndent();
+ fout.println();
+ mStatLogger.dump(fout);
+
mLogger.dumpLogs(fout);
}
}
@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) {
*/
@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
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;
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;
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;