恢复出厂设置 卡住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>
-
msdc_check_data_timeout 这个是在host driver中进行的超时检测,即一次DMA传输如果超过30s还未结束,则会调用到这里判断当前device状态
- cmd 25在emmc 5.1协议中规定为write操作;
- DMA传输的超时时间为30s;
- msdc_check_data_timeout这里循环check 状态的超时时间为3s
-
这里还有一个点需要说明,此问题一共抓取到两次log信息,两次读取到的device state不一样,即emmc端出现busy不回复,但是可能出现的时机点不同;
[ 33.763743] [msdc][msdc_check_data_timeout]: XXX DMA Data Busy Timeout: 30000 ms, CMD<25>
[ 33.764762] <2>.(2)[44:kworker/2:1][msdc]Accumulated dma cnt: 19
(200723_15:29:52.380)[ 33.863329] <2>.(2)[44:kworker/2:1][msdc]msdc0 -> check card state<7> <- msdc_check_data_timeout() : L<4764> PID<kworker/2:1><0x2c>
(200723_15:29:52.392)[ 33.864811] <2>.(2)[44:kworker/2:1][msdc]msdc0 -> state<7> card is busy <- msdc_check_data_timeout() : L<4769> PID<kworker/2:1><0x2c>
这里只是host端的超时检测,这里执行结束后会将err状态反馈给到card driver中,后续即card driver中的处理;
2.2.2.2 中间调度逻辑:
[ 599.411728] <1>-(3)[225:mmcqd/0][name:rt&]sched: initial rt_time 1243084, start at 598459789580
[ 599.411739] <1>-(3)[225:mmcqd/0][name:rt&]sched: cpu=3 rt_time 952958009 <-> runtime[950000000 -> 950000000]
[ 599.411737] <1>-(3)[225:mmcqd/0]exec_task[225: mmcqd/0] prio:98 exec_delta[3998461] clock[599411723813] exec_start[599407725352]
[ 599.411742] <1>-(3)[225:mmcqd/0][name:rt&]sched: update[599407725352, 599407725582] pick[598460008888, 598460013119] set_curr[1051524079, 1051526079]
[ 599.411747] <1>-(3)[225:mmcqd/0]sched: RT throttling activated for rt_rq ffffffe37ff55c58 (cpu 3)
[ 599.411747] <1>potential CPU hogs:
[ 599.411747] <1> mmcqd/0 (225)
[ 599.459797] <0>-(0)[0:swapper/0][name:rt&]sched: cpu=3, [952992317 -> 2992317] -= min(952992317, 1*[950000000 -> 950000000])
[ 599.459805] <0>-(0)[0:swapper/0][name:rt&]sched: RT throttling inactivated cpu=3
- 这部分打印是在RT Task调度逻辑中添加的:
- sched_rt_runtime_exceeded
- print_rt_throttle_info(上述1~4)
- dump_throttled_rt_tasks(上述5~7)
- 系统存在一个RT Task一直在执行(exec_task[225: mmcqd/0] prio:98),由于执行时间过久,所以每次超过0.95s后系统对其进行调度,避免其他Task无法执行到;
- rt_bandwidth ,这里在sched_init的时候初始化bandwidth为0.95s;
- 从这里来看,说明Task mmcqd一直进行了10min左右未完成,从这个task的名称即可发现这个与emmc强相关
- 源码中搜索这个mmcqd是在queue.c中启动的thread(function:mmc_init_queue中进行),这东西是card driver中的内容;
从这里的调度逻辑可以看到,host driver中返回的异常状态,并没有触发card driver中对device端的重置动作;
而且每次出现问题都是10分钟左右,则有理由怀疑在card driver中也存在一个check机制,超时时间为10min:
- 源码中搜索这个mmcqd是在queue.c中启动的thread(function:mmc_init_queue中进行),这东西是card driver中的内容;
2.2.2.3 block 退出逻辑
幸运的是我们抓取到一次完整10分钟后退出的log信息,则可以针对性的来看下是在哪里退出的:
[ 660.255734] <1>.(1)[225:mmcqd/0]mmc0: Card stuck in programming state! mmcblk0 card_busy_detect
[ 660.257011] <1>.(1)[225:mmcqd/0][msdc]msdc0 -> !!! Set<400KHz> Source<400000KHz> -> sclk<400KHz> timing<10> mode<3> div<125> hs400_div_dis<0>
- card_busy_detect 即在card driver这里做的检测,这里的超时时间是传入的;
- 这个函数跟host端那个处理基本完全一致,检测device端的状态,然后设置一个超时时间,超时后退出;
- 则从这里来看,上述整个过程都已经可以解释通了,那么问题就是这个超时时间是哪里设置的;
- 这个函数有两个调用位置:
- send_stop时调用,有三个调用位置:
- 每个调用都有log打印,而从我们的打印信息中没有相关信息;
- 传入超时时间均为1s中,则也不相符;
- mmc_blk_err_check,这个调用位置有很多
- 超时时间为:MMC_BLK_TIMEOUT_MS = 10 * 60 * 1000 即 10min
- 则整个path我们串通了,在blk驱动中有配置err check机制,且在这里配置时间为10min;
- 调用逻辑:
- mmc_blk_packed_err_check
- mqrq->mmc_active.err_check = mmc_blk_err_check;
- mqrq->mmc_active.err_check = mmc_blk_packed_err_check;
- send_stop时调用,有三个调用位置:
3. 问题原因以及处理
3.1 原因
- root cause:emmc device端状态不对,在write操作时状态一直没有转变为tran模式,而是PRG、RCV;
- mmc 子系统中分别在host driver和card driver中都有做err check以及超时检测处理,出现异常状态超时后会进行reset恢复;
3.2 处理
- 修改mmc block driver中的超时时间设置,缩短为1min,但是这个是标准linux kernel驱动,可能会有未知风险;
- 对于此问题目前仅有一台机复测到,有可能为该机通信情况异常导致,且后续复测其他机器并无此问题;
- 对于此项目中emmc用料,存在多个型号,后续对此型号持续关注;
3.3 记录
这个问题分析还算比较顺畅,打印信息中基本可以定位到问题点,分析过程中还是遇到了如下问题:
- 由于此问题为recovery逻辑触发,分析过程中在未找到block退出逻辑之前也有跟踪recovery中过程,未发现block点,但是耗费了比较多的时间;
- block 退出逻辑这个逻辑从host端往上分析则比较麻烦,很难反向找到,需要对于整个mmc 系统框架有一定了解;
4. 涉及模块
4.1 mmc子系统架构
对于此问题的分析,涉及到了linux mmc 子系统的框架理解:
这个是以前画的一张图:即mmc中划分为三个层次:
- user层,即card driver或者wifi driver 等使用到sdio通信的实际应用;
- core层,mmc中的核心处理,,提供三部分功能:
- 提供给到上层card通用接口(mmc、sdio、sd)
- 注册mmc bus并实现主要逻辑
- 与host driver进行通信(mmc_host实现)
- HW层, 最终将上层操作转换为底层通信cmd和data的层次,即SOC中的IP驱动,主要实现最底层的内容;
所以针对于此问题我们找到了mmc子系统中两个层次的超时检测,即card 和 host
4.2 调度策略处理
在卡住的10min中可以看到每秒都会打印一次上述sched的信息,而此就是CPU带宽限制的调度信息:
- 实时任务的优先级高于普通任务,为了防止cpu消耗型的实时任务一直占用cpu引发其他任务"饥饿"的情况发生,内核采用了带宽限制手段来抑制实时任务的运行时间,保证其他普通Task的调度。
- 在任务调度中带宽限制就是指一定周期内一个队列(CPU)上任务可运行的最大时间,内核中使用xxx_bandwidth结构来限制任务的运行时间。
RT_Task对应的是:
struct rt_bandwidth {
raw_spinlock_t rt_runtime_lock;
ktime_t rt_period;
u64 rt_runtime;
struct hrtimer rt_period_timer;
unsigned int rt_period_active;
};
则简单理解就是为了限制某些高优先级任务一直在运行,让其他Task没有机会得到“宠幸”机会,则设置了个限制,避免CPU被独占;
对于实时Task,使用update_curr_rt()来做更新检查:
- 计算执行时间:rt_rq->rt_time += delta_exec;
- 检测是否超标:sched_rt_runtime_exceeded(rt_rq);
- 需要受限,且时间超标,则直接出队,并且限制入队;
则核心就是:sched_rt_runtime_exceeded函数,具体来分析下:
static int sched_rt_runtime_exceeded(struct rt_rq *rt_rq)
{
u64 runtime = sched_rt_runtime(rt_rq); //这个是获取到rq中的runtime时间,即我们在sched_init中init_rt_bandwidth()初始化的时间,这里为0.95s;
if (rt_rq->rt_throttled) //这个是标志位,用于判断是否需要做带宽限制;
return rt_rq_throttled(rt_rq);//这里返回是做了个:rt_rq->rt_throttled && !rt_rq->rt_nr_boosted,即判断rt_rq->rt_nr_boosted
if (runtime >= sched_rt_period(rt_rq)) // runtime > period 则不可能发生超过限制;
return 0;
//这里做一次balance,即判断下其他的rq是否也是满负载了,否则可以“借”一些时间过来,则这个时间会发生变化,这样需要重新获取一下;
balance_runtime(rt_rq);
runtime = sched_rt_runtime(rt_rq);
if (runtime == RUNTIME_INF)
return 0;
// 这里就是实际处理了,即发现执行时间超过了规定时间;
if (rt_rq->rt_time > runtime) {
struct rt_bandwidth *rt_b = sched_rt_bandwidth(rt_rq);
/*
* Don't actually throttle groups that have no runtime assigned
* but accrue some time due to boosting.
*/
if (likely(rt_b->rt_runtime)) {//标志位设置为true,则下次进来会在函数开始退出去
rt_rq->rt_throttled = 1;
printk_deferred_once("sched: RT throttling activated\n");
} else {
/*
* In case we did anyway, make it go away,
* replenishment is a joke, since it will replenish us
* with exactly 0 ns.
*/
rt_rq->rt_time = 0;
}
if (rt_rq_throttled(rt_rq)) {
sched_rt_rq_dequeue(rt_rq);//处理即让这个task出队,这里还有一个逻辑:
//等待CPU在running的时候再重新将该Task entity入队,但是还有个限制:
// 如果group是throttled或者他是empty的情况,直接退出不enqueue;
//所以这里应该在这之后才会再次入队;
return 1;
}
}
return 0;
}
在此处处理之后,该Task已经退出了调度,而且所有入队操作其实都会检测该标志为,即该Task无法被调度了;
按照我们的猜测,一定会有个位置接触上述限制,则从逻辑上讲应该是在本次period结束的时候,再将其放入调度队列中;