Android pow键唤醒慢调试记录

9820e在Android4.4按power键唤醒用时过长，需要1s多左右，首先抓kernel日志

01-11 20:18:06.822 <6>[ 1159.282626] c0 [KEY] Key:Power Key ScanCode:116 Value:1  // power键按下
01-11 20:18:06.832 <6>[ 1159.286398] c1 [SPRD_KPLED_INFO]sprd_kpled_set!
01-11 20:18:06.832 <6>[ 1159.286411] c1 [SPRD_KPLED_INFO]led->chip_version=3
01-11 20:18:06.832 <6>[ 1159.286416] c1 [SPRD_KPLED_INFO]led->brightness_max=128
01-11 20:18:06.832 <6>[ 1159.286420] c1 [SPRD_KPLED_INFO]led->run_mode=0
01-11 20:18:06.832 <6>[ 1159.286425] c1 [SPRD_KPLED_INFO]led->reg_kpled_ctrl0=0x2ac
01-11 20:18:06.832 <6>[ 1159.286430] c1 [SPRD_KPLED_INFO]led->reg_kpled_ctrl1=0x2b0
01-11 20:18:06.832 <6>[ 1159.286468] c1 [SPRD_KPLED_INFO]sprd_kpled_ldo_switch power=1
01-11 20:18:06.832 <6>[ 1159.286474] c1 [SPRD_KPLED_INFO]reg:0x00000EB0 ldo_pd_mask:0x00007F8A  ldo_pd_value:0x00007F8A
01-11 20:18:06.832 <6>[ 1159.286506] c1 [SPRD_KPLED_INFO]sprd_kpled_enable
01-11 20:18:06.832 <6>[ 1159.286515] c1 [SPRD_KPLED_INFO]sprd_kpled_set_brightness:led->run_mode = 0
01-11 20:18:06.832 <6>[ 1159.286545] c1 [SPRD_KPLED_INFO]reg:0x00000EB0 set_val:0x00007F80 brightness:255
01-11 20:18:06.842 <6>[ 1159.303355] c1 wlan sprd-wlan wlan0: sprdwl_set_power_save: set suspend mode,value : 1
01-11 20:18:06.842 <6>[ 1159.303378] c1 ieee80211 phy0: [1159280]mode 1 send[WIFI_CMD_POWER_SAVE]
01-11 20:18:06.844 <6>[ 1159.304502] c0 ieee80211 phy0: mode 1 recv rsp[WIFI_CMD_POWER_SAVE]
01-11 20:18:06.863 <6>[ 1159.324147] c0 [sprd-adf][       panel_suspend] panel suspend OK
01-11 20:18:06.863 <6>[ 1159.324166] c0 [sprd-adf][      swdispc_uninit] swdispc uninit
01-11 20:18:06.863 <6>[ 1159.324172] c0 [sprd-adf][  sprd_dispc_suspend] dispc suspend OK
01-11 20:18:06.863 <6>[ 1159.324178] c0 [sprd-adf][    sprd_adf_suspend] adf suspend end
01-11 20:18:06.872 <3>[ 1159.325903] c1 [sprd-adf][     sprd_dispc_flip] dispc is not initialized!
01-11 20:18:06.872 <6>[ 1159.327113] c0 [sprd-adf][     sprd_adf_resume] adf resume start
01-11 20:18:06.873 <6>[ 1159.334194] c0 [sprd-adf][        swdispc_init] swdispc init
01-11 20:18:06.873 <6>[ 1159.334205] c0 [sprd-adf][   swdispc_intf_init] swdispc intf inited
01-11 20:18:06.873 <3>[ 1159.334214] c0 [iommu] sprd_iommu_restore()-illegal master
01-11 20:18:06.882 <6>[ 1159.339612] c0 [sprd-adf][   sprd_dispc_resume] dispc resume OK
01-11 20:18:06.882 <6>[ 1159.339817] c0 [sprd-adf][  spi_runtime_resume] spi_runtime_resume now
01-11 20:18:06.993 <6>[ 1159.453333] c1 n=1,value=0x0,addr_ic=0x2a4,val=0x0
01-11 20:18:06.993 <6>[ 1159.453361] c1 sprd_pmic_eic_irq_mask 320+1,bitof=1,group=0
01-11 20:18:06.993 <6>[ 1159.453464] c0 sprd_pmic_eic_irq_unmask 320+1,bitof=1
01-11 20:18:06.993 <6>[ 1159.453496] c0 [KEY] wake up cpu by level trigger:8
01-11 20:18:06.993 <6>[ 1159.453516] c0 [KEY] Key:Power Key ScanCode:116 Value:0
01-11 20:18:07.202 <6>[ 1159.663368] c0 [sprd-adf][        panel_resume] panel resume OK
01-11 20:18:07.202 <6>[ 1159.663384] c0 [sprd-adf][         swdispc_run] swdispc run now
01-11 20:18:07.202 <6>[ 1159.663392] c0 [sprd-adf][     sprd_adf_resume] adf resume end
01-11 20:18:07.203 <6>[ 1159.664091] c0 [sprd-adf][   swdispc_enable_te] TE enable
01-11 20:18:07.215 <6>[ 1159.675295] c1 [sprd-adf][ sprd_spi_flip_layer] layer base 8fb3e000 bpp 16
01-11 20:18:07.247 <6>[ 1159.704057] c0 [sprd-adf][  swdispc_disable_te] TE disable
01-11 20:18:07.262 <6>[ 1159.716203] c1 [sprd-adf][ sprd_spi_flip_layer] layer base 8fb66000 bpp 16
01-11 20:18:07.286 <6>[ 1159.746564] c1 [sprd-adf][   swdispc_enable_te] TE enable
01-11 20:18:07.302 <6>[ 1159.757170] c1 [sprd-adf][ sprd_spi_flip_layer] layer base 8fb3e000 bpp 16
01-11 20:18:07.302 <6>[ 1159.763020] c0 dfs_request, dfs succeeded!current freq:667
01-11 20:18:07.342 <6>[ 1159.797956] c1 [sprd-adf][ sprd_spi_flip_layer] layer base 8fb66000 bpp 16
01-11 20:18:07.473 <6>[ 1159.933826] c1 [sprd-adf][  swdispc_disable_te] TE disable
01-11 20:18:07.575 <6>[ 1160.036249] c1 wlan sprd-wlan wlan0: sprdwl_set_power_save: set suspend mode,value : 0
01-11 20:18:07.575 <6>[ 1160.036280] c1 ieee80211 phy0: [1160013]mode 1 send[WIFI_CMD_POWER_SAVE]
01-11 20:18:07.577 <4>[ 1160.037343] c1 mdbg_read read_size: 1024 mdbg_read_count:0
01-11 20:18:07.577 <6>[ 1160.037488] c0 ieee80211 phy0: mode 1 recv rsp[WIFI_CMD_POWER_SAVE]
01-11 20:18:07.592 <6>[ 1160.052937] c0 sprdbat: sprdbat_battery_works
01-11 20:18:07.594 <6>[ 1160.053924] c0 adc channel 14, value 1219
01-11 20:18:07.594 <6>[ 1160.053939] c0 sprdbat: sprdbat_get_val_from_buff value=4990,type =0
01-11 20:18:07.594 <6>[ 1160.053945] c0 sprdbat: sprdbat_get_val_from_buff value=-184,type =1
01-11 20:18:07.594 <6>[ 1160.054015] c0 sprdfgu: d cap -7,cnom 1900,g -132mAh(0.1mA),init_cc:39967100
01-11 20:18:07.594 <6>[ 1160.054022] c0 sprdfgu: soc 100,init_cap 1000,cap:993
01-11 20:18:07.594 <6>[ 1160.054174] c0 sprdfgu: cap read ui= 100,raw_soc = 993
01-11 20:18:07.594 <6>[ 1160.054182] c0 sprdbat: trickle_s_time: = 1160,trickle_time: = 1531
01-11 20:18:07.594 <6>[ 1160.054188] c0 sprdbat: fgu_cap: = 100,flush: = 16,period:=16
01-11 20:18:07.594 <6>[ 1160.054194] c0 sprdbat: bat_log:time:1160
01-11 20:18:07.594 <6>[ 1160.054201] c0 sprdbat: vbat:4117,ocv:4163,current:-184,cap:100
01-11 20:18:07.594 <6>[ 1160.055019] c0 adc channel 5, value 3225
01-11 20:18:07.594 <6>[ 1160.055029] c0 sprdbat: state:4,auxbat:4120,temp:200,present:1
01-11 20:18:07.812 <6>[ 1160.267522] c0 lowmemorykiller: Killing 'ndroid.settings' (2582:2582), adj 529,
01-11 20:18:07.812 <6>[ 1160.267522] c0    to free 16164kB on behalf of 'kswapd0' (40) because
01-11 20:18:07.812 <6>[ 1160.267522] c0    cache is 31528kB , limit is 34816kB for oom_score_adj 529
01-11 20:18:07.812 <6>[ 1160.267522] c0    Free memory is 16764kB above reserved
01-11 20:18:07.812 <6>[ 1160.267522] c0    swaptotal is 204796kB, swapfree is 109620kB, pressure is 0
01-11 20:18:07.812 <6>[ 1160.267522] c0    cache_orig is 26888kB
01-11 20:18:07.812 <6>[ 1160.267560] c0 lowmemorykiller: nlmsg_multicast error:-3
01-11 20:18:07.885 <6>[ 1160.345490] c0 [sprd-sc2721-backlight][sprd_bl_whtled_update_status] brightness = 178, led_level = 178   //背光亮

 从power键按下到背光亮，我们看到用时1.063秒，提交给展讯分析，展讯怀疑adf这一块有问题（Atomic Display Framework是Google新推出的一个关于Display驱动的框架）,在kernel/drivers/video/adf/adf_client.c函数 adf_interface_blank添加打印日志。

