From 5a0c320a820a0ccaafaa87ad858a29bf5d88a8b9 Mon Sep 17 00:00:00 2001 From: Robert Greenwalt Date: Tue, 22 May 2012 16:07:46 -0700 Subject: [PATCH] Modify logging to debug this issue Logging exec time on startUsingNetworkFeature as we've had some reports suggesting it's causing ANRs. Remove some logging from NDC so it's local log is more useful. bug:6492166 Change-Id: I258ff6c59bff2c65935242d50496d84720c5d493 --- .../android/server/ConnectivityService.java | 201 ++++++++++-------- .../android/server/NativeDaemonConnector.java | 9 +- .../server/NetworkManagementService.java | 2 +- 3 files changed, 117 insertions(+), 95 deletions(-) diff --git a/services/java/com/android/server/ConnectivityService.java b/services/java/com/android/server/ConnectivityService.java index e396a6970362a..7bbc8b5209ac8 100644 --- a/services/java/com/android/server/ConnectivityService.java +++ b/services/java/com/android/server/ConnectivityService.java @@ -66,6 +66,7 @@ import android.os.ParcelFileDescriptor; import android.os.PowerManager; import android.os.RemoteException; import android.os.ServiceManager; +import android.os.SystemClock; import android.os.SystemProperties; import android.provider.Settings; import android.text.TextUtils; @@ -995,120 +996,136 @@ private NetworkStateTracker makeWimaxStateTracker() { // javadoc from interface public int startUsingNetworkFeature(int networkType, String feature, IBinder binder) { + long startTime = 0; + if (DBG) { + startTime = SystemClock.elapsedRealtime(); + } if (VDBG) { log("startUsingNetworkFeature for net " + networkType + ": " + feature + ", uid=" + Binder.getCallingUid()); } enforceChangePermission(); - if (!ConnectivityManager.isNetworkTypeValid(networkType) || - mNetConfigs[networkType] == null) { - return Phone.APN_REQUEST_FAILED; - } + try { + if (!ConnectivityManager.isNetworkTypeValid(networkType) || + mNetConfigs[networkType] == null) { + return Phone.APN_REQUEST_FAILED; + } - FeatureUser f = new FeatureUser(networkType, feature, binder); + FeatureUser f = new FeatureUser(networkType, feature, binder); - // TODO - move this into individual networktrackers - int usedNetworkType = convertFeatureToNetworkType(networkType, feature); + // TODO - move this into individual networktrackers + int usedNetworkType = convertFeatureToNetworkType(networkType, feature); - if (mProtectedNetworks.contains(usedNetworkType)) { - enforceConnectivityInternalPermission(); - } + if (mProtectedNetworks.contains(usedNetworkType)) { + enforceConnectivityInternalPermission(); + } - // if UID is restricted, don't allow them to bring up metered APNs - final boolean networkMetered = isNetworkMeteredUnchecked(usedNetworkType); - final int uidRules; - synchronized (mRulesLock) { - uidRules = mUidRules.get(Binder.getCallingUid(), RULE_ALLOW_ALL); - } - if (networkMetered && (uidRules & RULE_REJECT_METERED) != 0) { - return Phone.APN_REQUEST_FAILED; - } + // if UID is restricted, don't allow them to bring up metered APNs + final boolean networkMetered = isNetworkMeteredUnchecked(usedNetworkType); + final int uidRules; + synchronized (mRulesLock) { + uidRules = mUidRules.get(Binder.getCallingUid(), RULE_ALLOW_ALL); + } + if (networkMetered && (uidRules & RULE_REJECT_METERED) != 0) { + return Phone.APN_REQUEST_FAILED; + } - NetworkStateTracker network = mNetTrackers[usedNetworkType]; - if (network != null) { - Integer currentPid = new Integer(getCallingPid()); - if (usedNetworkType != networkType) { - NetworkInfo ni = network.getNetworkInfo(); + NetworkStateTracker network = mNetTrackers[usedNetworkType]; + if (network != null) { + Integer currentPid = new Integer(getCallingPid()); + if (usedNetworkType != networkType) { + NetworkInfo ni = network.getNetworkInfo(); - if (ni.isAvailable() == false) { - if (!TextUtils.equals(feature,Phone.FEATURE_ENABLE_DUN_ALWAYS)) { - if (DBG) log("special network not available ni=" + ni.getTypeName()); - return Phone.APN_TYPE_NOT_AVAILABLE; - } else { - // else make the attempt anyway - probably giving REQUEST_STARTED below - if (DBG) { - log("special network not available, but try anyway ni=" + - ni.getTypeName()); - } - } - } - - int restoreTimer = getRestoreDefaultNetworkDelay(usedNetworkType); - - synchronized(this) { - boolean addToList = true; - if (restoreTimer < 0) { - // In case there is no timer is specified for the feature, - // make sure we don't add duplicate entry with the same request. - for (FeatureUser u : mFeatureUsers) { - if (u.isSameUser(f)) { - // Duplicate user is found. Do not add. - addToList = false; - break; + if (ni.isAvailable() == false) { + if (!TextUtils.equals(feature,Phone.FEATURE_ENABLE_DUN_ALWAYS)) { + if (DBG) log("special network not available ni=" + ni.getTypeName()); + return Phone.APN_TYPE_NOT_AVAILABLE; + } else { + // else make the attempt anyway - probably giving REQUEST_STARTED below + if (DBG) { + log("special network not available, but try anyway ni=" + + ni.getTypeName()); } } } - if (addToList) mFeatureUsers.add(f); - if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) { - // this gets used for per-pid dns when connected - mNetRequestersPids[usedNetworkType].add(currentPid); - } - } + int restoreTimer = getRestoreDefaultNetworkDelay(usedNetworkType); - if (restoreTimer >= 0) { - mHandler.sendMessageDelayed( - mHandler.obtainMessage(EVENT_RESTORE_DEFAULT_NETWORK, f), restoreTimer); - } - - if ((ni.isConnectedOrConnecting() == true) && - !network.isTeardownRequested()) { - if (ni.isConnected() == true) { - final long token = Binder.clearCallingIdentity(); - try { - // add the pid-specific dns - handleDnsConfigurationChange(usedNetworkType); - if (VDBG) log("special network already active"); - } finally { - Binder.restoreCallingIdentity(token); + synchronized(this) { + boolean addToList = true; + if (restoreTimer < 0) { + // In case there is no timer is specified for the feature, + // make sure we don't add duplicate entry with the same request. + for (FeatureUser u : mFeatureUsers) { + if (u.isSameUser(f)) { + // Duplicate user is found. Do not add. + addToList = false; + break; + } + } + } + + if (addToList) mFeatureUsers.add(f); + if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) { + // this gets used for per-pid dns when connected + mNetRequestersPids[usedNetworkType].add(currentPid); } - return Phone.APN_ALREADY_ACTIVE; } - if (VDBG) log("special network already connecting"); + + if (restoreTimer >= 0) { + mHandler.sendMessageDelayed(mHandler.obtainMessage( + EVENT_RESTORE_DEFAULT_NETWORK, f), restoreTimer); + } + + if ((ni.isConnectedOrConnecting() == true) && + !network.isTeardownRequested()) { + if (ni.isConnected() == true) { + final long token = Binder.clearCallingIdentity(); + try { + // add the pid-specific dns + handleDnsConfigurationChange(usedNetworkType); + if (VDBG) log("special network already active"); + } finally { + Binder.restoreCallingIdentity(token); + } + return Phone.APN_ALREADY_ACTIVE; + } + if (VDBG) log("special network already connecting"); + return Phone.APN_REQUEST_STARTED; + } + + // check if the radio in play can make another contact + // assume if cannot for now + + if (DBG) { + log("startUsingNetworkFeature reconnecting to " + networkType + ": " + + feature); + } + network.reconnect(); return Phone.APN_REQUEST_STARTED; - } - - // check if the radio in play can make another contact - // assume if cannot for now - - if (DBG) { - log("startUsingNetworkFeature reconnecting to " + networkType + ": " + feature); - } - network.reconnect(); - return Phone.APN_REQUEST_STARTED; - } else { - // need to remember this unsupported request so we respond appropriately on stop - synchronized(this) { - mFeatureUsers.add(f); - if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) { - // this gets used for per-pid dns when connected - mNetRequestersPids[usedNetworkType].add(currentPid); + } else { + // need to remember this unsupported request so we respond appropriately on stop + synchronized(this) { + mFeatureUsers.add(f); + if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) { + // this gets used for per-pid dns when connected + mNetRequestersPids[usedNetworkType].add(currentPid); + } } + return -1; } - return -1; } - } - return Phone.APN_TYPE_NOT_AVAILABLE; + return Phone.APN_TYPE_NOT_AVAILABLE; + } finally { + if (DBG) { + final long execTime = SystemClock.elapsedRealtime() - startTime; + if (execTime > 250) { + loge("startUsingNetworkFeature took too long: " + execTime + "ms"); + } else { + if (VDBG) log("startUsingNetworkFeature took " + execTime + "ms"); + } + } + } } // javadoc from interface diff --git a/services/java/com/android/server/NativeDaemonConnector.java b/services/java/com/android/server/NativeDaemonConnector.java index a15d3bbb4cf2a..f71125a839a4d 100644 --- a/services/java/com/android/server/NativeDaemonConnector.java +++ b/services/java/com/android/server/NativeDaemonConnector.java @@ -58,6 +58,7 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo private AtomicInteger mSequenceNumber; private static final int DEFAULT_TIMEOUT = 1 * 60 * 1000; /* 1 minute */ + private static final long WARN_EXECUTE_DELAY_MS = 500; /* .5 sec */ /** Lock held whenever communicating with native daemon. */ private final Object mDaemonLock = new Object(); @@ -148,7 +149,6 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo mCallbackHandler.sendMessage(mCallbackHandler.obtainMessage( event.getCode(), event.getRawEvent())); } else { - log("POST<- {" + rawEvent + "}"); mResponseQueue.add(event.getCmdNumber(), event); } } catch (IllegalArgumentException e) { @@ -300,6 +300,7 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo final int sequenceNumber = mSequenceNumber.incrementAndGet(); final StringBuilder cmdBuilder = new StringBuilder(Integer.toString(sequenceNumber)).append(' '); + final long startTime = SystemClock.elapsedRealtime(); makeCommand(cmdBuilder, cmd, args); @@ -332,6 +333,11 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo events.add(event); } while (event.isClassContinue()); + final long endTime = SystemClock.elapsedRealtime(); + if (endTime - startTime > WARN_EXECUTE_DELAY_MS) { + loge("NDC Command {" + logCmd + "} took too long (" + (endTime - startTime) + "ms)"); + } + if (event.isClassClientError()) { throw new NativeDaemonArgumentException(logCmd, event); } @@ -339,7 +345,6 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo throw new NativeDaemonFailureException(logCmd, event); } - log("RTN <- {" + logCmd + "}"); return events.toArray(new NativeDaemonEvent[events.size()]); } diff --git a/services/java/com/android/server/NetworkManagementService.java b/services/java/com/android/server/NetworkManagementService.java index e2852b5078732..11644e3b93e26 100644 --- a/services/java/com/android/server/NetworkManagementService.java +++ b/services/java/com/android/server/NetworkManagementService.java @@ -166,7 +166,7 @@ public class NetworkManagementService extends INetworkManagementService.Stub } mConnector = new NativeDaemonConnector( - new NetdCallbackReceiver(), "netd", 10, NETD_TAG, 80); + new NetdCallbackReceiver(), "netd", 10, NETD_TAG, 160); mThread = new Thread(mConnector, NETD_TAG); // Add ourself to the Watchdog monitors.