Android 能记录 关机了多长时间吗 安卓查看关机记录

异常现象：

高通8937平台手机执行开关机压力测试出现概率性无法关机，平均复现概率为1/400次， 问题出现时手机黑屏，看上去像死机，但充电灯在亮着.

分析：

拿到机器发现adb还可以使用，那既然adb还可以用，说明系统并没有发生kernel panic，只是由于某种原因导致关机Thread发生了stuck，跟死锁的现象有点像，问题是概率发生并且概率比较低，能想到比较合适的分析方法就是在关机流程中加trace记录下整个流程，看到底卡在了哪里，缩小代码分析范围。 这里有一个问题:为什么卡住了，wdt不会去复位呢？开始我也没明白，后面才发现，是卡在device_unlock函数被调度走了，不是在spinlock内，喂狗线程还在正常运行，所以也就不会wdt time out 了.

Debug 难点：

1、Android层关机流程走完后会把filesystem设为read only，所以内置log工具只能抓到Android 层的log，对于kernel层log需要使用uart 飞线抓取，但是问题复现是概率很低的，通常需要跑一个晚上才可能复现，所以也就是说必须要一直连着uart 工具，直到问题复现才有可能抓到浮现时候的klog.

2、虽然用uart抓很麻烦，但是终究是一种方法，遗憾的是，加了log后问题出现概率大大降低，从1/400降低到< 1/1500，再次提升了复现问题的难度，而且打开uart 输出后测试8*2000次无复现！如果无法复现的话，基本上是无解的，目前考虑的这种方法抓log失败了,只能想另外的方法途径。

w同学建议可以尝试在kernel关机流程函数加计数器(下面代码红色部分)追踪，浮现问题后，用adb把计数器值拉出来看(丰富debug手段多么重要！)，因为计数器只是赋值语句，相比log的时间开销来说很小的，这样可以大大增加复现概率！经过一晚上的压力测试，发现果然有效果，定位到thread卡在kernel关机流程的 device_shutdown() 函数.

void device_shutdown(void)
{
	struct device *dev, *parent;

	spin_lock(&devices_kset->list_lock);
	/*
	 * Walk the devices list backward, shutting down each in turn.
	 * Beware that device unplug events may also start pulling
	 * devices offline, even as the system is shutting down.
	 */
	while (!list_empty(&devices_kset->list)) {
		dev = list_entry(devices_kset->list.prev, struct device,
				kobj.entry);
				
                dev_p = dev->kobj.name;

		/*
		 * hold reference count of device's parent to
		 * prevent it from being freed because parent's
		 * lock is to be held
		 */
		parent = get_device(dev->parent);
		get_device(dev);
		/*
		 * Make sure the device is off the kset list, in the
		 * event that dev->*->shutdown() doesn't remove it.
		 */
		list_del_init(&dev->kobj.entry);
		spin_unlock(&devices_kset->list_lock);

                flag1++;

		/* hold lock to avoid race with probe/release */
		if (parent)
			device_lock(parent);
		device_lock(dev);

                flag2++;
        
		/* Don't allow any more runtime suspends */
		pm_runtime_get_noresume(dev);
		pm_runtime_barrier(dev);
		
                flag3++;
        
		if (dev->bus && dev->bus->shutdown) {
			if (initcall_debug)
				dev_info(dev, "shutdown\n");
			dev->bus->shutdown(dev);
		} else if (dev->driver && dev->driver->shutdown) {
			if (initcall_debug)
				dev_info(dev, "shutdown\n");
			dev->driver->shutdown(dev);
		}

		device_unlock(dev);
		if (parent)
			device_unlock(parent);

		put_device(dev);
		put_device(parent);

                flag4++;

		spin_lock(&devices_kset->list_lock);
	}
	spin_unlock(&devices_kset->list_lock);
}

激活pm runtime，依次删除掉，然后执行各个dev对关机动作感兴趣的shutdown回调函数.

第一晚的测试只是定位到了具体位置，后面还需要进一步定位具体卡在那一句代码上，经过w同学的反复努力，终于抓到卡住的如下具体代码位置，就是flag1 和 flag2之间，而此时dev_p是bam_dumx_ch_0.2，好像跟rmnet有关，这是属于qcom私有的东西，具体不知干什么用的...

if (parent)
    device_lock(parent);
device_lock(dev);

