关闭

AndroidKK4.4 Power key电量屏幕时button light先亮LCD后亮的卡顿有关问题分析

标签: supend休眠唤醒android系统流程
853人阅读 评论(0) 收藏 举报
分类:

转载一篇,分析的不错!

http://m.myexception.cn/android/1955151.html


AndroidKK4.4 Power key电量屏幕时button light先亮LCD后亮的卡顿有关问题分析

网友分享于:2015-07-05  浏览:0次
AndroidKK4.4 Power key电量屏幕时button light先亮LCD后亮的卡顿问题分析

一、问题现象

按下Power key点亮屏幕时,很大概率出现先亮button light,然后再亮屏的现象,明显感觉到卡顿。

线索1、快速按下Power key熄灭和唤醒基本不会出现以上问题现象

线索2、长按Power key会同时亮LCD和button light

线索3、插入2G sdcard基本没有出现过以上问题,换成32G的class 10的sdcard之后就很大概率出现以上问题


Platform:MT6732

Android版本:4.4.4KK

BuildType:user

系统软件版本:SWA27+UM

系统RAM:1GB


参考机行为:

1、参考机1的机制是短按也同时亮button light和LCD,无法参考

2、参考机2与当前项目的机制相同,虽然也伴有卡顿,但是没有达到当前项目的程度,没有出现以上现象


二、Power key休眠和唤醒系统时的处理流程

这里仅说明按下Power key之后,Linux kernel态的休眠和唤醒流程。

1、休眠过程主要步骤:

   1) 冻结用户态进程和内核态任务

   2) 调用注册的设备的suspend的回调函数, 顺序是按照注册顺序

   3) 休眠核心设备和使CPU进入休眠态

冻结进程是内核把进程列表中所有的进程的状态都设置为停止,并且保存下所有进程的上下文. 当这些进程被解冻的时候,他们是不知道自己被冻结过的,只是简单的继续执行。

2、唤醒过程的主要步骤

   1) 休眠中的系统被Power key的按键中断唤醒,同时将按键事件放入输入设备的文件缓冲区中

   2) 唤醒的顺序是和休眠的循序相反的,所以系统设备和总线会首先唤醒,使能系统中断,使能休眠时候停止掉的非启动CPU

   3)继续唤醒每个设备,使能虚拟终端

   4)继续来解冻进程和任务,唤醒终端


三、问题初步分析

初步分析结果:

通过分析log以及对应代码逻辑,发现Power key在分发时的状态出现了问题,最终导致处理流程异常。

下一步行动:

因为log中没有足够的信息来确认代码的执行流程,所以需要添加log再进一步确认问题并输出解决方案。

问题原理:

正常情况下:

1Power key只有长按超过500ms才会通知上层点亮button light,其他按下power key的情况都不会点亮button light

2Power key短按经过预处理之后不会传递给上层,同样也不会点亮button light

当前出问题的异常情况:

1、power key 在正常短按的时候通知上层点亮了button light,同时产生了异常的长按事件


四、问题进一步分析

进一步定义问题现象:

插入sdcard的情况下,很大概率出现按下power key会点亮button light然后再亮LCD,给用户的直接感觉就是卡顿一下

进一步的分析结果:

插入sdcard出现问题的情况下:

power key按下到用户空间接收到,花费了超过500ms的时间,导致inputdispatcher认为产生了长按事件,从而走了点亮button light的流程。

不插入sdcard的正常情况下:

power key按下到用户空间接收到,花费200ms左右的时间,inputdispatcher认为是正常短按,不会走点亮button light的流程。

已知的问题原因:

从有问题的kernel log中看到power key 的中断产生,到唤醒用户空间进程,中间已经花费超过500ms

通过进一步分析发现,这超过500ms的时间都花在了resume系统的过程中,包括resume各种器件的driver以及从cpu

其中就包括sdcard,与此同时,从log中还可以看出,在resume sdcard的时候,其log的时间间隔都比较长,处理过程花费了比较久的时间,加起来大概380ms

对比没有问题的kernel log,没有与resume sdcard相关的log信息打出,也没有花费比较久时间的处理log打出。

未知的问题原因:

为何按下power key resume的过程会超过500ms?特别是处理resume  sdcard的时候,时间耗费比较久?

五、问题结论及后续动作

通过查看代码和与MTK的工程师沟通,resume high speed的sdcard的时间比较长是正常的,但是由于此问题特别影响用户体验,所以需要进行横向对比。
查看qualcomm平台的sdcard resume时间和机制,截止到目前还在添加log验证中,如果qualcomm平台的时间短或者机制比较好,就要敦促MTK去从根本上优化。
另外button light和LCD light之间为何会有时间差?给人感觉卡顿一下的原理:

