From 4701121f3eaebed677cca52370cf05aa808e61b8 Mon Sep 17 00:00:00 2001 From: Hugo Benichi Date: Thu, 30 Mar 2017 10:46:05 +0900 Subject: [PATCH] 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 --- .../android/server/ConnectivityService.java | 119 ++++++++---------- 1 file changed, 52 insertions(+), 67 deletions(-) diff --git a/services/core/java/com/android/server/ConnectivityService.java b/services/core/java/com/android/server/ConnectivityService.java index 7466f54c2b..13a6cd6300 100644 --- a/services/core/java/com/android/server/ConnectivityService.java +++ b/services/core/java/com/android/server/ConnectivityService.java @@ -395,6 +395,10 @@ public class ConnectivityService extends IConnectivityManager.Stub */ 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 tracking network validation and results private static final int MAX_VALIDATION_LOGS = 10; private static class ValidationLog { @@ -815,10 +816,6 @@ public class ConnectivityService extends IConnectivityManager.Stub loge("Error registering observer :" + e); } - if (DBG) { - mInetLog = new ArrayList(); - } - mSettingsObserver = new SettingsObserver(mContext, mHandler); registerSettingsCallbacks(); @@ -1041,22 +1038,19 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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 @@ public class ConnectivityService extends IConnectivityManager.Stub 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) {