int adf_interface_blank(struct adf_interface *intf, u8 state) {     struct adf_device *dev = adf_interface_parent(intf);     u8 prev_state;     bool disable_vsync;     bool enable_vsync;     int ret = 0;     struct adf_event_refcount *vsync_refcount; // 在此函数进入的时候加打印  ++ printk("=====================> (%s) start\n", __func__);     if (!intf->ops || !intf->ops->blank)         return -EOPNOTSUPP;        ....... done:     mutex_unlock(&intf->base.event_lock);     mutex_unlock(&dev->client_lock); // 在此加此函数退出的时候加打印  ++ printk("=====================> (%s) end\n", __func__);     return ret; } EXPORT_SYMBOL(adf_interface_blank);

 抓取kernel日志：
01-01 00:01:43.676 <4>[    8.137957] c0 =====================> (adf_interface_blank) start
01-01 00:01:43.676 <6>[    8.137972] c0 [sprd-adf][sprd_adf_interface_dpms_on] dpms enable
01-01 00:01:43.676 <4>[    8.137978] c0 =====================> (adf_interface_blank) end

发现耗时不在这里。

继续分析，

根据最新的log，以最后一次Waking up分析，整个过程耗时960ms，且耗时在"Unblocked screen on"之前。 在4.4中，当Window中完成其任务，回调 screenOnListener.onScreenOn()后，如果此时亮灭屏广播发送将解除亮屏流程阻塞（Unblocked screen on），设置背光。根据前面的分析，此时BroadQueue中亮灭屏广播已经发生完毕，而亮屏流程依旧阻塞，只能说明Window中回调screenOnListener.onScreenOn()晚了， 谢谢 //Powerkey事件 01-02 03:56:58.599   600   639 D WindowManager: interceptKeyTq keycode=26 screenIsOn=false keyguardActive=true policyFlags=2000001 isWakeKey=true down=true //进入Wakeup 流程 01-02 03:56:58.599   600   639 I PowerManagerService: Waking up from sleep... 01-02 03:56:58.599   600   600 I power_screen_broadcast_send: 1 //-----------------start 01-02 03:56:58.599   600   600 D WindowManager: Screen turning on... 01-02 03:56:58.599   600   600 D WindowManager: screenOnListener != null 01-02 03:56:58.599   600   600 D WindowManager: Setting event dispatching to true 01-02 03:56:59.059   600   611 I WindowManager: Lock screen displayed! 01-02 03:56:59.059   600   611 D WindowManager: finishScreenTurningOn maybe set event dispatch to true 01-02 03:56:59.059   600   600 I power_screen_broadcast_done: [1,464,1] //call screenOnListener.onScreenOn() 01-02 03:56:59.559   600   611 D PowerManagerNotifier: release screenon blocker //-----------------end 耗时区域 //unblock后至背光设置完成，未出现耗时 01-02 03:56:59.559   600   635 D DisplayPowerController: Unblocked screen on after 125005 ms 01-02 03:56:59.559   600  1811 E LIGHTS  : file:vendor/sprd/modules/lights/lights.c, func:write_int, path=/sys/class/backlight/sprd_backlight/brightness, value=178

 

最后发现在phonewindowmanager.java的 里面发现

if (screenOnListener != null) {             /* SPRD: Graphics draws slow, need to light up later */             try {                Thread.sleep(500);    //唤醒前有一个500ms的延时，最后修改这里             } catch (Exception e) {             }             screenOnListener.onScreenOn();         }

最后贴上一张流程图