在系统suspend的状态下,Power key上报到上层系统之后,上层pms经过电源管理状态的处理以及一些状态判断之后会先将wakeup的请求再发送给其内部的一个专门的控制者,其中就包括点亮lcd的操作,但是这个过程是异步的。接下来pms直接根据是否长按power key来决定点亮button与否,这个处理是同步的

然后这个控制者负责与kernel底层交互,将wakeup的请求发送给kernel底层,等kernel处理完成之后再点亮LCD

因此如果系统处于suspend状态,这个时候发送wakeup请求,与kernel底层的交互过程就会稍长,大概250ms左右,这个时间就是你先看到button light亮之后,lcd再亮的中间间隔时间。


六、附上关键代码及Log分析

1休眠和唤醒的关键代码:

以上代码是:static int suspend_enter(suspend_state_t state, bool *wakeup)

以上代码是:int suspend_devices_and_enter(suspend_state_t state)
以上代码是:static int suspend_enter(suspend_state_t state, bool *wakeup)

2、初步分析的关键log:

按下power key时:

03-03 10:35:07.119074   795   845 D WindowManager: interceptKeyTq: result=2 keycode=26 screenIsOn=false keyguardActive=true policyFlags = #2000001 down =true canceled = false isWakeKey=true mVolumeDownKeyTriggered =false mVolumeUpKeyTriggered =false

通知上层时:

03-03 10:35:07.121838   795   844 D PowerManagerService: userActivityFromNative

03-03 10:35:07.121887   795   844 D PowerManagerService: userActivityNoUpdateLocked: eventTime=45028174, event=1, flags=0x0, uid=1000

点亮button light时:

03-03 10:35:07.122567   795   844 I PowerManagerService: setBrightness mButtonLight, screenBrightness=102

抬起power key时:

03-03 10:35:07.122476   795   845 D WindowManager: interceptKeyTq: result=1 keycode=26 screenIsOn=true keyguardActive=true policyFlags = #2000001 down =false canceled = false isWakeKey=true mVolumeDownKeyTriggered =false mVolumeUpKeyTriggered =false

异常的长按事件(正常的是在按下不抬起超过500ms才会产生):

03-03 10:35:07.123281   795   844 D WindowManager: interceptKeyTi keyCode=26 down=true repeatCount=1 keyguardOn=true mHomePressed=false canceled=false metaState:0

3、进一步分析的关键log:

用户空间获取到power key的过程以及时间戳

