现象:重启系统后,马上打开任意一个app activity,隔40S左右app自动重启。 也就是会重走生命周期。 结论如图:
分析过程:
//APP接收到AMS relunch消息,APP 执行到relaunchActivity,这会导致APP 重走onCreate生命周期 01-19 04:29:06.847 491 715 D ActivityManager: Resumed after relaunch ActivityRecord{760e9e5 u0 com.android.gallery3d/.app.GalleryActivity t11} 01-19 04:29:06.850 1518 1531 D tanrong1: requestRelaunchActivityandroid.app.ActivityThread@33ec990 01-19 04:29:06.850 1518 1531 D tanrong1: java.lang.Throwable: 4354 01-19 04:29:06.850 1518 1531 D tanrong1: at android.app.ActivityThread.requestRelaunchActivity(ActivityThread.java:4354) 01-19 04:29:06.850 1518 1531 D tanrong1: at android.app.ActivityThread$ApplicationThread.scheduleRelaunchActivity(ActivityThread.java:754) 01-19 04:29:06.850 1518 1531 D tanrong1: at android.app.ApplicationThreadNative.onTransact(ApplicationThreadNative.java:183) 01-19 04:29:06.850 1518 1531 D tanrong1: at android.os.Binder.execTransact(Binder.java:565) 01-19 04:29:06.846 491 715 D ActivityManager: Moving to RESUMED Relaunching ActivityRecord{760e9e5 u0 01-19 04:29:06.850 1518 1531 D ActivityThread: relaunchActivity android.app.ActivityThread@33ec990, target ActivityRecord{afd628e token=android.os.BinderProxy@75fa121 no component name} operation received seq: 0
AMS判断需要重启com.android.gallery3d.app.GalleryActivity 01-19 04:29:06.804 491 715 V ActivityManager: Ensuring correct configuration: ActivityRecord{760e9e5 u0 com.android.gallery3d/.app.GalleryActivity t11} 01-19 04:29:06.805 491 715 V ActivityManager: Configuration changes for ActivityRecord{760e9e5 u0 com.android.gallery3d/.app.GalleryActivity t11} ; taskChanges={}, allChanges={CONFIG_MCC, CONFIG_MNC} 01-19 04:29:06.805 491 715 V ActivityManager: Checking to restart com.android.gallery3d.app.GalleryActivity: changed=0x3, handles=0x4a0, newConfig={1.0 999mcc40mnc [en_US] ldltr sw800dp w800dp h1208dp 160dpi xlrg port finger -keyb/v/h -nav/h s.5}, taskConfig={1.0 ?mcc?mnc ?localeList ?layoutDir ?swdp ?wdp ?hdp ?density ?lsize ?long ?orien ?uimode ?night ?touch ?keyb/?/? ?nav/?} AMS 会判断已经打开的应用的activity的配置是否与最新配置的相同,不同的activity会被relunch。 services/core/java/com/android/server/am/ActivityStack.java
//AMS 判断APP relunchAcitivity的 Callstack 01-19 04:29:06.843 491 715 V ActivityManager: Config is relaunching resumed ActivityRecord{760e9e5 u0 com.android.gallery3d/.app.GalleryActivity t11} 01-19 04:29:06.844 1417 1418 D AT : s_type : (2) 01-19 04:29:06.845 491 715 D ActivityManager: Relaunching: ActivityRecord{760e9e5 u0 com.android.gallery3d/.app.GalleryActivity t11} with results=null newIntents=null andResume=true preserveWindow=false 01-19 04:29:06.845 491 715 D ActivityManager: java.lang.Throwable: tanrong 01-19 04:29:06.845 491 715 D ActivityManager: at com.android.server.am.ActivityStack.relaunchActivityLocked(ActivityStack.java:4823) 01-19 04:29:06.845 491 715 D ActivityManager: at com.android.server.am.ActivityStack.ensureActivityConfigurationLocked(ActivityStack.java:4697) 01-19 04:29:06.845 491 715 D ActivityManager: at com.android.server.am.ActivityManagerService.updateConfigurationLocked(ActivityManagerService.java:19363) 01-19 04:29:06.845 491 715 D ActivityManager: at com.android.server.am.ActivityManagerService.updateConfigurationLocked(ActivityManagerService.java:19208) 01-19 04:29:06.845 491 715 D ActivityManager: at com.android.server.am.ActivityManagerService.updateConfigurationLocked(ActivityManagerService.java:19202) 01-19 04:29:06.845 491 715 D ActivityManager: at com.android.server.am.ActivityManagerService.updateConfiguration(ActivityManagerService.java:19188) 01-19 04:29:06.845 491 715 D ActivityManager: at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:1224) 01-19 04:29:06.845 491 715 D ActivityManager: at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2909) 01-19 04:29:06.845 491 715 D ActivityManager: at android.os.Binder.execTransact(Binder.java:565)
将AMS的log打开后抓取log services/core/java/com/android/server/am/ActivityManagerDebugConfig.java:42: static final boolean DEBUG_ALL = true;
Telephony 通过调用AMS的updateConfigureation方法更新MccMnc 01-19 04:29:06.692 639 639 D MccTable: updateMccMncConfiguration mccmnc=‘99940’ fromServiceState=false 01-19 04:29:06.694 639 639 D SubscriptionController: [getPhoneId]- no sims, returning default phoneId=0 01-19 04:29:06.695 639 639 D MccTable: updateMccMncConfiguration defaultMccMnc= 01-19 04:29:06.695 639 639 D MccTable: updateMccMncConfiguration: mcc=999, mnc=40 01-19 04:29:06.696 639 639 D MccTable: updateMccMncConfiguration updateConfig config={1.0 999mcc40mnc ?localeList ?layoutDir ?swdp ?wdp ?hdp ?density ?lsize ?long ?orien ?uimode ?night ?touch ?keyb/?/? ?nav/?} /frameworks/opt/telephony/src/java/com/android/internal/telephony/MccTable.java
//AMS 收到配置更新请求 01-19 04:29:06.698 491 715 I ActivityManager: Updating configuration to: {0.0 999mcc40mnc ?localeList ?layoutDir ?swdp ?wdp ?hdp ?density ?lsize ?long ?orien ?uimode ?night ?touch ?keyb/?/? ?nav/?}
正常时 11-09 19:51:36.534 488 488 I chatty : uid=1000 system_server expire 213 lines 11-09 19:51:42.078 680 680 D RILJ : Starting RILReceiver0 [SUB0] 11-09 19:51:42.083 680 856 I RILJ : (0) Connected to ‘rild’ socket 11-09 19:51:42.808 680 680 D SIMRecords: [SIMRecords] fetchSimRecords 18 requested: true 11-09 19:51:42.809 680 680 D RILJ : [3708]> getIMSI: GET_IMSI aid: null [SUB0] 连上rild后只过了1秒左右就获取到mccmnc 11-09 19:51:43.713 680 856 D RILJ : [3708]< GET_IMSI [SUB0] 11-09 19:51:43.714 680 680 D MccTable: updateMccMncConfiguration mccmnc=‘46003’ fromServiceState=false 11-09 19:51:43.715 680 680 D SubscriptionController: [getPhoneId]- no sims, returning default phoneId=0 11-09 19:51:43.715 680 680 D MccTable: updateMccMncConfiguration defaultMccMnc=46003 11-09 19:51:43.715 680 680 D MccTable: updateMccMncConfiguration: mcc=460, mnc=3 11-09 19:51:43.715 680 680 D MccTable: updateMccMncConfiguration updateConfig config={1.0 460mcc3mnc ?localeList ?layoutDir ?swdp ?wdp ?hdp ?density ?lsize ?long ?orien ?uimode ?night ?touch ?keyb/?/? ?nav/?} 11-09 19:51:43.760 708 708 I am_on_paused_called: [0,com.android.settings.FallbackHome,handleRelaunchActivity] //正常时也会走handleRelaunchActivity
异常时 01-19 04:27:54.590 491 491 I chatty : uid=1000 system_server expire 215 lines 01-19 04:28:01.331 639 639 D RILJ : Starting RILReceiver0 [SUB0] 01-19 04:28:13.340 639 774 I RILJ : (0) Connected to ‘rild’ socket 01-19 04:28:17.628 639 639 D RILJ : [3696]> getIMSI: GET_IMSI aid: null [SUB0] 01-19 04:28:17.669 639 639 D GsmCdmaPhone: [GsmCdmaPhone] New Uicc application found. type = APPTYPE_SIM 连上rild后却过了53秒左右才就获取到mccmnc 01-19 04:29:06.692 639 639 D MccTable: updateMccMncConfiguration mccmnc=‘99940’ fromServiceState=false 01-19 04:29:06.694 639 639 D SubscriptionController: [getPhoneId]- no sims, returning default phoneId=0 01-19 04:29:06.695 639 639 D MccTable: updateMccMncConfiguration defaultMccMnc= 01-19 04:29:06.695 639 639 D MccTable: updateMccMncConfiguration: mcc=999, mnc=40 01-19 04:29:06.696 639 639 D MccTable: updateMccMncConfiguration updateConfig config={1.0 999mcc40mnc ?localeList ?layoutDir ?swdp ?wdp ?hdp ?density ?lsize ?long ?orien ?uimode ?night ?touch ?keyb/?/? ?nav/?} 01-19 04:29:06.870 1518 1518 I am_on_paused_called: [0,com.android.gallery3d.app.GalleryActivity,handleRelaunchActivity] 异常时,在RILGDM 中requestGetImsi 方法中添加log, hardware/ril/libgdm-ril/gdm-lte-ril-common.c
抓取log如下,说明卡在RILJ下 getIMSI 以后,RILD 下GET_IMSI commands以前 01-20 02:09:37.426 637 637 D RILJ : [3684]> getIMSI: GET_IMSI aid: null [SUB0] 01-20 02:10:19.616 247 277 D RILGDM : ********** RIL_RequestFunc: GET_IMSI (11) 01-20 02:10:19.616 247 277 D RILGDM : tanrong libgdm-ril:requestGetImsi send AT+CIMI 01-20 02:10:19.634 247 277 D RILGDM : tanrong libgdm-ril:requestGetImsi AT+CIMI secucess 01-20 02:10:19.636 637 773 D RILJ : [3684]< GET_IMSI [SUB0]
经过查看RILGDM log,可以发现执行SET_NETWORK_SELECTION_AUTOMATIC耗时长。 01-20 01:45:36.696 248 278 D RILGDM : ********** RIL_RequestFunc: SIM_OPEN_CHANNEL (115) 01-20 01:45:36.696 248 278 D RILGDM : ********** RIL_onRequestComplete: NOT SUPPORTED 01-20 01:45:36.696 248 278 D RILGDM : ********** RIL_RequestFunc: SET_NETWORK_SELECTION_AUTOMATIC (46) 01-20 01:46:25.359 248 278 D RILGDM : ********** RIL_onUnsolicitedResponse: RIL_UNSOL_RESPONSE_VOICE_NETWORK_STATE_CHANGED (1002) 01-20 01:46:25.360 248 278 D RILGDM : ********** RIL_onUnsolicitedResponse: RIL_UNSOL_RESPONSE_IMS_NETWORK_STATE_CHANGED (1037)
添加如下log后可以发现在执行 AT+COPS=0 command 后一直卡住,直到40秒以后才走到ERROR,说明就是这里卡住导致。 /hardware/ril/libgdm-ril/gdm-lte-ril-data.c
log如下: 01-20 04:49:25.168 245 265 E RILGDM : requestSetNetworkSelectionAutomatic send AT+COPS=0 01-20 04:50:07.524 245 265 E RILGDM : requestSetNetworkSelectionAutomatic ERROR 01-20 04:50:08.841 245 265 E RILGDM : requestSetNetworkSelectionAutomatic send AT+COPS=0
|