一、问题现象
按下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再进一步确认问题并输出解决方案。
问题原理：
正常情况下：
1、Power key只有长按超过500ms才会通知上层点亮button light，其他按下power key的情况都不会点亮button light。
2、Power 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的过程以及时间戳：
InputReader（eventhub）:{{{{{{{{{{{{{{{{{{{{{{{{{{{{{{
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.959992（power 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] receiveinterrupt（power 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.318583≈170ms
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.985808≈650ms
整个系统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
