Skip to content

Commit 5a0c320

Browse files
author
Robert Greenwalt
committed
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
1 parent 956f28e commit 5a0c320

File tree

3 files changed

+114
-92
lines changed

3 files changed

+114
-92
lines changed

‎services/java/com/android/server/ConnectivityService.java‎

Lines changed: 106 additions & 89 deletions
Original file line numberDiff line numberDiff line change
@@ -66,6 +66,7 @@
6666
import android.os.PowerManager;
6767
import android.os.RemoteException;
6868
import android.os.ServiceManager;
69+
import android.os.SystemClock;
6970
import android.os.SystemProperties;
7071
import android.provider.Settings;
7172
import android.text.TextUtils;
@@ -995,120 +996,136 @@ public String toString() {
995996
// javadoc from interface
996997
public int startUsingNetworkFeature(int networkType, String feature,
997998
IBinder binder) {
999+
long startTime = 0;
1000+
if (DBG) {
1001+
startTime = SystemClock.elapsedRealtime();
1002+
}
9981003
if (VDBG) {
9991004
log("startUsingNetworkFeature for net " + networkType + ": " + feature + ", uid="
10001005
+ Binder.getCallingUid());
10011006
}
10021007
enforceChangePermission();
1003-
if (!ConnectivityManager.isNetworkTypeValid(networkType) ||
1004-
mNetConfigs[networkType] == null) {
1005-
return Phone.APN_REQUEST_FAILED;
1006-
}
1007-
1008-
FeatureUser f = new FeatureUser(networkType, feature, binder);
1009-
1010-
// TODO - move this into individual networktrackers
1011-
int usedNetworkType = convertFeatureToNetworkType(networkType, feature);
1008+
try {
1009+
if (!ConnectivityManager.isNetworkTypeValid(networkType) ||
1010+
mNetConfigs[networkType] == null) {
1011+
return Phone.APN_REQUEST_FAILED;
1012+
}
10121013

1013-
if (mProtectedNetworks.contains(usedNetworkType)) {
1014-
enforceConnectivityInternalPermission();
1015-
}
1014+
FeatureUser f = new FeatureUser(networkType, feature, binder);
10161015

1017-
// if UID is restricted, don't allow them to bring up metered APNs
1018-
final boolean networkMetered = isNetworkMeteredUnchecked(usedNetworkType);
1019-
final int uidRules;
1020-
synchronized (mRulesLock) {
1021-
uidRules = mUidRules.get(Binder.getCallingUid(), RULE_ALLOW_ALL);
1022-
}
1023-
if (networkMetered && (uidRules & RULE_REJECT_METERED) != 0) {
1024-
return Phone.APN_REQUEST_FAILED;
1025-
}
1016+
// TODO - move this into individual networktrackers
1017+
int usedNetworkType = convertFeatureToNetworkType(networkType, feature);
10261018

1027-
NetworkStateTracker network = mNetTrackers[usedNetworkType];
1028-
if (network != null) {
1029-
Integer currentPid = new Integer(getCallingPid());
1030-
if (usedNetworkType != networkType) {
1031-
NetworkInfo ni = network.getNetworkInfo();
1019+
if (mProtectedNetworks.contains(usedNetworkType)) {
1020+
enforceConnectivityInternalPermission();
1021+
}
10321022

1033-
if (ni.isAvailable() == false) {
1034-
if (!TextUtils.equals(feature,Phone.FEATURE_ENABLE_DUN_ALWAYS)) {
1035-
if (DBG) log("special network not available ni=" + ni.getTypeName());
1036-
return Phone.APN_TYPE_NOT_AVAILABLE;
1037-
} else {
1038-
// else make the attempt anyway - probably giving REQUEST_STARTED below
1039-
if (DBG) {
1040-
log("special network not available, but try anyway ni=" +
1041-
ni.getTypeName());
1023+
// if UID is restricted, don't allow them to bring up metered APNs
1024+
final boolean networkMetered = isNetworkMeteredUnchecked(usedNetworkType);
1025+
final int uidRules;
1026+
synchronized (mRulesLock) {
1027+
uidRules = mUidRules.get(Binder.getCallingUid(), RULE_ALLOW_ALL);
1028+
}
1029+
if (networkMetered && (uidRules & RULE_REJECT_METERED) != 0) {
1030+
return Phone.APN_REQUEST_FAILED;
1031+
}
1032+
1033+
NetworkStateTracker network = mNetTrackers[usedNetworkType];
1034+
if (network != null) {
1035+
Integer currentPid = new Integer(getCallingPid());
1036+
if (usedNetworkType != networkType) {
1037+
NetworkInfo ni = network.getNetworkInfo();
1038+
1039+
if (ni.isAvailable() == false) {
1040+
if (!TextUtils.equals(feature,Phone.FEATURE_ENABLE_DUN_ALWAYS)) {
1041+
if (DBG) log("special network not available ni=" + ni.getTypeName());
1042+
return Phone.APN_TYPE_NOT_AVAILABLE;
1043+
} else {
1044+
// else make the attempt anyway - probably giving REQUEST_STARTED below
1045+
if (DBG) {
1046+
log("special network not available, but try anyway ni=" +
1047+
ni.getTypeName());
1048+
}
10421049
}
10431050
}
1044-
}
10451051

1046-
int restoreTimer = getRestoreDefaultNetworkDelay(usedNetworkType);
1047-
1048-
synchronized(this) {
1049-
boolean addToList = true;
1050-
if (restoreTimer < 0) {
1051-
// In case there is no timer is specified for the feature,
1052-
// make sure we don't add duplicate entry with the same request.
1053-
for (FeatureUser u : mFeatureUsers) {
1054-
if (u.isSameUser(f)) {
1055-
// Duplicate user is found. Do not add.
1056-
addToList = false;
1057-
break;
1052+
int restoreTimer = getRestoreDefaultNetworkDelay(usedNetworkType);
1053+
1054+
synchronized(this) {
1055+
boolean addToList = true;
1056+
if (restoreTimer < 0) {
1057+
// In case there is no timer is specified for the feature,
1058+
// make sure we don't add duplicate entry with the same request.
1059+
for (FeatureUser u : mFeatureUsers) {
1060+
if (u.isSameUser(f)) {
1061+
// Duplicate user is found. Do not add.
1062+
addToList = false;
1063+
break;
1064+
}
10581065
}
10591066
}
1060-
}
10611067

1062-
if (addToList) mFeatureUsers.add(f);
1063-
if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) {
1064-
// this gets used for per-pid dns when connected
1065-
mNetRequestersPids[usedNetworkType].add(currentPid);
1068+
if (addToList) mFeatureUsers.add(f);
1069+
if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) {
1070+
// this gets used for per-pid dns when connected
1071+
mNetRequestersPids[usedNetworkType].add(currentPid);
1072+
}
10661073
}
1067-
}
10681074

1069-
if (restoreTimer >= 0) {
1070-
mHandler.sendMessageDelayed(
1071-
mHandler.obtainMessage(EVENT_RESTORE_DEFAULT_NETWORK, f), restoreTimer);
1072-
}
1075+
if (restoreTimer >= 0) {
1076+
mHandler.sendMessageDelayed(mHandler.obtainMessage(
1077+
EVENT_RESTORE_DEFAULT_NETWORK, f), restoreTimer);
1078+
}
10731079

1074-
if ((ni.isConnectedOrConnecting() == true) &&
1075-
!network.isTeardownRequested()) {
1076-
if (ni.isConnected() == true) {
1077-
final long token = Binder.clearCallingIdentity();
1078-
try {
1079-
// add the pid-specific dns
1080-
handleDnsConfigurationChange(usedNetworkType);
1081-
if (VDBG) log("special network already active");
1082-
} finally {
1083-
Binder.restoreCallingIdentity(token);
1080+
if ((ni.isConnectedOrConnecting() == true) &&
1081+
!network.isTeardownRequested()) {
1082+
if (ni.isConnected() == true) {
1083+
final long token = Binder.clearCallingIdentity();
1084+
try {
1085+
// add the pid-specific dns
1086+
handleDnsConfigurationChange(usedNetworkType);
1087+
if (VDBG) log("special network already active");
1088+
} finally {
1089+
Binder.restoreCallingIdentity(token);
1090+
}
1091+
return Phone.APN_ALREADY_ACTIVE;
10841092
}
1085-
return Phone.APN_ALREADY_ACTIVE;
1093+
if (VDBG) log("special network already connecting");
1094+
return Phone.APN_REQUEST_STARTED;
10861095
}
1087-
if (VDBG) log("special network already connecting");
1088-
return Phone.APN_REQUEST_STARTED;
1089-
}
10901096

1091-
// check if the radio in play can make another contact
1092-
// assume if cannot for now
1097+
// check if the radio in play can make another contact
1098+
// assume if cannot for now
10931099

1094-
if (DBG) {
1095-
log("startUsingNetworkFeature reconnecting to " + networkType + ": " + feature);
1096-
}
1097-
network.reconnect();
1098-
return Phone.APN_REQUEST_STARTED;
1099-
} else {
1100-
// need to remember this unsupported request so we respond appropriately on stop
1101-
synchronized(this) {
1102-
mFeatureUsers.add(f);
1103-
if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) {
1104-
// this gets used for per-pid dns when connected
1105-
mNetRequestersPids[usedNetworkType].add(currentPid);
1100+
if (DBG) {
1101+
log("startUsingNetworkFeature reconnecting to " + networkType + ": " +
1102+
feature);
1103+
}
1104+
network.reconnect();
1105+
return Phone.APN_REQUEST_STARTED;
1106+
} else {
1107+
// need to remember this unsupported request so we respond appropriately on stop
1108+
synchronized(this) {
1109+
mFeatureUsers.add(f);
1110+
if (!mNetRequestersPids[usedNetworkType].contains(currentPid)) {
1111+
// this gets used for per-pid dns when connected
1112+
mNetRequestersPids[usedNetworkType].add(currentPid);
1113+
}
11061114
}
1115+
return -1;
11071116
}
1108-
return -1;
11091117
}
1110-
}
1111-
return Phone.APN_TYPE_NOT_AVAILABLE;
1118+
return Phone.APN_TYPE_NOT_AVAILABLE;
1119+
} finally {
1120+
if (DBG) {
1121+
final long execTime = SystemClock.elapsedRealtime() - startTime;
1122+
if (execTime > 250) {
1123+
loge("startUsingNetworkFeature took too long: " + execTime + "ms");
1124+
} else {
1125+
if (VDBG) log("startUsingNetworkFeature took " + execTime + "ms");
1126+
}
1127+
}
1128+
}
11121129
}
11131130

11141131
// javadoc from interface

‎services/java/com/android/server/NativeDaemonConnector.java‎

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -58,6 +58,7 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo
5858
private AtomicInteger mSequenceNumber;
5959

6060
private static final int DEFAULT_TIMEOUT = 1 * 60 * 1000; /* 1 minute */
61+
private static final long WARN_EXECUTE_DELAY_MS = 500; /* .5 sec */
6162

6263
/** Lock held whenever communicating with native daemon. */
6364
private final Object mDaemonLock = new Object();
@@ -148,7 +149,6 @@ private void listenToSocket() throws IOException {
148149
mCallbackHandler.sendMessage(mCallbackHandler.obtainMessage(
149150
event.getCode(), event.getRawEvent()));
150151
} else {
151-
log("POST<- {" + rawEvent + "}");
152152
mResponseQueue.add(event.getCmdNumber(), event);
153153
}
154154
} catch (IllegalArgumentException e) {
@@ -300,6 +300,7 @@ public NativeDaemonEvent[] execute(int timeout, String cmd, Object... args)
300300
final int sequenceNumber = mSequenceNumber.incrementAndGet();
301301
final StringBuilder cmdBuilder =
302302
new StringBuilder(Integer.toString(sequenceNumber)).append(' ');
303+
final long startTime = SystemClock.elapsedRealtime();
303304

304305
makeCommand(cmdBuilder, cmd, args);
305306

@@ -332,14 +333,18 @@ public NativeDaemonEvent[] execute(int timeout, String cmd, Object... args)
332333
events.add(event);
333334
} while (event.isClassContinue());
334335

336+
final long endTime = SystemClock.elapsedRealtime();
337+
if (endTime - startTime > WARN_EXECUTE_DELAY_MS) {
338+
loge("NDC Command {" + logCmd + "} took too long (" + (endTime - startTime) + "ms)");
339+
}
340+
335341
if (event.isClassClientError()) {
336342
throw new NativeDaemonArgumentException(logCmd, event);
337343
}
338344
if (event.isClassServerError()) {
339345
throw new NativeDaemonFailureException(logCmd, event);
340346
}
341347

342-
log("RTN <- {" + logCmd + "}");
343348
return events.toArray(new NativeDaemonEvent[events.size()]);
344349
}
345350

‎services/java/com/android/server/NetworkManagementService.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -166,7 +166,7 @@ private NetworkManagementService(Context context) {
166166
}
167167

168168
mConnector = new NativeDaemonConnector(
169-
new NetdCallbackReceiver(), "netd", 10, NETD_TAG, 80);
169+
new NetdCallbackReceiver(), "netd", 10, NETD_TAG, 160);
170170
mThread = new Thread(mConnector, NETD_TAG);
171171

172172
// Add ourself to the Watchdog monitors.

0 commit comments

Comments
 (0)