恢复出厂设置卡住10分钟问题

文章目录

恢复出厂设置卡住10分钟问题
- 1. 信息初步收集
- - 1.1 现象描述
  - 1.2 问题概率以及实验情况确认
- 2. 分析过程
- - 2.1 确认recovery log信息情况
  - 2.2 log分析
  - - 2.2.1 recovery 重启
    - 2.2.2 recovery 清除操作
    - - 2.2.2.1 block 进入逻辑：
      - 2.2.2.2 中间调度逻辑：
      - 2.2.2.3 block 退出逻辑
- 3. 问题原因以及处理
- - 3.1 原因
  - 3.2 处理
  - 3.3 记录
- 4. 涉及模块
- - 4.1 mmc子系统架构
  - 4.2 调度策略处理

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：

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；

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中的核心处理，，提供三部分功能：
1. 提供给到上层card通用接口（mmc、sdio、sd）
2. 注册mmc bus并实现主要逻辑
3. 与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_boostedif (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结束的时候，再将其放入调度队列中；