IMS 注册慢问题分析
1、问题描述
VOLTE长时间没注册上。
2、Log分析
10-04 15:49:04.745089 2118 3531 D ImsService: enableIms, phoneId = 1
10-04 15:49:04.757739 1423 1498 D RmcImsCtlReqHdl: [1] requestSetImsCfg volte:1, vilte:1, vowifi:0, viwifi:0, sms:1, imsTestMode:0, eims:1
10-04 15:49:04.757800 1423 1498 I AT : [1] AT> AT+EIMSCFG=1,1,0,0,1,1 (RIL_CMD2_READER_3 tid:481754402032)
从Log看,IMS配置已经发送到Modem了。但是Modem发起PDN建立在15:49:30左右,这个导致IMS注册有明显的延时。
进一步研究发现,上层发起PDN的建立依赖Modem上报AT< +EIMSPDN通知
如果对IMS感兴趣,可以参考
Telephony IMS-CSDN博客
10-04 15:49:31.065500 1423 1468 I AT : [1] AT< +EIMSPDN: "notify", 33, 1, "ims",3,0,0 (RIL_URC2_READER, tid:481920011504)
10-04 15:49:31.180564 1423 1500 I AT : [1] AT> AT+EAPNACT=1,"ims","ims",0,,"dnn=ims",,0 (RIL_CMD2_READER_4 tid:481735552240)
3、解决方案
提交MTK Case确认为什么EIMSPDN建立过慢
Dear Customer,
We have checked the logs further, RF resource are fluctuate b/w SIM1 and SIM2.
As we can see from the logs DUT established bearer @ 15:49:04:651, at this time DUT has resource for 2 seconds, Next DUT star RSRS Process and sent to NW, But NW did not respond.
Due to RSRA Process not completed @ 15:49:04:651 modem received ra", "no_ra_initial, and REG was not done.
As we suggested you in previous Note please help to retest DUT/REF parallelly with same Sim card and share logs from bootup.
[DUT Traces]:
Type | Index | Time | Local Time | Module | Message | Comment |
SYS | 2950914 | 169697153 | 15:49:04:251 | NIL | [AT_RX p46,ch15]AT+EIMSCFG=1,1,0,0,1,1 => Decode:Integrated IMS related capability and functionality +EIMSCFG | |
PS | 2951744 | 169697283 | 15:49:04:251 | IMC_2 - IMCB_2 | MSG_ID_IMCB_IMC_IMS_REG_IND | |
PS | 2951838 | 169697294 | 15:49:04:251 | IMC_2 | [IMC-REG] Account type: IMC_ACCT_TY_NORMAL, Current REG FSM State: IMC_REG_FSM_STATE_REGISTERING | |
PS | 2953618 | 169697546 | 15:49:04:251 | IMSM_2 - D2PM_2 | MSG_ID_D2CM_ACT_DATA_CALL_REQ | |
PS | 2954351 | 169697679 | 15:49:04:251 | D2RM_2 - DDM_2 | MSG_ID_D2RM_DDM_ACT_DATA_CALL_REQ | //IMS |
OTA | 2956118 | 169697988 | 15:49:04:251 | ESM_2 | [MS->NW] ESM_MSG_PDN_CONNECTIVITY_REQUEST (PTI:11, EBI:0) | [Comments in OTA structure] |
PS | 2961500 | 169699386 | 15:49:04:451 | ERRC_2 - RSVAS | MSG_ID_RSVAS_SERVICE_RES_OCCUPY_REQ | //cs |
PS | 2963039 | 169699699 | 15:49:04:451 | ERRC - RSVAS | MSG_ID_RSVAS_SERVICE_RES_RELEASE_REQ | //hps |
OTA | 2975882 | 169703106 | 15:49:04:651 | ESM_2 | [NW->MS] ESM_MSG_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_REQUEST (PTI:11, EBI:6) | [Comments in OTA structure] |
OTA | 2976113 | 169703141 | 15:49:04:651 | ESM_2 | [MS->NW] ESM_MSG_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:6) | |
PS | 2978652 | 169703733 | 15:49:04:651 | DDM_2 - D2RM_2 | MSG_ID_D2RM_DDM_ACT_DATA_CALL_CNF | |
SYS | 2979133 | 169703841 | 15:49:04:651 | NIL | [AT_URC p64,ch23]+EIF: 4502, ifup, 2, FE:80:00:00:00:00:00:00:00:00:00:00:00:00:00:01, 0 | |
SYS | 2979527 | 169703926 | 15:49:04:651 | NIL | [AT_RX p63,ch22]AT+EIF=4502, "ifst", "up", 2 => Decode:Update the network interface information +EIF | |
SIP | 2988430 | 169708996 | 15:49:05:051 | [MS->NW][P1][S1]SUBSCRIBE sip:+8613662238564@gd.ims.mnc000.mcc460.3gppnetwork.org SIP/2.0 | ||
OTA | 2993346 | 169712595 | 15:49:05:251 | ERRC_MOB_2 | [MS->NW] ERRC_MeasurementReport (EARFCN[1850], PCI[94]) (measID[3] eventA2 pcell[1850/94] rslt[-425][-38]) | |
OTA | 3023964 | 169732429 | 15:49:06:451 | ERRC_CONN_2 | [NW->MS] ERRC_RRCConnectionRelease(EARFCN[1850], PCI[94])(cause:[ReleaseCause_other], redirectInfo:[0]) | |
PS | 3025489 | 169732886 | 15:49:06:451 | ERRC_2 - RSVAS | MSG_ID_RSVAS_SERVICE_RES_RELEASE_REQ | //cs |
PS | 3034786 | 169734675 | 15:49:06:651 | ERRC - RSVAS | MSG_ID_RSVAS_SERVICE_RES_OCCUPY_REQ | //hps |
PS | 3047355 | 169740263 | 15:49:07:051 | ERRC - RSVAS | MSG_ID_RSVAS_SERVICE_RES_RELEASE_REQ | //hps |
PS | 3086159 | 169766481 | 15:49:08:652 | ERRC_2 - RSVAS | MSG_ID_RSVAS_SERVICE_RES_OCCUPY_REQ | //cs |
PS | 3104595 | 169775417 | 15:49:09:253 | TIMER - IMC_2 | MSG_ID_TIMER_EXPIRY | |
PS | 3104599 | 169775418 | 15:49:09:253 | IMC_2 | [IMC-Timer] Timer expiry. expiry_time: 5000 (ms) | |
PS | 3144085 | 169800288 | 15:49:10:853 | ERRC_2 - RSVAS | MSG_ID_RSVAS_SERVICE_RES_RELEASE_REQ | |
PS | 3262037 | 169891444 | 15:49:16:659 | D2RM_2 - DDM_2 | MSG_ID_D2RM_DDM_DEACT_DATA_CALL_REQ | |
OTA | 3262451 | 169891476 | 15:49:16:659 | ESM_2 | [MS->NW] ESM_MSG_PDN_DISCONNECT_REQUEST (PTI:12, EBI:0) | //sim2 |
SYS | 3304981 | 169922714 | 15:49:18:659 | NIL | [AT_RX p63,ch22]AT+EIF=4502, "ra", "no_ra_initial" => Decode:Update the network interface information +EIF | |
OTA | 3307457 | 169924429 | 15:49:18:859 | ERRC_CONN_2 | [NW->MS] ERRC_RRCConnectionRelease(EARFCN[1850], PCI[94])(cause:[ReleaseCause_other], redirectInfo:[0]) | |
OTA | 3377597 | 169987719 | 15:49:22:732 | ESM_2 | [MS->NW] ESM_MSG_PDN_DISCONNECT_REQUEST (PTI:12, EBI:0) | |
OTA | 3452747 | 170084328 | 15:49:28:933 | ESM_2 | [MS->NW] ESM_MSG_PDN_DISCONNECT_REQUEST (PTI:12, EBI:0) | |
OTA | 3454805 | 170085357 | 15:49:29:133 | ESM_2 | [NW->MS] ESM_MSG_DEACTIVATE_EPS_BEARER_CONTEXT_REQUEST (PTI:12, EBI:6) | |
OTA | 3454935 | 170085374 | 15:49:29:133 | ESM_2 | [MS->NW] ESM_MSG_DEACTIVATE_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:6) | |
PS | 3455996 | 170085562 | 15:49:29:133 | DDM_2 - D2RM_2 | MSG_ID_D2RM_DDM_DEACT_DATA_CALL_CNF | |
PS | 3456084 | 170085575 | 15:49:29:133 | D2CM_2 - IMSM_2 | MSG_ID_D2CM_ACT_DATA_CALL_CNF | |
SYS | 3456150 | 170085592 | 15:49:29:133 | NIL | [AT_URC p64,ch23]+EIF: 4502, ifdown, 0 | |
PS | 3456306 | 170085639 | 15:49:29:133 | RSVAS | RSVAS: SIM2: curr = RSVAS_SIM_CONNECTED, new = RSVAS_SIM_CONNECTED, target = RSVAS_SIM_CONNECTED | |
SYS | 3457034 | 170085779 | 15:49:29:133 | NIL | [AT_RX p63,ch22]AT+EIF=4502, "ifst", "down", 0 => Decode:Update the network interface information +EIF | |
PS | 3503394 | 170101435 | 15:49:30:134 | IMSM_2 - D2PM_2 | MSG_ID_D2CM_ACT_DATA_CALL_REQ | |
OTA | 3507944 | 170102164 | 15:49:30:134 | ESM_2 | [MS->NW] ESM_MSG_PDN_CONNECTIVITY_REQUEST (PTI:13, EBI:0) | [Comments in OTA structure] |
OTA | 3519749 | 170105797 | 15:49:30:334 | ESM_2 | [NW->MS] ESM_MSG_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_REQUEST (PTI:13, EBI:7) | [Comments in OTA structure] |
OTA | 3519925 | 170105825 | 15:49:30:334 | ESM_2 | [MS->NW] ESM_MSG_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:7) | |
PS | 3522977 | 170106516 | 15:49:30:334 | DDM_2 - D2RM_2 | MSG_ID_D2RM_DDM_ACT_DATA_CALL_CNF | |
SYS | 3523455 | 170106636 | 15:49:30:334 | NIL | [AT_URC p64,ch23]+EIF: 4603, ifup, 2, FE:80:00:00:00:00:00:00:00:00:00:00:00:00:00:01, 0 | //Pass case |
SYS | 3524483 | 170106819 | 15:49:30:534 | NIL | [AT_RX p63,ch22]AT+EIF=4603, "ifst", "up", 2 => Decode:Update the network interface information +EIF | |
SYS | 3525398 | 170107778 | 15:49:30:534 | NIL | [AT_RX p63,ch22]AT+EIF=4603, "ipupdate", 2, "24:08:85:71:11:14:14:00:00:00:00:00:00:00:00:01/64" => Decode:Update the network interface information +EIF | // Pass case |
SYS | 3526578 | 170108043 | 15:49:30:534 | NIL | [AT_URC p43,ch12]+EIMSPDN: "notify", 33, 1, "ims",3,0,0 | |
SYS | 3526935 | 170108404 | 15:49:30:534 | NIL | [AT_RX p72,ch20]AT+EIMSPDN= "confirm", 33, 0 |
MTK认为是网络问题,复测后未复现。