Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge "Add stats logging to ServiceManager and NPMS" into pi-dev

Browse Source 
am: a26e755900

Change-Id: Ib0bd9ecc183b1b2c9a6785554e6f717744820da3
This commit is contained in:
Makoto Onuki
2018-04-11 18:39:53 -07:00
committed by android-build-merger
parent 5327a38956 a26e755900
commit fa3a2acfbc
10 changed files with 238 additions and 15 deletions
Download Patch File Download Diff File Expand all files Collapse all files

1
Android.bp
View File

@@ -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",

6
core/java/android/os/EventLogTags.logtags Normal file
View File

@@ -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)

126
core/java/android/os/ServiceManager.java
View File

@@ -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;
}
}

71
services/core/java/com/android/server/StatLogger.java → core/java/com/android/internal/util/StatLogger.java
View File

@@ -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();
}

1
services/core/java/com/android/server/AlarmManagerService.java
View File

@@ -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;

1
services/core/java/com/android/server/AppStateTracker.java
View File

@@ -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;

5
services/core/java/com/android/server/am/ActivityManagerService.java
View File

@@ -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);

37
services/core/java/com/android/server/net/NetworkPolicyManagerService.java
View File

@@ -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

3
services/core/java/com/android/server/pm/ShortcutService.java
View File

@@ -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;

2
services/devicepolicy/java/com/android/server/devicepolicy/DevicePolicyManagerService.java
View File

@@ -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;