ConnectivityService: log wakelock activity in dumps
This patch adds wakelock acquire and release activity to
ConnectivityService logs in dumpsys. All of the last 20 acquire and
release operations are logged.
This patch also:
- does a bit of cleanup to related dumpsys logs
- unify pretty printing of internal event ids to their names.
- delete mInetLog which was obsolete and not used.
Example of logs:
NetTransition WakeLock activity (most recent first):
03-30 02:15:40.628 - RELEASE 1 by EVENT_EXPIRE_NET_TRANSITION_WAKELOCK: not released (serial number was 2)
03-30 02:15:09.965 - ACQUIRE 2 for NetworkAgentInfo [WIFI () - 101]
03-30 02:15:01.877 - RELEASE 1 by EVENT_CLEAR_NET_TRANSITION_WAKELOCK: released
03-30 02:14:40.598 - ACQUIRE 1 for NetworkAgentInfo [WIFI () - 100]
Test: inspected result of $ adb shell dumpsys connectivity
Bug: 36703718
Change-Id: Ia8e2016fc512ee798ef0adc3f612d1f6c33d4870
diff --git a/services/core/java/com/android/server/ConnectivityService.java b/services/core/java/com/android/server/ConnectivityService.java
index 7466f54..13a6cd6 100644
--- a/services/core/java/com/android/server/ConnectivityService.java
+++ b/services/core/java/com/android/server/ConnectivityService.java
@@ -395,6 +395,10 @@
*/
private static final int EVENT_REGISTER_NETWORK_LISTENER_WITH_INTENT = 31;
+ private static String eventName(int what) {
+ return sMagicDecoderRing.get(what, Integer.toString(what));
+ }
+
/** Handler thread used for both of the handlers below. */
@VisibleForTesting
protected final HandlerThread mHandlerThread;
@@ -407,15 +411,10 @@
private Intent mInitialBroadcast;
private PowerManager.WakeLock mNetTransitionWakeLock;
- private String mNetTransitionWakeLockCausedBy = "";
private int mNetTransitionWakeLockSerialNumber;
private int mNetTransitionWakeLockTimeout;
private final PowerManager.WakeLock mPendingIntentWakeLock;
- // used in DBG mode to track inet condition reports
- private static final int INET_CONDITION_LOG_MAX_SIZE = 15;
- private ArrayList mInetLog;
-
// track the current default http proxy - tell the world if we get a new one (real change)
private volatile ProxyInfo mDefaultProxy = null;
private Object mProxyLock = new Object();
@@ -457,10 +456,12 @@
private final LocalLog mNetworkRequestInfoLogs = new LocalLog(MAX_NETWORK_REQUEST_LOGS);
// NetworkInfo blocked and unblocked String log entries
- // TODO: consider reducing memory usage. Each log line is ~40 2B chars, for a total of ~8kB.
- private static final int MAX_NETWORK_INFO_LOGS = 100;
+ private static final int MAX_NETWORK_INFO_LOGS = 40;
private final LocalLog mNetworkInfoBlockingLogs = new LocalLog(MAX_NETWORK_INFO_LOGS);
+ private static final int MAX_WAKELOCK_LOGS = 20;
+ private final LocalLog mWakelockLogs = new LocalLog(MAX_WAKELOCK_LOGS);
+
// Array of <Network,ReadOnlyLocalLogs> tracking network validation and results
private static final int MAX_VALIDATION_LOGS = 10;
private static class ValidationLog {
@@ -815,10 +816,6 @@
loge("Error registering observer :" + e);
}
- if (DBG) {
- mInetLog = new ArrayList();
- }
-
mSettingsObserver = new SettingsObserver(mContext, mHandler);
registerSettingsCallbacks();
@@ -1041,22 +1038,19 @@
if (ni == null || !LOGD_BLOCKED_NETWORKINFO) {
return;
}
- boolean removed = false;
- boolean added = false;
+ final boolean blocked;
synchronized (mBlockedAppUids) {
if (ni.getDetailedState() == DetailedState.BLOCKED && mBlockedAppUids.add(uid)) {
- added = true;
+ blocked = true;
} else if (ni.isConnected() && mBlockedAppUids.remove(uid)) {
- removed = true;
+ blocked = false;
+ } else {
+ return;
}
}
- if (added) {
- log("Returning blocked NetworkInfo to uid=" + uid);
- mNetworkInfoBlockingLogs.log("BLOCKED " + uid);
- } else if (removed) {
- log("Returning unblocked NetworkInfo to uid=" + uid);
- mNetworkInfoBlockingLogs.log("UNBLOCKED " + uid);
- }
+ String action = blocked ? "BLOCKED" : "UNBLOCKED";
+ log(String.format("Returning %s NetworkInfo to uid=%d", action, uid));
+ mNetworkInfoBlockingLogs.log(action + " " + uid);
}
/**
@@ -2028,16 +2022,6 @@
mLegacyTypeTracker.dump(pw);
- synchronized (this) {
- pw.print("mNetTransitionWakeLock: currently " +
- (mNetTransitionWakeLock.isHeld() ? "" : "not ") + "held");
- if (!TextUtils.isEmpty(mNetTransitionWakeLockCausedBy)) {
- pw.println(", last requested for " + mNetTransitionWakeLockCausedBy);
- } else {
- pw.println(", last requested never");
- }
- }
-
pw.println();
mTethering.dump(fd, pw, args);
@@ -2047,17 +2031,6 @@
pw.println();
dumpAvoidBadWifiSettings(pw);
- pw.println();
- if (mInetLog != null && mInetLog.size() > 0) {
- pw.println();
- pw.println("Inet condition reports:");
- pw.increaseIndent();
- for(int i = 0; i < mInetLog.size(); i++) {
- pw.println(mInetLog.get(i));
- }
- pw.decreaseIndent();
- }
-
if (argsContain(args, "--short") == false) {
pw.println();
synchronized (mValidationLogs) {
@@ -2081,6 +2054,12 @@
pw.increaseIndent();
mNetworkInfoBlockingLogs.reverseDump(fd, pw, args);
pw.decreaseIndent();
+
+ pw.println();
+ pw.println("NetTransition WakeLock activity (most recent first):");
+ pw.increaseIndent();
+ mWakelockLogs.reverseDump(fd, pw, args);
+ pw.decreaseIndent();
}
}
@@ -2089,8 +2068,7 @@
final NetworkAgentInfo officialNai = getNetworkAgentInfoForNetwork(nai.network);
if (officialNai != null && officialNai.equals(nai)) return true;
if (officialNai != null || VDBG) {
- final String msg = sMagicDecoderRing.get(what, Integer.toString(what));
- loge(msg + " - isLiveNetworkAgent found mismatched netId: " + officialNai +
+ loge(eventName(what) + " - isLiveNetworkAgent found mismatched netId: " + officialNai +
" - " + nai);
}
return false;
@@ -2127,8 +2105,7 @@
NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
if (nai == null) {
if (VDBG) {
- final String what = sMagicDecoderRing.get(msg.what, Integer.toString(msg.what));
- log(String.format("%s from unknown NetworkAgent", what));
+ log(String.format("%s from unknown NetworkAgent", eventName(msg.what)));
}
return;
}
@@ -2865,25 +2842,7 @@
switch (msg.what) {
case EVENT_EXPIRE_NET_TRANSITION_WAKELOCK:
case EVENT_CLEAR_NET_TRANSITION_WAKELOCK: {
- String causedBy = null;
- synchronized (ConnectivityService.this) {
- if (msg.arg1 == mNetTransitionWakeLockSerialNumber &&
- mNetTransitionWakeLock.isHeld()) {
- mNetTransitionWakeLock.release();
- causedBy = mNetTransitionWakeLockCausedBy;
- } else {
- break;
- }
- }
- if (VDBG) {
- if (msg.what == EVENT_EXPIRE_NET_TRANSITION_WAKELOCK) {
- log("Failed to find a new network - expiring NetTransition Wakelock");
- } else {
- log("NetTransition Wakelock (" +
- (causedBy == null ? "unknown" : causedBy) +
- " cleared because we found a replacement network");
- }
- }
+ handleNetworkTransitionWakelockRelease(msg.what, msg.arg1);
break;
}
case EVENT_APPLY_GLOBAL_HTTP_PROXY: {
@@ -3112,7 +3071,7 @@
if (mNetTransitionWakeLock.isHeld()) return;
serialNum = ++mNetTransitionWakeLockSerialNumber;
mNetTransitionWakeLock.acquire();
- mNetTransitionWakeLockCausedBy = forWhom;
+ mWakelockLogs.log(String.format("ACQUIRE %d for %s", serialNum, forWhom));
}
mHandler.sendMessageDelayed(mHandler.obtainMessage(
EVENT_EXPIRE_NET_TRANSITION_WAKELOCK, serialNum, 0),
@@ -3120,6 +3079,32 @@
return;
}
+ private void handleNetworkTransitionWakelockRelease(int eventId, int wantSerialNumber) {
+ final int serialNumber;
+ final boolean isHeld;
+ final boolean release;
+ synchronized (this) {
+ serialNumber = mNetTransitionWakeLockSerialNumber;
+ isHeld = mNetTransitionWakeLock.isHeld();
+ release = (wantSerialNumber == serialNumber) && isHeld;
+ if (release) {
+ mNetTransitionWakeLock.release();
+ }
+ }
+ final String result;
+ if (release) {
+ result = "released";
+ } else if (!isHeld) {
+ result = "already released";
+ } else {
+ result = String.format("not released (serial number was %d)", serialNumber);
+ }
+ String msg = String.format(
+ "RELEASE %d by %s: %s", wantSerialNumber, eventName(eventId), result);
+ mWakelockLogs.log(msg);
+ if (DBG) log(msg);
+ }
+
// 100 percent is full good, 0 is full bad.
@Override
public void reportInetCondition(int networkType, int percentage) {