平台
?????????RK3566 + Android 11
问题
?????????在测试过程中, 发现第三方应用的开机自启时间加长了, 在显示Launcher后, 还需要等待超过1分钟的时间. 后续在查LOG中发现以以下异常LOG(Timeout of broadcast BroadcastRecord):
//第一个收到
09-13 17:45:03.406 D/WifiSleepController( 432): onReceive, action=android.intent.action.BOOT_COMPLETED
//异常LOG位置
09-13 17:46:07.077 W/BroadcastQueue( 432): Timeout of broadcast BroadcastRecord{35f0038 u0 android.intent.action.BOOT_COMPLETED} - receiver=android.os.BinderProxy@e7eb8bf, started 60000ms ago
09-13 17:46:07.077 W/BroadcastQueue( 432): Receiver during timeout of BroadcastRecord{35f0038 u0 android.intent.action.BOOT_COMPLETED} : ResolveInfo{af90b8c com.android.phone/.vvm.VvmSimStateTracker m=0x108000}
started 60000ms ago 表明是开始于1分钟前的广播处理超时, 这时候广播会继续下发, 这时候第三方应用才开始接收到开机广播并执行相应的操作, 比如自启.
虽然不是关键的位置, 还是记录下源码中LOG输出位置
frameworks/base/services/core/java/com/android/server/am/BroadcastQueue.java
final void broadcastTimeoutLocked(boolean fromMsg) {
if (fromMsg) {
mPendingBroadcastTimeoutMessage = false;
}
if (mDispatcher.isEmpty() || mDispatcher.getActiveBroadcastLocked() == null) {
return;
}
long now = SystemClock.uptimeMillis();
BroadcastRecord r = mDispatcher.getActiveBroadcastLocked();
if (fromMsg) {
if (!mService.mProcessesReady) {
return;
}
if (r.timeoutExempt) {
if (DEBUG_BROADCAST) {
Slog.i(TAG_BROADCAST, "Broadcast timeout but it's exempt: "
+ r.intent.getAction());
}
return;
}
long timeoutTime = r.receiverTime + mConstants.TIMEOUT;
if (timeoutTime > now) {
if (DEBUG_BROADCAST) Slog.v(TAG_BROADCAST,
"Premature timeout ["
+ mQueueName + "] @ " + now + ": resetting BROADCAST_TIMEOUT_MSG for "
+ timeoutTime);
setBroadcastTimeoutLocked(timeoutTime);
return;
}
}
if (r.state == BroadcastRecord.WAITING_SERVICES) {
Slog.i(TAG, "Waited long enough for: " + (r.curComponent != null
? r.curComponent.flattenToShortString() : "(null)"));
r.curComponent = null;
r.state = BroadcastRecord.IDLE;
processNextBroadcast(false);
return;
}
final boolean debugging = (r.curApp != null && r.curApp.isDebugging());
Slog.w(TAG, "Timeout of broadcast " + r + " - receiver=" + r.receiver
+ ", started " + (now - r.receiverTime) + "ms ago");
}
跟踪
?????????首先, 这个问题从Log上可以看出, 在传递广播的过程中, 卡在了其它的某个进程里, 考虑的顺序如下:
- 是否在VvmSimStateTracker.onReceive中处理了比较耗时的操作
- 是否进程初始化执行了耗时操作, 进程中的PhoneApp
????????1.是否在VvmSimStateTracker.onReceive中处理了比较耗时的操作
注册广播: packages/services/Telephony/src/com/android/phone/AndroidManifest.xml
<receiver
android:name="com.android.phone.vvm.VvmSimStateTracker"
android:exported="false"
androidprv:systemUserOnly="true">
<intent-filter>
<action android:name="android.intent.action.BOOT_COMPLETED"/>
<action android:name="android.telephony.action.CARRIER_CONFIG_CHANGED"/>
<action android:name="android.intent.action.SIM_STATE_CHANGED"/>
</intent-filter>
</receiver>
广播处理:packages/services/Telephony/src/com/android/phone/vvm/VvmSimStateTracker.java
public void onReceive(Context context, Intent intent) {
final String action = intent.getAction();
if (action == null) {
VvmLog.w(TAG, "Null action for intent.");
return;
}
VvmLog.i(TAG, action);
switch (action) {
case Intent.ACTION_BOOT_COMPLETED:
onBootCompleted(context);
break;
}
private void onBootCompleted(Context context) {
for (PhoneAccountHandle phoneAccountHandle : sPreBootHandles) {
TelephonyManager telephonyManager = getTelephonyManager(context, phoneAccountHandle);
if (telephonyManager == null) {
continue;
}
if (telephonyManager.getServiceState().getState() == ServiceState.STATE_IN_SERVICE) {
sListeners.put(phoneAccountHandle, null);
sendConnected(context, phoneAccountHandle);
} else {
listenToAccount(context, phoneAccountHandle);
}
}
sPreBootHandles.clear();
}
? ? ???????? 2.是否进程初始化执行了耗时操作, 进程中的PhoneApp
Application声明: packages/services/Telephony/src/com/android/phone/AndroidManifest.xml
<application android:name="PhoneApp"
android:persistent="true"
android:label="@string/phoneAppLabel"
android:icon="@mipmap/ic_launcher_phone"
android:allowBackup="false"
android:supportsRtl="true"
android:usesCleartextTraffic="true"
android:defaultToDeviceProtectedStorage="true"
android:directBootAware="true">
Application: packages/services/Telephony/src/com/android/phone/PhoneApp.java
public class PhoneApp extends Application {
PhoneGlobals mPhoneGlobals;
public PhoneApp() {
}
@Override
public void onCreate() {
if (UserHandle.myUserId() == 0) {
mPhoneGlobals = new PhoneGlobals(this);
mPhoneGlobals.onCreate();
TelecomAccountRegistry.getInstance(this).setupOnBoot();
}
}
}
结论
通过在1和2的代码中插入LOG后, 最终确定, 问题是出在了Application的初始化上, 也就是说, Phone的进程卡在了onCreate这个函数上.
Phone进程为什么卡住?
关键部分代码:
packages/services/Telephony/src/com/android/phone/PhoneGlobals.java
public void onCreate() {
if (VDBG) Log.v(LOG_TAG, "onCreate()...");
ContentResolver resolver = getContentResolver();
sVoiceCapable = ((TelephonyManager) getSystemService(Context.TELEPHONY_SERVICE))
.isVoiceCapable();
if (mCM == null) {
AnomalyReporter.initialize(this);
XmlResourceParser parser = getResources().getXml(R.xml.telephony_injection);
TelephonyComponentFactory.getInstance().injectTheComponentFactory(parser);
PhoneFactory.makeDefaultPhones(this);
}
frameworks/opt/telephony/src/java/com/android/internal/telephony/PhoneFactory.java
public static void makeDefaultPhones(Context context) {
makeDefaultPhone(context);
}
@UnsupportedAppUsage
public static void makeDefaultPhone(Context context) {
synchronized (sLockProxyPhones) {
if (!sMadeDefaults) {
sContext = context;
TelephonyDevController.create();
TelephonyMetrics metrics = TelephonyMetrics.getInstance();
metrics.setContext(context);
int retryCount = 0;
for(;;) {
boolean hasException = false;
retryCount ++;
try {
new LocalServerSocket("com.android.internal.telephony");
} catch (java.io.IOException ex) {
hasException = true;
}
if ( !hasException ) {
break;
} else if (retryCount > SOCKET_OPEN_MAX_RETRY) {
throw new RuntimeException("PhoneFactory probably already running");
} else {
try {
Thread.sleep(SOCKET_OPEN_RETRY_MILLIS);
} catch (InterruptedException er) {
}
}
}
sMetricsCollector = new MetricsCollector(context);
sPhoneNotifier = new DefaultPhoneNotifier(context);
int cdmaSubscription = CdmaSubscriptionSourceManager.getDefault(context);
Rlog.i(LOG_TAG, "Cdma Subscription set to " + cdmaSubscription);
int numPhones = TelephonyManager.getDefault().getActiveModemCount();
int[] networkModes = new int[numPhones];
sPhones = new Phone[numPhones];
sCommandsInterfaces = new RIL[numPhones];
sTelephonyNetworkFactories = new TelephonyNetworkFactory[numPhones];
for (int i = 0; i < numPhones; i++) {
networkModes[i] = RILConstants.PREFERRED_NETWORK_MODE;
Rlog.i(LOG_TAG, "Network Mode set to " + Integer.toString(networkModes[i]));
sCommandsInterfaces[i] = new RIL(context, networkModes[i],
cdmaSubscription, i);
}
}
frameworks/opt/telephony/src/java/com/android/internal/telephony/RIL.java
@UnsupportedAppUsage
public RIL(Context context, int preferredNetworkType,
int cdmaSubscription, Integer instanceId) {
super(context);
if (RILJ_LOGD) {
riljLog("RIL: init preferredNetworkType=" + preferredNetworkType
+ " cdmaSubscription=" + cdmaSubscription + ")");
}
mContext = context;
mCdmaSubscription = cdmaSubscription;
mPreferredNetworkType = preferredNetworkType;
mPhoneType = RILConstants.NO_PHONE;
mPhoneId = instanceId == null ? 0 : instanceId;
if (isRadioBugDetectionEnabled()) {
mRadioBugDetector = new RadioBugDetector(context, mPhoneId);
}
TelephonyManager tm = (TelephonyManager) context.getSystemService(
Context.TELEPHONY_SERVICE);
mIsCellularSupported = tm.isVoiceCapable() || tm.isSmsCapable() || tm.isDataCapable();
mRadioResponse = new RadioResponse(this);
mRadioIndication = new RadioIndication(this);
mOemHookResponse = new OemHookResponse(this);
mOemHookIndication = new OemHookIndication(this);
mRilHandler = new RilHandler();
mRadioProxyDeathRecipient = new RadioProxyDeathRecipient();
PowerManager pm = (PowerManager)context.getSystemService(Context.POWER_SERVICE);
mWakeLock = pm.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK, RILJ_WAKELOCK_TAG);
mWakeLock.setReferenceCounted(false);
mAckWakeLock = pm.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK, RILJ_ACK_WAKELOCK_NAME);
mAckWakeLock.setReferenceCounted(false);
mWakeLockTimeout = TelephonyProperties.wake_lock_timeout()
.orElse(DEFAULT_WAKE_LOCK_TIMEOUT_MS);
mAckWakeLockTimeout = TelephonyProperties.wake_lock_timeout()
.orElse(DEFAULT_ACK_WAKE_LOCK_TIMEOUT_MS);
mWakeLockCount = 0;
mRILDefaultWorkSource = new WorkSource(context.getApplicationInfo().uid,
context.getPackageName());
mActiveWakelockWorkSource = new WorkSource();
TelephonyDevController tdc = TelephonyDevController.getInstance();
tdc.registerRIL(this);
getRadioProxy(null);
getOemHookProxy(null);
if (RILJ_LOGD) {
riljLog("Radio HAL version: " + mRadioVersion);
}
}
@VisibleForTesting
public synchronized IRadio getRadioProxy(Message result) {
if (!SubscriptionManager.isValidPhoneId(mPhoneId)) return null;
if (!mIsCellularSupported) {
if (RILJ_LOGV) riljLog("getRadioProxy: Not calling getService(): wifi-only");
if (result != null) {
AsyncResult.forMessage(result, null,
CommandException.fromRilErrno(RADIO_NOT_AVAILABLE));
result.sendToTarget();
}
return null;
}
if (mRadioProxy != null) {
return mRadioProxy;
}
try {
if (mDisabledRadioServices.contains(mPhoneId)) {
riljLoge("getRadioProxy: mRadioProxy for " + HIDL_SERVICE_NAME[mPhoneId]
+ " is disabled");
} else {
try {
mRadioProxy = android.hardware.radio.V1_5.IRadio.getService(
HIDL_SERVICE_NAME[mPhoneId], true);
mRadioVersion = RADIO_HAL_VERSION_1_5;
} catch (NoSuchElementException e) {
}
if (mRadioProxy == null) {
try {
mRadioProxy = android.hardware.radio.V1_4.IRadio.getService(
HIDL_SERVICE_NAME[mPhoneId], true);
mRadioVersion = RADIO_HAL_VERSION_1_4;
} catch (NoSuchElementException e) {
}
}
if (mRadioProxy == null) {
try {
mRadioProxy = android.hardware.radio.V1_3.IRadio.getService(
HIDL_SERVICE_NAME[mPhoneId], true);
mRadioVersion = RADIO_HAL_VERSION_1_3;
} catch (NoSuchElementException e) {
}
}
if (mRadioProxy == null) {
try {
mRadioProxy = android.hardware.radio.V1_2.IRadio.getService(
HIDL_SERVICE_NAME[mPhoneId], true);
mRadioVersion = RADIO_HAL_VERSION_1_2;
} catch (NoSuchElementException e) {
}
}
if (mRadioProxy == null) {
try {
mRadioProxy = android.hardware.radio.V1_1.IRadio.getService(
HIDL_SERVICE_NAME[mPhoneId], true);
mRadioVersion = RADIO_HAL_VERSION_1_1;
} catch (NoSuchElementException e) {
}
}
if (mRadioProxy == null) {
try {
mRadioProxy = android.hardware.radio.V1_0.IRadio.getService(
HIDL_SERVICE_NAME[mPhoneId], true);
mRadioVersion = RADIO_HAL_VERSION_1_0;
} catch (NoSuchElementException e) {
}
}
if (mRadioProxy != null) {
mRadioProxy.linkToDeath(mRadioProxyDeathRecipient,
mRadioProxyCookie.incrementAndGet());
mRadioProxy.setResponseFunctions(mRadioResponse, mRadioIndication);
} else {
mDisabledRadioServices.add(mPhoneId);
riljLoge("getRadioProxy: mRadioProxy for "
+ HIDL_SERVICE_NAME[mPhoneId] + " is disabled");
}
}
} catch (RemoteException e) {
mRadioProxy = null;
riljLoge("RadioProxy getService/setResponseFunctions: " + e);
}
if (mRadioProxy == null) {
riljLoge("getRadioProxy: mRadioProxy == null");
if (result != null) {
AsyncResult.forMessage(result, null,
CommandException.fromRilErrno(RADIO_NOT_AVAILABLE));
result.sendToTarget();
}
}
return mRadioProxy;
}
frameworks/opt/telephony/src/java/com/android/internal/telephony/TelephonyDevController.java
public static void registerRIL(CommandsInterface cmdsIf) {
cmdsIf.getHardwareConfig(sRilHardwareConfig);
if (sRilHardwareConfig != null) {
AsyncResult ar = (AsyncResult) sRilHardwareConfig.obj;
if (ar.exception == null) {
handleGetHardwareConfigChanged(ar);
}
}
cmdsIf.registerForHardwareConfigChanged(sTelephonyDevController, EVENT_HARDWARE_CONFIG_CHANGED, null);
}
public static void unregisterRIL(CommandsInterface cmdsIf) {
cmdsIf.unregisterForHardwareConfigChanged(sTelephonyDevController);
}
跟踪代码找到最终卡住的地方是在创建RIL的时候
PhoneApp
PhoneGlobals
PhoneFactory
RIL
TelephonyDevController
onCreate
makeDefaultPhones
new RIL
registerRIL
getHardwareConfig
getRadioProxy
PhoneApp
PhoneGlobals
PhoneFactory
RIL
TelephonyDevController
同时, 从Log中可以看出一些与RIL相关的LOG.
01:48:48.154 1880-1880 chatty com.android.phone I uid=1001(radio) com.android.phone expire 4 lines
01:48:48.160 331-339 RIL RILU pid-331 E cannot find ttyname for AT Port
01:48:48.161 331-339 RIL RILC D USB can't find at device
01:48:51.161 331-339 RIL RILU D find_pci_device is 0
01:48:51.170 331-339 RIL RILU E cannot find ttyname for AT Port
01:48:51.171 331-339 RIL RILC D USB can't find at device
01:48:52.168 1880-1880 HidlS...ment com.android.phone W Waited one second for android.hardware.radio@1.1::IRadio/slot1
01:48:53.172 1880-1880 HidlS...ment W Waited one second for android.hardware.radio@1.1::IRadio/slot1
01:48:54.172 331-339 RIL RILU pid-331 D find_pci_device is 0
显然, 这个找不到4G, 所以自然而然地RIL初始化失败了 如果接上4G模块, 则不会出现这个问题
在长时间等待初始化后, 伴随而来的还有来自于com.android.phone的ANR报错.
2022-09-16 07:18:14.975 426-1802/system_process E/ActivityManager: ANR in com.android.phone
PID: 873
Reason: Broadcast of Intent { act=android.intent.action.BOOT_COMPLETED flg=0x89000010 cmp=com.android.phone/.vvm.VvmSimStateTracker (has extras) }
Load: 0.0 / 0.0 / 0.0
----- Output from /proc/pressure/memory -----
some avg10=0.00 avg60=0.00 avg300=0.00 total=0
full avg10=0.00 avg60=0.00 avg300=0.00 total=0
----- End output from /proc/pressure/memory -----
CPU usage from 64519ms to 0ms ago (2022-09-16 07:17:10.274 to 2022-09-16 07:18:14.793):
10% 426/system_server: 7.9% user + 2.6% kernel / faults: 15491 minor 133 major
3.5% 579/com.android.systemui: 2.9% user + 0.5% kernel / faults: 8380 minor 1 major
1.6% 174/surfaceflinger: 1% user + 0.6% kernel / faults: 550 minor
1.5% 1124/com.google.android.inputmethod.pinyin: 1.2% user + 0.2% kernel / faults: 5726 minor 39 major
1.4% 331/adbd: 0.4% user + 1% kernel / faults: 8283 minor
1.3% 146/rknn_server: 0.1% user + 1.2% kernel
0.5% 224/android.hardware.graphics.composer@2.1-service: 0.2% user + 0.3% kernel / faults: 31 minor
0.5% 138/logd: 0.1% user + 0.3% kernel / faults: 21 minor
0.4% 340/installd: 0.3% user + 0.1% kernel / faults: 140 minor
0.4% 246/zygote64: 0% user + 0.3% kernel / faults: 2679 minor
0.3% 329/rild: 0% user + 0.3% kernel
0.3% 7/kworker/u8:0-flush-179:0: 0% user + 0.3% kernel / faults: 1137 minor
0.2% 50/cfinteractive: 0% user + 0.2% kernel
0.2% 286/audioserver: 0.1% user + 0.1% kernel / faults: 125 minor
0.2% 346/mediaserver: 0.1% user + 0.1% kernel / faults: 346 minor
0.2% 141/hwservicemanager: 0% user + 0.1% kernel / faults: 192 minor
0.2% 387/media.swcodec: 0.1% user + 0% kernel / faults: 136 minor
0.2% 870/logcat: 0% user + 0.1% kernel
0.2% 949/com.android.launcher3: 0.1% user + 0% kernel / faults: 537 minor
0.2% 1/init: 0% user + 0.1% kernel / faults: 39 minor
0.1% 81/kworker/0:1H-mmc_complete: 0% user + 0.1% kernel
0.1% 111/kworker/2:2H-kblockd: 0% user + 0.1% kernel
0.1% 262/android.hardware.audio.service: 0% user + 0.1% kernel / faults: 37 minor
0.1% 230/kworker/u8:3-devfreq_wq: 0% user + 0.1% kernel / faults: 770 minor
0.1% 393/irq/77-dwc3: 0% user + 0.1% kernel
0.1% 873/com.android.phone: 0% user + 0% kernel / faults: 14 minor
0.1% 244/statsd: 0% user + 0% kernel / faults: 6 minor
0.1% 896/com.android.settings: 0.1% user + 0% kernel / faults: 420 minor 1 major
0.1% 95/kworker/1:1H-kblockd: 0% user + 0.1% kernel
0.1% 231/kworker/0:3H-mmc_complete: 0% user + 0.1% kernel
0.1% 917/android.ext.services: 0.1% user + 0% kernel / faults: 630 minor
0.1% 46/kworker/2:1-events_freezable: 0% user + 0.1% kernel
0.1% 80/kworker/3:1H-kblockd: 0% user + 0.1% kernel
0.1% 140/servicemanager: 0% user + 0% kernel
0.1% 1102/com.android.deskclock: 0% user + 0% kernel / faults: 503 minor
0% 229/kworker/u8:2: 0% user + 0% kernel / faults: 350 minor
0% 425/kworker/u9:2-kbase_pm_poweroff_wait: 0% user + 0% kernel
0% 10/rcu_preempt: 0% user + 0% kernel
0% 139/lmkd: 0% user + 0% kernel
0% 216/android.hardware.graphics.allocator@4.0-service: 0% user + 0% kernel / faults: 191 minor
0% 481/kworker/u9:3-blk_crypto_wq: 0% user + 0% kernel
0% 78/ion_system_heap: 0% user + 0% kernel
0% 105/kworker/1:2H-kblockd: 0% user + 0% kernel
0% 124/kworker/3:2-events_power_efficient: 0% user + 0% kernel
0% 190/f2fs_discard-25: 0% user + 0% kernel
0% 270/android.hardware.health@2.1-service: 0% user + 0% kernel
0% 977/com.hsdz.systemcontroler:shellservice: 0% user + 0% kernel / faults: 163 minor
0% 11/rcu_sched: 0% user + 0% kernel
0% 14/kworker/0:1-kdmflush: 0% user + 0% kernel
0% 45/kconsole: 0% user + 0% kernel
0% 131/kworker/1:2-kdmflush: 0% user + 0% kernel
0% 148/vold: 0% user + 0% kernel / faults: 87 minor
0% 172/android.system.suspend@1.0-service: 0% user + 0% kernel
0% 280/android.hardware.power-service.rockchip: 0% user + 0% kernel
0% 342/media.extractor: 0% user + 0% kernel
0% 822/com.android.se: 0% user + 0% kernel / faults: 10 minor
解决
?????可以从packages/services/Telephony着手, 将PhoneApp中的代码移到Service中去执行, 这样改了之后, 会产生什么影响, 需要做更多验证, 至少目前测试来说, 4G部分功能及开机广播功能都正常.
|