平台
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) { // Only process broadcast timeouts if the system is ready; some early // broadcasts do heavy work setting up system facilities return; } // If the broadcast is generally exempt from timeout tracking, we're done 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) { // We can observe premature timeouts because we do not cancel and reset the // broadcast timeout message after each receiver finishes. Instead, we set up // an initial timeout then kick it down the road a little further as needed // when it expires. 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) { // In this case the broadcast had already finished, but we had decided to wait // for started services to finish as well before going on. So if we have actually // waited long enough time timeout the broadcast, let's give up on the whole thing // and just move on to the next. Slog.i(TAG, "Waited long enough for: " + (r.curComponent != null ? r.curComponent.flattenToShortString() : "(null)")); r.curComponent = null; r.state = BroadcastRecord.IDLE; processNextBroadcast(false); return; } // If the receiver app is being debugged we quietly ignore unresponsiveness, just // tidying up and moving on to the next broadcast without crashing or ANRing this // app just because it's stopped at a breakpoint. 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上可以看出, 在传递广播的过程中, 卡在了其它的某个进程里, 考虑的顺序如下:
1.是否在VvmSimStateTracker.onReceive中处理了比较耗时的操作
2.是否进程初始化执行了耗时操作, 进程中的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; //Ignore.... } 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) { // We are running as the primary user, so should bring up the // global phone state. 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(); // Cache the "voice capable" flag. // This flag currently comes from a resource (which is // overrideable on a per-product basis): sVoiceCapable = ((TelephonyManager) getSystemService(Context.TELEPHONY_SERVICE)) .isVoiceCapable(); // ...but this might eventually become a PackageManager "system // feature" instead, in which case we'd do something like: // sVoiceCapable = // getPackageManager().hasSystemFeature(PackageManager.FEATURE_TELEPHONY_VOICE_CALLS); if (mCM == null) { // Initialize AnomalyReporter early so that it can be used AnomalyReporter.initialize(this); // Inject telephony component factory if configured using other jars. XmlResourceParser parser = getResources().getXml(R.xml.telephony_injection); TelephonyComponentFactory.getInstance().injectTheComponentFactory(parser); // Initialize the telephony framework PhoneFactory.makeDefaultPhones(this); //ignored... }
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; // create the telephony device controller. TelephonyDevController.create(); TelephonyMetrics metrics = TelephonyMetrics.getInstance(); metrics.setContext(context); int retryCount = 0; for(;;) { boolean hasException = false; retryCount ++; try { // use UNIX domain socket to // prevent subsequent initialization 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) { } } } // register statsd pullers. sMetricsCollector = new MetricsCollector(context); sPhoneNotifier = new DefaultPhoneNotifier(context); int cdmaSubscription = CdmaSubscriptionSourceManager.getDefault(context); Rlog.i(LOG_TAG, "Cdma Subscription set to " + cdmaSubscription); /* In case of multi SIM mode two instances of Phone, RIL are created, where as in single SIM mode only instance. isMultiSimEnabled() function checks whether it is single SIM or multi SIM mode */ 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++) { // reads the system properties and makes commandsinterface // Get preferred network type. 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); } // Ignored }
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); // set radio callback; needed to set RadioIndication callback (should be done after // wakelock stuff is initialized above as callbacks are received on separate binder threads) getRadioProxy(null); getOemHookProxy(null); if (RILJ_LOGD) { riljLog("Radio HAL version: " + mRadioVersion); } } /** Returns a {@link IRadio} instance or null if the service is not available. */ @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) { // getService() is a blocking call, so this should never happen 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
/** * each RIL call this interface to register/unregister the unsolicited hardware * configuration callback data it can provide. */ public static void registerRIL(CommandsInterface cmdsIf) { /* get the current configuration from this ril... */ cmdsIf.getHardwareConfig(sRilHardwareConfig); /* ... process it ... */ if (sRilHardwareConfig != null) { AsyncResult ar = (AsyncResult) sRilHardwareConfig.obj; if (ar.exception == null) { handleGetHardwareConfigChanged(ar); } } /* and register for async device configuration change. */ cmdsIf.registerForHardwareConfigChanged(sTelephonyDevController, EVENT_HARDWARE_CONFIG_CHANGED, null); } public static void unregisterRIL(CommandsInterface cmdsIf) { cmdsIf.unregisterForHardwareConfigChanged(sTelephonyDevController); }
跟踪代码找到最终卡住的地方是在创建RIL的时候
同时, 从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部分功能及开机广播功能都正常.