InputReadereventhub:{{{{{{{{{{{{{{{{{{{{{{{{{{{{{{

03-05 14:55:49.518601   766   861 D InputReader: vincent loopOnce now=450968789025

03-05 14:55:52.140518   766   861 E EventHub: /dev/input/event0 got: time=451.959992power key产生的时间), type=1, code=116, value=1

03-05 14:55:52.140590   766   861 E EventHub: /dev/input/event0 got: time=452.184186, type=1, code=116, value=0

452.184186-451.959992=0.224194

03-05 14:55:52.140840   766   861 D InputReader: vincent after getEvents now=452609428487(获取到power key的时间)

03-05 14:55:52.141047   766   861 D InputReader: vincent notifyKey - eventTime=451959992000, deviceId=7, source=0x101, policyFlags=0x1, action=0x0, flags=0x8, keyCode=0x1a, scanCode=0x74, metaState=0x0, downTime=451959992000

03-05 14:55:52.162639   766   860 D InputDispatcher: vincent dispatchOnceInnerLocked,currentTime=452631225948,nextRepeatTime=452459992000(应该产生repeat的时间,已经小于获取到power key的时间)

}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}

Kernel 空间处理power key的过程

kernel process power key:{{{{{{{{{{{{{{{{{{{{{{{{{{

<4>[  451.708947] (2)[70:kworker/u8:1]Freezing user space processes ...

<6>[  451.712100] (2)[70:kworker/u8:1]last active wakeup source: pmicAuxadc irq wakelock

<4>[  451.712114] (2)[70:kworker/u8:1]

<3>[  451.712129] (2)[70:kworker/u8:1]Freezing of tasks aborted after 0.003 seconds (59 tasks refusing to freeze, wq_busy=0):

<4>[  451.712139] (2)[70:kworker/u8:1]

<4>[  451.712148] (2)[70:kworker/u8:1]Restarting tasks ... done.

<5>[  451.985808]-0)[Power/PMIC] [mt_pmic_eint_irq_mt6325] receiveinterruptpower key的按键中断产生的时间)

<5>[  451.985974] 0)[Power/PMIC] [pwrkey_int_handler] Press pwrkey

<4>[  451.985979] 0)kpd: Power Key generate, pressed=1

<4>[  451.986271] 0)kpd: (pressed) HW keycode =116 using PMIC

<6>[  451.988072] 0)Enabling non-boot CPUs ...

<2>[  451.988413] 0)Boot slave CPU(启动从cpu

<4>[  451.988622]-1)CPU1: Booted secondary processor

<4>[  451.988628]-1)[Power/hotplug] platform_secondary_init, cpu: 1

<4>[  451.990119] 0)[wdk]bind kicker thread[132] to cpu[1]

Resume sdcard:{{{{{{{{{{{{{{{{{{{

<7>[  452.012297] 0)[2] bus device_resume

<7>[  452.012302] 0)dev->driver->name=mtk-msdc

<6>[  452.012321]-0)[Power/clkmgr] [clkmux_enable_op]: mux->name=MUX_MSDC30_1

<3>[  452.012376] 0)msdc1 -> PM Resume(开始resume sdcard)

<5>[ 452.096177] 0)[Power/cpufreq] _calc_new_opp_idx(): for early suspend, idx = 3

<3>[  452.306899] 0)msdc1 -> !!! Set<300KHz> Source<200000KHz> -> sclk<299KHz> state<0> mode<0> div<167> hs400_src<0>

452.306899-452.096177≈210ms

<6>[  452.308569] 0)[Power/PMIC] [pmic_ldo_enable] Receive powerId 11, action is 1

<4>[  452.318583] 0)[msdc_set_mclk] hz = 260000

<5>[  452.326109] 0)[Power/cpufreq] _calc_new_opp_idx(): for early suspend, idx = 3

<5>[  452.346192] 0)[Power/cpufreq] _calc_new_opp_idx(): for early suspend, idx = 3

<5>[  452.406189] 0)[Power/cpufreq] _calc_new_opp_idx(): for early suspend, idx = 3

<5>[  452.426088] 0)[Power/cpufreq] _calc_new_opp_idx(): for early suspend, idx = 3

<3>[  452.474040] 0)msdc1 -> !!! Set<260KHz> Source<200000KHz> -> sclk<259KHz> state<0> mode<0> div<193> hs400_src<0>[msdc_set_mclk] hz = 299401

<5>[  452.476821] 0)[Power/cpufreq] _calc_new_opp_idx(): for early suspend, idx = 3

<3>[  452.479275] 0)msdc1 -> !!! Set<299KHz> Source<200000KHz> -> sclk<297KHz> state<0> mode<0> div<168> hs400_src<0>[msdc_set_mclk] hz = 300000

<3>[  452.481533] 0)msdc1 -> !!! Set<300KHz> Source<200000KHz> -> sclk<299KHz> state<0> mode<0> div<167> hs400_src<0>

<4>[  452.483992] 0)msdc1 select card<0x59b40000>

<4>[  452.483994] 0)msdc status[16] & 0xF = 0x4 bus_speed = 0x4

<4>[  452.484003] 0)[msdc_set_mclk] hz = 300000

<3>[  452.484146] 0)msdc1 -> !!! Set<300KHz> Source<200000KHz> -> sclk<299KHz> state<1> mode<2> div<83> hs400_src<0>[msdc_set_mclk] hz = 50000000

<3>[  452.484223] 0)msdc1 -> !!! Set<50000KHz> Source<200000KHz> -> sclk<50000KHz> state<1> mode<2> div<0> hs400_src<0>

452.484223-452.318583170ms

170ms+210ms=380ms,有关resume sdcard 的处理大概花费380ms

}}}}}}}}}}}}}}}}}}}}}}}}

<7>[  452.484942] 0)dev->driver->name=mtk-kpd

<4>[  452.484953] 0)kpd: kpd_early_suspend wake up source resume!! (0)

<4>[  452.484958] 0)kpd: enable kpd work!

<4>[  452.484963] 0)kpd: KEYPAD is enabled

<4>[  452.484967] 0)kpd: resume!! (0)

<4>[  452.632297] (0)[70:kworker/u8:1]Restarting tasks ... done.->>>>>2015-03-05 06:55:52.137685 UTC

(开始唤醒用户空间的进程,包括inputreader)

452.632297-451.985808650ms

整个系统resume的过程花费了大概650ms

<6>[  452.641290] (0)[70:kworker/u8:1]PM: suspend exit 2015-03-05 06:55:52.146678077 UTC

}}}}}}}}}}}}}}}}}}}}}}}


#analyzed by vincent.song from SWD2 Framework team.

#vincent.song@tcl.com

#201503171631

版权声明:本文为博主原创文章,未经博主允许不得转载。

0
0

查看评论
* 以上用户言论只代表其个人观点,不代表CSDN网站的观点或立场
    个人资料
    • 访问:815859次
    • 积分:11385
    • 等级:
    • 排名:第1377名
    • 原创:303篇
    • 转载:183篇
    • 译文:11篇
    • 评论:153条
    最新评论