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

转载一篇，分析的不错！

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：MT6732Android版本：4.4.4KKBuildType：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以及对应代码逻辑，发现Powerkey在分发时的状态出现了问题，最终导致处理流程异常。下一步行动：因为log中没有足够的信息来确认代码的执行流程，所以需要添加log再进一步确认问题并输出解决方案。问题原理：正常情况下：1、Powerkey只有长按超过500ms才会通知上层点亮buttonlight，其他按下power key的情况都不会点亮buttonlight。2、Powerkey短按经过预处理之后不会传递给上层，同样也不会点亮button light。当前出问题的异常情况：1、powerkey 在正常短按的时候通知上层点亮了button light，同时产生了异常的长按事件

四、问题进一步分析

进一步定义问题现象：在插入sdcard的情况下，很大概率出现按下powerkey会点亮button light，然后再亮LCD，给用户的直接感觉就是卡顿一下。进一步的分析结果：插入sdcard出现问题的情况下：从powerkey按下到用户空间接收到，花费了超过500ms的时间，导致inputdispatcher认为产生了长按事件，从而走了点亮buttonlight的流程。不插入sdcard的正常情况下：从powerkey按下到用户空间接收到，花费200ms左右的时间，inputdispatcher认为是正常短按，不会走点亮buttonlight的流程。已知的问题原因：从有问题的kernellog中看到power key 的中断产生，到唤醒用户空间进程，中间已经花费超过500ms，通过进一步分析发现，这超过500ms的时间都花在了resume系统的过程中，包括resume各种器件的driver以及从cpu，其中就包括sdcard，与此同时，从log中还可以看出，在resumesdcard的时候，其log的时间间隔都比较长，处理过程花费了比较久的时间，加起来大概380ms。对比没有问题的kernellog，没有与resume sdcard相关的log信息打出，也没有花费比较久时间的处理log打出。未知的问题原因：为何按下powerkey 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左右，这个时间就是你先看到buttonlight亮之后，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：按下powerkey时：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: userActivityFromNative03-03 10:35:07.121887   795   844 D PowerManagerService: userActivityNoUpdateLocked:eventTime=45028174, event=1, flags=0x0, uid=1000点亮buttonlight时：03-03 10:35:07.122567  795   844 I PowerManagerService: setBrightness mButtonLight, screenBrightness=102抬起powerkey时：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:03、进一步分析的关键log：用户空间获取到powerkey的过程以及时间戳：InputReader（eventhub）:{{{{{{{{{{{{{{{{{{{{{{{{{{{{{{03-05 14:55:49.518601   766   861 D InputReader: vincent loopOnce now=45096878902503-05 14:55:52.140518   766   861 E EventHub: /dev/input/event0 got: time=451.959992（powerkey产生的时间）, type=1, code=116, value=103-05 14:55:52.140590   766   861 E EventHub: /dev/input/event0 got: time=452.184186,type=1, code=116, value=0452.184186-451.959992=0.22419403-05 14:55:52.140840   766   861 D InputReader: vincent after getEventsnow=452609428487（获取到powerkey的时间）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=45195999200003-05 14:55:52.162639   766   860 D InputDispatcher: vincent dispatchOnceInnerLocked,currentTime=452631225948,nextRepeatTime=452459992000（应该产生repeat的时间，已经小于获取到powerkey的时间）}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}Kernel 空间处理powerkey的过程：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: pmicAuxadcirq wakelock<4>[  451.712114] (2)[70:kworker/u8:1]<3>[  451.712129] (2)[70:kworker/u8:1]Freezing of tasks aborted after 0.003seconds (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] receiveinterrupt（powerkey的按键中断产生的时间）<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)Enablingnon-boot CPUs ...<2>[  451.988413] 0)Bootslave 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, actionis 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.318583≈170ms170ms+210ms=380ms，有关resumesdcard 的处理大概花费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: KEYPADis enabled<4>[  452.484967] 0)kpd:resume!! (0)<4>[  452.632297](0)[70:kworker/u8:1]Restarting tasks ... done.->>>>>2015-03-0506:55:52.137685 UTC(开始唤醒用户空间的进程，包括inputreader)452.632297-451.985808≈650ms整个系统resume的过程花费了大概650ms<6>[  452.641290] (0)[70:kworker/u8:1]PM: suspend exit 2015-03-05 06:55:52.146678077UTC}}}}}}}}}}}}}}}}}}}}}}}#analyzed by vincent.song from SWD2 Framework team.#vincent.song@tcl.com#201503171631版权声明：本文为博主原创文章，未经博主允许不得转载。