卡住的地方很诡异，看上去像死锁... 前面费了很大力气抓到了卡住的具体代码，目的是想知道事故现场的具体情况，以及给高通提供最精确的信息，但是目前看到这段貌似死锁的代码也无法进一步分析为什么会这样？按道理如果是单线程就不应该会出现卡在lock上, java层关机会发一个shutdown广播，难道还有别的内核线程也在执行dev的操作导致死锁？猜想根本原因是还有其他的路径再执行设备卸载操作，由于某种原因导致卸载失败又没有释放lock，所以当device shutdown的时候再次去获取lock就导致死锁了...已经抓ramdump给高通（若是能自己分析ramdump就多一个debug手段了），希望他们可以离线分析出root cause，遗憾的是，到目前为止，现在还没有有价值的分析结果...

到这里为止，以现有的知识积累跟调试手段已经无法再进一步分析根本原因，但问题还得解决，既然直的来不了，就只能想办法来弯的，想办法绕过去，有两种思路：

1、既然加log难以浮现，可以尝试在loop中加mdelay的方式，看是否可以解决问题，此法改动风险最小，但是被动而且运气成分高，不够可靠.

2、新开一个内核线程用于监视device_shutdown函数是否卡住，如果这个函数执行时间超过 5s（正常不到1s跑完），那么就认为已经被stuck，就执行强制restart，有点类似于给这个函数加了一个wdt...此法主动出击，应该比上一种方法可靠，但是改动相对大风险高，而且简单粗暴，在目前这种山穷水尽也没有其它更好的办法的情况下, 只能背水一战赌一把了.

经过大量的压力测试发现，上面的NO.1方法最终没有扛住10*5000次的压力测试，加delay降低了复现概率，但是大量长时间的压力测试时候还是会出现。NO.2方法还在验证中...

下面简单介绍下NO.2的实现方式：

简单流程图：

1、新建一个内核线程，当作device_shutdown的监视器：

static int sd_counter = 0;
static struct task_struct *sd_thd = NULL;

static void start_monitor_kthread(void)
{
    sd_counter = 0;
    sd_thd = kthread_run(ds_monitor_thd, NULL, "ds_m_thd");
    if (IS_ERR(sd_thd)) {
        pr_emerg("xxx# %s: -%d create fail!\n", __func__, __LINE__);
        sd_thd = NULL;
    }
}

线程回调入口，起一个while(1)循环，如果5s后sd_counter计数器没清零就执行强制reboot.

static int ds_monitor_thd(void *args) 
{    	 
    do {
         mdelay(5000);
         if(sd_counter > 0) {
            pr_emerg("xxx# %s: Oops! force shutdown or reboot ! sd_counter:%d\n", __func__, sd_counter);
            force_reboot();
            break;
        }
    } while(1);
	
    return 0;
}

2、强制重启force_reboot的实现，其实只要执行machine_xxx就行了，这样的做法只是为了尽量按原有代码路径执行.

void force_reboot(void)
{
    char *cmd = reboot_cmd_buf;
    
    //原有关机流程中的动作，这里保留,以达到影响最小.
    migrate_to_reboot_cpu();
    syscore_shutdown();
    
    pr_emerg("xxx# %s: -%d-machine goto restart or shutdown!:%s\n", __func__, __LINE__, cmd);
    
    //判断是reboot还是shutdonw，执行不同的操作.
    if(reboot_cmd == LINUX_REBOOT_CMD_RESTART2 
    || reboot_cmd == LINUX_REBOOT_CMD_RESTART) {
        machine_restart(cmd);
    }
    else {
        machine_power_off();
    }
}

3、在device_shutdown()中启动该线程，同时加上计数器：

void device_shutdown(void)
{
	struct device *dev, *parent;

	start_monitor_kthread(); //启动监视线程
...
	while (!list_empty(&devices_kset->list)) {
...
		sd_counter++; //计数器++
...
	}
	spin_unlock(&devices_kset->list_lock);

	sd_counter = 0; //说明该函数跑完了，计数器清零.
}

从上面代码可以得出，如果device_shutdown函数在5s内没有执行完成导致sd_counter计数器没有被清零，则ds_m_thd 线程会进入force_reboot,强制系统重启或者关机，以达到不卡住的问题出现，因为正常情况下device_shutdown会在1s内执行完成，所以正常情况下新加的监视线程也就没有影响了，有点类似是给这个函数单独加了一个watch dog，规定时间没喂狗就被狗咬..