恢复出厂设置 卡住10分钟问题
文章目录
1. 信息初步收集
1.1 现象描述
- 恢复出厂设置操作;
- 重启进入recovery 清除data/cache分区;
- 概率性出现卡住10分钟后再次启动的情况;
1.2 问题概率以及实验情况确认
- 反复进行恢复出厂设置动作,约半天出现一次;
- 仅有一台机器出现此case;
- recovery log没有抓取到;
- 正常进行recovery基本在1分钟左右;
2. 分析过程
从反馈现象分析存在两种可能性:
- recovery 逻辑中存在case,卡在某个逻辑中无法退出;
- 上述recovery逻辑主要为清除data分区内容,则可能在写emmc操作时出现问题卡住;
则需要log信息来进一步证实上述猜测情况;
2.1 确认recovery log信息情况
当前机器中未保存recovery log,而分析问题需要该部分log信息,但是无法确认为个例问题还是普遍问题,则该机器软件环境需要尽可能小的改动;
- recovery log部分会在执行时生成,但是该部分log会在recovery完成后清除掉;
- 默认recovery为单独分区,但是AB版本recovery是打包在boot.img中的,修改后需要升级boot.img
- recovery部分code:bootable/recovery/recovery.cpp,目前直接将log修改为在串口输出;
2.2 log分析
2.2.1 recovery 重启
从log中找到最后3次重启,找到对应的recovery触发重启的操作:
-
触发recovery 重启;
[ 169.275465] <0>.(0)[1:init]reboot: Restarting system with command ‘recovery’
[ 169.276568] <0>-(0)[1:init]ARCH_RESET happen!!!
[ 169.277142] <0>-(0)[1:init]arch_reset: cmd = recovery -
重启到kernel进入recovery 模块内进行清除分区操作;
-
清除结束后重启进入系统:
[ 659.341311] Data wipe complete.
…
[ 659.383821] Rebooting…
[ 661.897156] <1>.(1)[1:init]init: Received sys.powerctl=‘reboot,’ from pid: 256 (/sbin/recovery)
[ 661.898310] <1>.(1)[1:init]init: PropSet [sys.powerctl]=[reboot,] Done
[ 661.899163] <1>.(1)[1:init]init: Clear action queue and start shutdown trigger
[ 661.900146] <1>.(1)[1:init]init: processing action (shutdown_done) from (:0)
[ 661.901214] <1>.(1)[1:init]init: Reboot start, reason: reboot, rebootTarget:
[ 661.902274] <1>.(1)[1:init]init: PropSet [persist.sys.boot.reason]=[reboot,] Done
[ 661.903366] <1>.(1)[1:init]init: Shutdown timeout: 1000 ms
从时间戳可以看得出来,recovery清除操作这次启动时间约11min,则确认问题确实出现在此次recovery 清除逻辑;
2.2.2 recovery 清除操作
则分析这次数据清除逻辑,发现如下信息:
- kernel进入后30s左右提示emmc 写异常,device端没有回复信息,超时;
- 中间经过10分钟的系统调度;
- 最终emmc reset 恢复后recovery快速进行完重启
2.2.2.1 block 进入逻辑:
[ 37.859926] <1>.(0)[210:kworker/0:2][msdc][msdc_check_data_timeout]: XXX DMA Data Busy Timeout: 30000 ms, CMD<25>
[ 37.859919] <1>.(0)[210:kworker/0:2][msdc]Accumulated dma cnt: 23
[ 37.880459] <1>.(0)[210:kworker/0:2][msdc]msdc0 -> check card state<6> <- msdc_check_data_timeout() : L<4764> PID<kworker/0:2><0xd2>
[ 37.880465] <1>.(0)[210:kworker/0:2][msdc]msdc0 -> state<6> need cmd12 to stop <- msdc_check_data_timeout() : L<4766> PID<kworker/0:2><0xd2>
[ 60.250439] <0>.(0)[210:kworker/0:2][msdc][msdc_command_resp_polling]: msdc0 CMD<12> MSDC_INT_CMDTMO Arg<0x00000000>
[ 60.251914] <0>.(0)[210:kworker/0:2][msdc][msdc_command_resp_polling]: msdc0 CMD<12> Arg<0x00000000> tmo: 21474ms (max 21474ms)
[ 60.253356] <0>.(0)[210:kworker/0:2][msdc]msdc0 -> card stuck in 6 state <- msdc_check_data_timeout() : L<4777> PID<kworker/0:2><0xd2>