am 1ed1de7a: Merge "Modify logging to debug this issue" into jb-dev

* commit '1ed1de7ab2ae03f82500dbf6272bf036d89bd0c9':
  Modify logging to debug this issue

3 files changed, 114 insertions, 92 deletions

diff --git a/services/java/com/android/server/ConnectivityService.java b/services/java/com/android/server/ConnectivityService.java
index e396a69..7bbc8b5 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;
-        }
-
-        FeatureUser f = new FeatureUser(networkType, feature, binder);
-
-        // TODO - move this into individual networktrackers
-        int usedNetworkType = convertFeatureToNetworkType(networkType, feature);
+        try {
+            if (!ConnectivityManager.isNetworkTypeValid(networkType) ||
+                    mNetConfigs[networkType] == null) {
+                return Phone.APN_REQUEST_FAILED;
+            }
 
-        if (mProtectedNetworks.contains(usedNetworkType)) {
-            enforceConnectivityInternalPermission();
-        }
+            FeatureUser f = new FeatureUser(networkType, feature, binder);
 
-        // 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;
-        }
+            // TODO - move this into individual networktrackers
+            int usedNetworkType = convertFeatureToNetworkType(networkType, feature);
 
-        NetworkStateTracker network = mNetTrackers[usedNetworkType];
-        if (network != null) {
-            Integer currentPid = new Integer(getCallingPid());
-            if (usedNetworkType != networkType) {
-                NetworkInfo ni = network.getNetworkInfo();
+            if (mProtectedNetworks.contains(usedNetworkType)) {
+                enforceConnectivityInternalPermission();
+            }
 
-                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 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();
+
+                    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;
+                    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 (addToList) mFeatureUsers.add(f);
-                    if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) {
-                        // this gets used for per-pid dns when connected
-                        mNetRequestersPids[usedNetworkType].add(currentPid);
+                        if (addToList) mFeatureUsers.add(f);
+                        if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) {
+                            // this gets used for per-pid dns when connected
+                            mNetRequestersPids[usedNetworkType].add(currentPid);
+                        }
                     }
-                }
 
-                if (restoreTimer >= 0) {
-                    mHandler.sendMessageDelayed(
-                            mHandler.obtainMessage(EVENT_RESTORE_DEFAULT_NETWORK, f), restoreTimer);
-                }
+                    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);
+                    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;
                         }
-                        return Phone.APN_ALREADY_ACTIVE;
+                        if (VDBG) log("special network already connecting");
+                        return Phone.APN_REQUEST_STARTED;
                     }
-                    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
+                    // 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);
+                    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);
+                        }
                     }
+                    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 a15d3bb..f71125a 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 e2852b5..11644e3 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.