前言

这个问题由来已久,一直搁着没看,它在官方系统+官方内核上同样发生,导致一加的865设备的数据流量下的待机续航普遍较差,idle drain高达4%-5%/h,这显然是无法接受的。今天决定了要把这个问题瞧一瞧,一瞧就是半个下午+一个晚上。

问题描述

数据流量下待机续航极差

ss1

深度睡眠时间极少
(截图来自官方内核)

日志排查

dmesg中存在大量类似这样的日志

[  750.094062] PM: Device alarmtimer failed to suspend: error -16
[  750.094065] PM: Some devices failed to suspend, or early wake event detected
[  753.496178] active wakeup source: alarmtimer
[  756.421102] active wakeup source: alarmtimer
[  757.386560] active wakeup source: alarmtimer
[  760.735522] active wakeup source: alarmtimer
[  763.220499] active wakeup source: alarmtimer
[  764.955187] active wakeup source: alarmtimer
[  767.227574] active wakeup source: alarmtimer
[  769.694145] active wakeup source: alarmtimer
[  771.424980] active wakeup source: alarmtimer
[  773.686699] active wakeup source: alarmtimer
[  775.367871] pm_system_irq_wakeup: 351 triggered pm8xxx_rtc_alarm

另外再附上一张来自官方内核的日志截图

ss2

非常类似

源码排查

alarmtimer 来自 kernel/time/alarmtimer.c ,这是一个负责定时器的核心驱动,Android系统层的AlarmManager就是由它在内核层实现的

这个驱动能发生问题就很神奇,首先,确定阻止唤醒的原因

排查一 为什么它阻止了休眠?

经过一次测试,马上锁定了问题的发生点

static int alarmtimer_suspend(struct device *dev)
{
        ..............
    if (ktime_to_ns(min) < 2 * NSEC_PER_SEC) {
        __pm_wakeup_event(ws, 2 * MSEC_PER_SEC);
        return -EBUSY;
    }
        ..............
}

错误代码-16就是在这里返回的,可以看到在这里跳出的条件是ktime_to_ns(min) < 2 * NSEC_PER_SEC,结合上下文可知此处是判断下一个定时器的发生时间如果在两秒以内,则阻止休眠(就休眠这两秒没什么用,而且可能导致问题(比如rtc时钟未即时响应导致下一次唤醒时间被设置在休眠时间之前了))

我也尝试了移除这段代码,原来的难以休眠变为了诡异的休眠一点点时间(大概一秒)就唤醒,循环进行

排查二 诡异的定时器哪里来?

定时器创建函数 alarmtimer_enqueue

static void alarmtimer_enqueue(struct alarm_base *base, struct alarm *alarm)
{
    if (alarm->state & ALARMTIMER_STATE_ENQUEUED)
        timerqueue_del(&base->timerqueue, &alarm->node);

    timerqueue_add(&base->timerqueue, &alarm->node);
    alarm->state |= ALARMTIMER_STATE_ENQUEUED;
}

我尝试在里面打印出current->comm从而显示执行这段代码的任务
通过比较wifi下与数据流量下的定时器日志,我发现主要区别来自一大堆kworker/xx的进程
(排除了来自用户空间的可能性,反而是松了一口气,因为一加的用户空间脏的不行 + 现在的动态分区 使得修改用户空间变得非常困难)
而很明显,我无法直接追踪这些kworker到底是哪里的
于是我尝试使用工具调试

perf 工具

我尝试使用perf record -g -a sleep 10记录了10秒内的系统活动情况
然后通过perf report打印出来

遗憾的是,没有什么有用的东西(主要是特征不是很明显,现在找到了问题再去回看日志,确实是能找到对应函数的痕迹的)

定时器激活函数 alarmtimer_fired

static enum hrtimer_restart alarmtimer_fired(struct hrtimer *timer)
{
    struct alarm *alarm = container_of(timer, struct alarm, timer);
    struct alarm_base *base = &alarm_bases[alarm->type];
    unsigned long flags;
    int ret = HRTIMER_NORESTART;
    int restart = ALARMTIMER_NORESTART;

    spin_lock_irqsave(&base->lock, flags);
    alarmtimer_dequeue(base, alarm);
    spin_unlock_irqrestore(&base->lock, flags);

    if (alarm->function)
        restart = alarm->function(alarm, base->gettime());

    spin_lock_irqsave(&base->lock, flags);
    if (restart != ALARMTIMER_NORESTART) {
        hrtimer_set_expires(&alarm->timer, alarm->node.expires);
        alarmtimer_enqueue(base, alarm);
        ret = HRTIMER_RESTART;
    }
    spin_unlock_irqrestore(&base->lock, flags);

    trace_alarmtimer_fired(alarm, base->gettime());
    return ret;

}

这个函数在定时器激活时被调用,其中有一个回调函数用于确定定时器是否应该被再次设定
这里似乎是可以得到线索的
我使用pr_err("%pF", 函数名)的方式从函数指针alarm->function还原出了函数名
它指向了函数qmi_rmnet_work_alarm
而在这里我也发现了定时器的调用频率超乎想象,每秒就有一次定时器激活(这直接解释了上面对于休眠的观察),这在打开wifi后会立即消失,而再启用流量后又会再次出现

它又发生了什么?

于是通过函数名我顺利的定位到了问题,来自drivers/soc/qcom/qmi_rmnet.c

结合上下文我发现函数qmi_rmnet_check_statsrmnet_work_quit==false的情况下就会不断通过开启延迟为1s的alarm执行自己,而这正是造成这个问题的原因

于是我进行了一些临时的修复

首先是Revert这个提交
这个提交将原来的workqueue换成了alarm,按提交里的意思是这样唤醒更精确,更省电,但是不知道为什么rmnet_work_quit始终没有被设为true,导致alarm持续唤醒,反而造成了巨量的耗电

其次是为工作队列加上unbound和freezable的flag来尽可能降低对功耗的影响

一点额外调查

我尝试弄清rmnet_work_quit的值在何时会发生改变
很遗憾
只有这唯一一条日志

[  311.346071] libxzr: rmnet_work_quit=false

它就没有被设为true过

暂且不知道这bug应该甩锅给谁,一加还是高通?但是我的代码来自CAF rebase,问题却依然在发生。。嗯?
又是帮厂商擦屁股的一天

解决后的效果 正常了很多
ss3