AP suspend异常debug及log分析

tangh

[DESCRIPTION]
分析待机平均电流高的问题时，经常需要知道每次wake up起来的时间点，以及唤醒的时长，以此找到一些异常的唤醒


[SOLUTION]
1、定位系统无法待机原因
1.1 设备连接powermonitor可以直接从电流图判断休眠情况的定位方法
     如果从电流图看到系统无法suspend，插入USB通过如下cmd dump当前阻止休眠的wakelocks：

1. #adb shell
   
2. #cat /sys/kernel/debug/wakeup_sources |sed -e 's/"^ "/"unnamed"/g' | awk '{print $6 "\t" $1}' | grep -v "^0" |sort -n

复制代码

例如:

1. active_since name
   
2. 24               WLAN
   
3. 79               mt6360_pmu_chg.2.auto
   
4. 24271         PowerManagerService.WakeLocks （PMS持锁）
   
5. 35558         musb-hdrc （USB持锁，因插usb，属于正常现象）

复制代码

如果有PMS持锁，则执行如下cmd dump出持锁的应用：#dumpsys power | grep " PARTIAL_WAKE_LOCK "
例如：如下GMS应用持锁

1. PARTIAL_WAKE_LOCK 'wake:com.google.android.gms/.auth.account.be.accountstate.LoginAccountsChangedIntentService' ACQ=-15s910ms (uid=10177 (displayid =0 pid=4937 pkg=com.google.android.gms uid=10177)

复制代码

1.2 kernel log定位方法
在对应时间段log中搜索“active wakeup source”，可以定位到阻止系统休眠的wakelock：

1.       active wakeup source: WLAN timeout
   
2.       active wakeup source: PowerManagerService.WakeLocks
   
3.       active wakeup source: ccci_poll

复制代码

2、快速定位suspend/resume耗时较长问题

执行如下adb cmd：

1. #adb shell "echo 1 > /sys/module/kernel/parameters/initcall_debug"
   
2. #adb shell "echo 1 > /sys/power/pm_print_times"

复制代码

拔掉USB灭屏待机，确认系统suspend后，插入usb执行如下cmd:

1. #adb shell
   
2. #dmesg | grep 'call ' | awk '{print $4 "\t" $8}' | sort -k 2 -rn > /data/result.txt
   
3. #adb pull /data/result.txt

复制代码

打开result文件，可以看的每个device resume耗时（如下），请相关owner确认是否可以优化：
例如：

1. dpm_name usecs
   
2. bootdevice+ 25318
   
3. mt_charger+ 6406
   
4. 13000000.mfg_lorne+ 5208
   
5. mt-pmic+ 3334

复制代码

3、唤醒kernel log分析
     note：如下介绍以MT6853 suspend wake up log为例，旧有平台log或有差异，详见具体item介绍；
搜索“suspend wake up by”关键字，可以找到AP的唤醒原因、上次suspend时长、AP睡下去后subsystem休眠行为等信息

1. <6>[244518.391440] -(0)[5430:Binder:535_2][name:spm&][SPM] suspend wake up by R12_EINT_EVENT_B, timer_out = 4591536, r13 = 0x84006a80, debug_flag = 0xfc1f9bfc 0x4000006e, r12 = 0x40, r12_ext = 0x0, raw_sta = 0x0 0x0 0x0, idle_sta = 0x341b3, req_sta = 0x1c01000 0x0 0x50000017 0x1f0000 0x0, cg_check_sta =0x0, isr = 0x0, rt_req_sta0 = 0x0 rt_req_sta1 = 0x0 rt_req_sta2 = 0xffffffff rt_req_sta3 = 0xffffffff dram_sw_con_3 = 0x0, raw_ext_sta = 0x184255, wake_misc = 0x310000, pcm_flag = 0x488400 0x0 0x488000 0x488000, req = 0x0, clk_settle = 0x60fe, wlk_cntcv_l = 0x94cb344f, wlk_cntcv_h = 0x559, 26M_off_pct = 0
   
2. <6>[244518.391597] -(0)[5430:Binder:535_2][name:spm&][SPM] suspend warning:(OneShot) System LPM is blocked by conn
   
3. <6>[244518.391605] -(0)[5430:Binder:535_2][name:spm&][SPM] Suspended for 140.122 seconds
   
4. <6>[244518.391615] -(0)[5430:Binder:535_2][name:spm&][SPM] md_slp_duration = 4430012
   
5. <6>[244518.391629] -(0)[5430:Binder:535_2][WMT-CONSYS-HW][I]mtk_wmt_resume: mtk_wmt_resume !!
   
6. <6>[244518.391719] -(0)[5430:Binder:535_2]alarmtimer_fired.: type=1, count=19, wakeup count=12, func=devalarm_alarmhandler
   
7. <6>[244518.392756] -(0)[833:mtk_wmtd][WMT-CONSYS-HW][I]mtk_wcn_consys_sleep_info_read_all_ctrl:TOP:0,0;MCU:305,4384893;BT:0,0;WIFI:507,4472662;GPS:0,4591656
   
8. <6>[244518.393447] (0)[833:mtk_wmtd][WMT-CONSYS-HW][I]consys_dump_osc_state:0x180c1340: 0xe010b (BT)
   
9. <6>[244518.428292]  (4)[108:irq/143-mt6358-]mt6358-pmic 10026000.pwrap:mt6359-pmic: Reg[0x534]=0x1,name=rtc,hwirq=64,type=4
   
10. <6>[244518.544532]  (1)[5430:Binder:535_2][name:scp&][mt_scp_dump_sleep_count:988] - scp_sleep_cnt_0 = 26862754

复制代码

（1）唤醒原因：R12_EINT_EVENT_B表示本次外部中断唤醒，具体中断为PMIC mt6359 rtc，即本次因alarmtimer到期唤醒系统，需从android  log或者bugreport定位此时间点alarm到期的应用名称；
         AlarmManager: Native set alarm :Alarm{42786ea8 type 0 com.sina.weibo}
        ps：旧有平台搜索关键字或有差别，可能是“[SPM] wake up by”。注意“mcusys wake up by”为系统退出idle状态时打印的log，非AP suspend唤醒；      

（2）suspend时长：
        timer_out = 4591536 表示上次AP suspend的时长（32k计数，除以32768可转换为秒数）。Suspended for 140.122 seconds打印转换为单位秒的suspend时长；
        ps：旧有平台或许只打印32k计数suspend时长 ，没有转换为单位秒的suspend时长；
（3）唤醒瞬间子系统工作状态：
        如若log中debug_flag = 0xfc1f9bfc最后两个字符不是ff，则表示唤醒前一瞬子系统有起来工作；System LPM is blocked by conn可以找到具体子系统名称（connsys，wifi/bt/gps/fm四合一子系统）；
       ps：旧有平台没有打印打印就有子系统名称，则需要通过R13（ r13 = 0x84006a80）确认到底哪个子系统：R13每个bit代表的意义可以在${platform}_pcm_def.h中找到
            
     （4）AP休眠期间子系统行为：26M clk为所有系统模块提供clock，26M_off_pc表示AP suspend期间26M clock buffer关闭的比例，比例越高理论耗电越小；如上log26M_off_pct = 0则表示AP休眠期间子系统clk一直有开启，可以通过如下log定位哪个子系统模块的问题：

• md_slp_duration = 4430012； AP上次休眠modem休眠时长，32k计数；
• mtk_wcn_consys_sleep_info_read_all_ctrl:TOP:0,0;MCU:305,4384893;BT:0,0;WIFI:507,4472662;GPS:0,4591656； AP上次休眠connsys各个模块休眠时长，32k计数；log可见BT期间一直没有休眠，需要BT owner帮忙进一步分析；
• scp_sleep_cnt_0 = 26862754；scp（sensorhub）core0休眠总次数，可以对比休眠前scp休眠次数确认是否scp导致问题；
  

       PS：旧有平台或需此log打印；

4、常见唤醒源
其余AP suspend常见唤醒源：

• R12_CONN2AP_SPM_WAKEUP_B: connsys唤醒，如应用需要使用wifi联网，需从netlog定位联网应用；
• R12_SCP2SPM_WAKEUP_B: scp sensor相关唤醒，如VOW唤醒系统；
• R12_CCIF0_EVENT_B: modem ccci唤醒，详细分析参考FAQ21806
• R12_AP2AP_PEER_EVENT_B：modem数据业务唤醒，旧有平台可能叫R12_CLDMA_EVENT_B，需从netlog定位联网应用；
  

5、AP suspend后漏电行为排查
（1）默认系统进入suspend之前会打印没有关闭的MTCMOS/PLL/CLKBUF，可以从中排查是否有异常点
      note：大部分时候AP睡下去时MD/CONN MTCMOS还没有关闭属于正常现象   

1. (0)[5430:Binder:535_2][name:spm&][mt6853_suspend_prompt:127] - suspend enter
   
2. (0)[5430:Binder:535_2][Power/clkbuf] suspend warning: XO_WCN is on!!
   
3. (0)[5430:Binder:535_2][Power/clkbuf] suspend warning: XO_EXT is on!!
   
4. (0)[5430:Binder:535_2]suspend warning[0m: PG_MD1
   
5. (0)[5430:Binder:535_2]suspend warning[0m: PG_CONN
   
6. (0)[5430:Binder:535_2][name:spm&][mt6853_suspend_reflect:160] - prepare suspend resume
   
7. (0)[5430:Binder:535_2][name:spm&][mt6853_suspend_reflect:179] - resume

复制代码

（2）可以通过如下cmd在suspend前check更多信息，如gpio、pmic setting等   

1. gpio dump disable/enable:
   
2. echo gpio_dump 0/1 > /sys/kernel/debug/suspend/suspend_state
   
3. golden dump disable/enable:
   
4. echo golden_dump 0/1 > /sys/kernel/debug/suspend/suspend_state
   
5. golden type setting (default)PMIC[0], CG[1], DCM[2]:
   
6. echo golden_type 1/3/7 > /sys/kernel/debug/suspend/suspend_state
   

复制代码