开机后APP重启动分析

现象：重启系统后，马上打开任意一个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