Hang Detect 问题

来源：互联网发布：蔡司三坐标编程编辑：程序博客网时间：2024/06/08 00:23

转载自mtk faq

一、设计背景

2. 厂家难以分析

死机问题通常是概率性问题, 在售后难以分析, 而厂家拿回机器后, 往往难以复现, 导致问题往往不了了之，或者经过很长的时间才有结论.
死机问题往往需要比较多的系统关键资讯, 默认出厂版本, 这些资讯都不会抓取, 导致分析难度很大, 非常不利于厂家场测, CTA 测试, CMCC 测试等场景.

3. 传统死机保护设计缺陷

在Google Android 系统中, 死机保护是通过watchdog 机制来达成, 即将死机转换成重启.

HW Watchdog, 用于监测CPU 执行是否异常, 启用Kernel RT thread tick HW watchdog 来达成, 如果异常, 则重启整个系统.
System Server Watchdog, 用于监测Android System Server 关键线程和资源使用是否正常, 如果异常则重启android 上层.

严重缺陷.

HW Watchdog 和 System Server Watchdog 分离执行
System Server Watchdog 依赖于底层本身稳定性, 一旦Kernel 出现异常或者Native 层异常, System Server Watchdog 本身可能卡在
System Server Watchdog 后, android 重启, System Server 可能重启fail 掉, 导致一直卡死.

……

下列场景传统设计无法达成保护：

Android 虚拟机(ART/Dalvik) 异常, 导致Java 层代码无法执行, System Server 卡死.
File System 异常, 导致System Server Watchdog 卡在, 无法重启.
Memory leaks 或者Severely fragmented, 导致System Server 无法申请到memory 而卡在Kernel 中等待memory.
Kernel Driver 异常, 比如常见的Sensor Driver 卡在, 导致System Server 卡在后变成uninterruptible, system server 无法重启成功.
Surfaceflinger 卡在, system server 重启后, 将无法重启成功.
System Server Watchdog 抓取资讯时，如果自己卡住，那么将无法重启, 持续卡死.

……

二、设计原理

1. 设计原理

基于前面的说明，我们的设计关键在于将上层的system server watchdog 以及 HW watchdog 结合起来，同时进一步对上层的关键进程监控.

2. System Server Watchdog

SystemServer Watchdog 我们简称 SSW，最开始设计只是在main looper 里面执行register 的monitor 对象的monitor 方法. 后续Google 改进，通过HandlerChecker 来达成，在HandlerChecker 中审查注入的montior 对象是否能快速执行。

即在foreground thread 来执行register 的monitor 对象，而对于其他的线程，则是审查规定时间内是否可以达到idle. 不是一直卡死在某个message 执行上.

需要注意的是, SystemServer Watchdog 启动是在SystemServer init 的后期, 如果SystemServer 在init 的过程中卡死了，那么就意味着watchdog 不会有任何的作用.

226    /**227     * The main entry point from zygote.228     */229    public static void main(String[] args) {230        new SystemServer().run();231    }233    public SystemServer() {234        // Check for factory test mode.235        mFactoryTestMode = FactoryTest.getMode();236    }238    private void run() {239        // If a device's clock is before 1970 (before 0), a lot of240        // APIs crash dealing with negative numbers, notably241        // java.io.File#setLastModified, so instead we fake it and242        // hope that time from cell towers or NTP fixes it shortly.243        if (System.currentTimeMillis() < EARLIEST_SUPPORTED_TIME) {244            Slog.w(TAG, "System clock is before 1970; setting to 1970.");245            SystemClock.setCurrentTimeMillis(EARLIEST_SUPPORTED_TIME);        .......         318        // Initialize the system context.319        createSystemContext();320321        // Create the system service manager.322        mSystemServiceManager = new SystemServiceManager(mSystemContext);323        LocalServices.addService(SystemServiceManager.class, mSystemServiceManager);324325        // Start services.326        try {327            startBootstrapServices();328            startCoreServices();329            startOtherServices();330        } catch (Throwable ex) {331            Slog.e("System", "******************************************");332            Slog.e("System", "************ Failure starting system services", ex);333            /// M: RecoveryManagerService  @{334            if (mRecoveryManagerService != null && ex instanceof RuntimeException) {335                mRecoveryManagerService.handleException((RuntimeException)ex, true);336            }337            /// @}338        }517    private void startOtherServices() {518        final Context context = mSystemContext;        .....614            mSystemServiceManager.startService(AlarmManagerService.class);615            alarm = IAlarmManager.Stub.asInterface(616                    ServiceManager.getService(Context.ALARM_SERVICE));617618            Slog.i(TAG, "Init Watchdog");619            final Watchdog watchdog = Watchdog.getInstance();620            watchdog.init(context, mActivityManagerService);        .....         1386                Watchdog.getInstance().start();        .....       }

3. surfaceflinger watchdog

Surfaceflinger Watchdog 为MTK 开发，简称其设计主要为快速检测到Surfaceflinger 是否有卡住的情况，并抓取backtrace 以便确认问题。目前其轮转周期非常快 1000ms.

117status_t SFWatchDog::readyToRun() {118    XLOGI("[%s]", __func__);119120    mThreshold = SW_WATCHDOG_INIT_THRESHOLD; //800ms121    mTimer = SW_WATCHDOG_TIMER; //1000ms122    mShowLog = false;123124    return NO_ERROR;125}

它提供了两个API 供外部调用, 如下所示.

 352void SFWatchDog::markStartTransactionTime(uint32_t index) {353    Mutex::Autolock _l(mLock);354355    if (index >= mNodeList.size()) {356        XLOGE("[unmarkStartTransactionTime] index=%d > Node list size=%d", index, mNodeList.size());357        return;358    }359360    mNodeList[index]->mStartTransactionTime = systemTime();361    mUpdateCount ++;362    if (mShowLog)363        XLOGV("[%s] name=%s, index=%d, time = %" PRId64 "", __func__, mNodeList[index]->mName.string(), index, mNodeList[index]->mStartTransactionTime);364 }365366 void SFWatchDog::unmarkStartTransactionTime(uint32_t index) {367    Mutex::Autolock _l(mLock);368369    if (index >= mNodeList.size()) {370        XLOGE("[unmarkStartTransactionTime] index=%d > Node list size=%d", index, mNodeList.size());371        return;372    }373374    mNodeList[index]->mStartTransactionTime = 0;375    mTransformRegionStorage.clear();376377    if (mShowLog)378        XLOGV("[%s] name=%s, index=%d, time = %" PRId64 "", __func__, mNodeList[index]->mName.string(), index, mNodeList[index]->mStartTransactionTime);379 }380

目前检测的是SF Main thread 的行为, 即检测了SF 的onMessageReceived

 937void SurfaceFlinger::onMessageReceived(int32_t what) {938#ifdef MTK_AOSP_ENHANCEMENT939    ATRACE_CALL_PERF();940    // start watchdog941    sp watchDog(SFWatchDog::getInstance());942    watchDog->markStartTransactionTime(mWatchDogIndex);943#else944    ATRACE_CALL();945#endif946    switch (what) {947        case MessageQueue::TRANSACTION: {948            handleMessageTransaction();949            break;950        }951        case MessageQueue::INVALIDATE: {952            bool refreshNeeded = handleMessageTransaction();953            refreshNeeded |= handleMessageInvalidate();954            refreshNeeded |= mRepaintEverything;955            if (refreshNeeded) {956                // Signal a refresh if a transaction modified the window state,957                // a new buffer was latched, or if HWC has requested a full958                // repaint959                signalRefresh();960            }961            break;962        }963        case MessageQueue::REFRESH: {964            handleMessageRefresh();965            break;966        }967    }968#ifdef MTK_AOSP_ENHANCEMENT969    // stop watchdog970    watchDog->unmarkStartTransactionTime(mWatchDogIndex);971#endif972}

目前SFWatchdog 的处理方式比较简单，超时后，利用debuggerd 打印backtrace 到/data/anr/SF_RTT 当中.

4. hang detect

目前有开发两个feature：

一个用来监控system server 的watchdog 行为是否异常.
一个用来监控点亮屏幕的操作是否能在规定的时间内完成，因为此feature 存在一些误报的现象，目前还没有开启.

我们目前只说明第一个的实现.

首先，注册了一个device, /dev/RT_Monitor, 上层可以通过ioctl 和它进行沟通.

99 static long monitor_hang_ioctl(struct file *file, unsigned int cmd, unsigned long arg)100{101 int ret = 0;102 static long long monitor_status;103 if (cmd == AEEIOCTL_WDT_KICK_POWERKEY) {104     if ((int)arg == WDT_SETBY_WMS_DISABLE_PWK_MONITOR) {105         /* pwk_start_monitor=0; */106         /* wdt_kick_status=0; */107         /* hwt_kick_times=0; */108     } else if ((int)arg == WDT_SETBY_WMS_ENABLE_PWK_MONITOR) {109         /* pwk_start_monitor=1; */110         /* wdt_kick_status=0; */111         /* hwt_kick_times=0; */112     } else if ((int)arg < 0xf) {113         aee_kernel_wdt_kick_Powkey_api("Powerkey ioctl", (int)arg);114     }115     return ret;116117 }118/* QHQ RT Monitor */119 if (cmd == AEEIOCTL_RT_MON_Kick) {120     LOGE("AEEIOCTL_RT_MON_Kick ( %d)\n", (int)arg);121     aee_kernel_RT_Monitor_api((int)arg);122     return ret;123 }124//   LOGE("AEEIOCTL_RT_MON_Kick unknown cmd :(%d)( %d)\n",(int)cmd, (int)arg);125//   LOGE("AEEIOCTL_RT_MON_Kick known cmd :(%d)( %d)\n",(int)AEEIOCTL_WDT_KICK_POWERKEY, (int)AEEIOCTL_RT_MON_Kick);126/* QHQ RT Monitor end */127128 if (cmd == AEEIOCTL_SET_SF_STATE) {129     if (copy_from_user(&monitor_status, (void __user *)arg, sizeof(long long)))130         ret = -1;131     LOGE("AEE_MONITOR_SET[status]: 0x%llx", monitor_status);132     return ret;133 } else if (cmd == AEEIOCTL_GET_SF_STATE) {134     if (copy_to_user((void __user *)arg, &monitor_status, sizeof(long long)))135         ret = -1;136     return ret;137 }138139 return -1;140}

其中我们重点关注AEEIOCTL_RT_MON_Kick

445void aee_kernel_RT_Monitor_api(int lParam)446{447 if (0 == lParam) {448     hd_detect_enabled = 0;449     hang_detect_counter = hd_timeout;450     LOGE("[Hang_Detect] hang_detect disabled\n");451 } else if (lParam > 0) {452     hd_detect_enabled = 1;453     hang_detect_counter = hd_timeout = ((long)lParam + HD_INTER - 1) / (HD_INTER);454     LOGE("[Hang_Detect] hang_detect enabled %d\n", hd_timeout);455 }456}

即在hang detect 中有两个关键的变数， hd_detect_enabled 指示当前hang detect 是否开启， hang_detect_counter 为计时器计数. hang_detect thread 每隔30s (HD_INTER) 将其减一。

其设计思想非常简单，即上层通过ioctl 此device, 设置hang_detect_counter, 即告知hang detect, 本人预计会在hang_detect_counter * 30s 之内再次来tick 您, 假如我没有在这个时间内tick 您，那么就意味着我已经牺牲了, 您就发动暴动, 重启手机.

对应hang_detect_thread 的实现就这个循环检测和操作hang_detect_counter .

385static int hang_detect_thread(void *arg)386{387388 /* unsigned long flags; */389 struct sched_param param = {.sched_priority = RTPM_PRIO_WDT };390391 LOGE("[Hang_Detect] hang_detect thread starts.\n");392393 sched_setscheduler(current, SCHED_FIFO, ¶m);394395 while (1) {396     if ((1 == hd_detect_enabled) && (FindTaskByName("system_server") != -1)) {397         LOGE("[Hang_Detect] hang_detect thread counts down %d:%d.\n",398              hang_detect_counter, hd_timeout);399400401         if (hang_detect_counter <= 0) {402             ShowStatus();403         }404405406         if (hang_detect_counter == 0)407         {408             LOGE("[Hang_Detect] we should triger   HWT ...\n");409             if(aee_mode!=AEE_MODE_CUSTOMER_USER)410             {411                 aee_kernel_warning_api(__FILE__, __LINE__, DB_OPT_NE_JBT_TRACES|DB_OPT_DISPLAY_HANG_DUMP, "\nCRDISPATCH_KEY:SS Hang\n","we triger HWT ");412                 msleep(30 * 1000);413             }414             else //only Customer user load  trigger HWT415             {416                 //aee_kernel_exception_api(__FILE__, __LINE__, DB_OPT_NE_JBT_TRACES|DB_OPT_DISPLAY_HANG_DUMP, "\nCRDISPATCH_KEY:SS Hang\n","we triger HWT ");417                 //msleep(30 * 1000);418                 //local_irq_disable();419                 //while (1);420                 BUG();421             }422         }423424         hang_detect_counter--;425     } else {426         /* incase of system_server restart, we give 2 mins more.(4*HD_INTER) */427         if (1 == hd_detect_enabled) {428             hang_detect_counter = hd_timeout + 4;429             hd_detect_enabled = 0;430         }431         LOGE("[Hang_Detect] hang_detect disabled.\n");432     }433434     msleep((HD_INTER) * 1000);435 }436 return 0;437}

5. System server Watchdog call hang detect

与之相关的代码其实很少，所以我直接贴出来，然后再来讲.

 85  ExceptionLog exceptionHWT; //init exceptionHWT262        if (SystemProperties.get("ro.have_aee_feature").equals("1")) {263            exceptionHWT = new ExceptionLog();264        } 386         mSFHang = false;387         if(exceptionHWT!= null){388             exceptionHWT.WDTMatterJava(300);389         }390         if(mNeedDump){391                // We've waited half the deadlock-detection interval.  Pull a stack392                // trace and wait another half.393                if(exceptionHWT!= null) exceptionHWT.WDTMatterJava(600);394                dumpAllBackTraces(true);395                mNeedDump = false;396         }397 495        if(exceptionHWT!= null) exceptionHWT.WDTMatterJava(720);

即System server watchdog 在轮转的过程中，会周期性的tick hang detect, 目前设计的timing 比较保守，我们会在M 版本将这个时间进一步降低优化. tick 分成三种:

正常情况下，tick 300s, 对应count=10.
在dump backtrace 时，tick 600s, 对应count=20.
在SWT 发生的情况下，tick 720s, 对应count=24.

三、问题分析

正如我们前面提到，目前hang detect 问题发生时，即意味着watchdog 因为一些特殊的原因没有正确的执行. 你的分析手法可以按下面的流程进行.

1. 确定System Server watchdog tick hang detect 的状态

这个可以从kernel log 中明确的看到.如：

watchdog 看起来正常：

[  198.215932] (1)[1322:watchdog]AEEIOCTL_RT_MON_Kick ( 300)[  198.215945] (1)[1322:watchdog][Hang_Detect] hang_detect enabled 10

watchdog 在dump backtrace:

[  258.218145] (0)[1322:watchdog]AEEIOCTL_RT_MON_Kick ( 600)[  258.218171] (0)[1322:watchdog][Hang_Detect] hang_detect enabled 20

watchdog 在做SWT:

[  299.046542] (0)[1322:watchdog]AEEIOCTL_RT_MON_Kick ( 720)[  299.046572] (0)[1322:watchdog][Hang_Detect] hang_detect enabled 24

当然你也可以从hang detect thread 的log 中看到这个：

[  210.475572] (0)[90:hang_detect][Hang_Detect] init found pid:1.[  210.475735] (0)[90:hang_detect][Hang_Detect] mmcqd/0 found pid:158.[  210.475815] (0)[90:hang_detect][Hang_Detect] surfaceflinger found pid:265.[  210.475887] (0)[90:hang_detect][Hang_Detect] system_server found pid:734.[  210.475919] (0)[90:hang_detect][Hang_Detect] ndroid.systemui found pid:1071.[  210.476003] (0)[90:hang_detect][Hang_Detect] debuggerd found pid:4313.[  210.476027] (0)[90:hang_detect][Hang_Detect] debuggerd64 found pid:4314.[  210.476056] (0)[90:hang_detect][Hang_Detect] hang_detect thread counts down 10:10.

2. 确认System Server Watchdog thread 状态

首先你需要明白， Watchdog 正常时，它是停留在java wait 函数，所以它对应的backtrace 即是

 KERNEL SPACE BACKTRACE, sysTid=1299     [] __switch_to+0x74/0x8c from []     [] __schedule+0x314/0x794 from []     [] schedule+0x24/0x68 from []     [] futex_wait_queue_me+0xcc/0x158 from []     [] futex_wait+0x120/0x20c from []     [] do_futex+0x184/0xa48 from []     [] SyS_futex+0x88/0x19c from []     [] cpu_switch_to+0x48/0x4c from []  "watchdog" sysTid=1299   #00 pc 0000000000019478  /system/lib64/libc.so (syscall+28)  #01 pc 00000000000d0c74  /system/lib64/libart.so (art::ConditionVariable::TimedWait(art::Thread*, long, int)+168)  #02 pc 00000000002a3e98  /system/lib64/libart.so (art::Monitor::Wait(art::Thread*, long, int, bool, art::ThreadState)+860)  #03 pc 00000000002a4e04  /system/lib64/libart.so (art::Monitor::Wait(art::Thread*, art::mirror::Object*, long, int, bool, art::ThreadState)+244)  #04 pc 0000000000000974  /data/dalvik-cache/arm64/system@framework@boot.oat

但注意的是因为在kernel 中，你只能看到kernel backtrace, 而SyS_futex 这个futex 只能表明是上层卡住, 可能是pthread mutex lock, 也可能是wait 也可能是其他，难以直接明了.

如果不是这个backtrace 那么很明显watchdog 已经卡住，这个时候即由它的backtrace 进行推理，以便确认进一步卡住的地方。

那如果你没有找到watchdog 线程怎么办呢？很简单，说明此时可能是两种情况，一种是system server 发生SWT 后，退出因为卡在了kernel 导致system server 某个线程无法退出，而这个线程就是你需要进一步分析的，另外一种情况是system server SWT 重启后，system server 初始化失败，watchdog 还没有启动就卡死了。这两种根据前后的LOG 很容易就可以判断出来。

3.关键process 状态追查

根据以往分析的经验，我们发现很多时候都是一些关键的process 卡住，导致watchdog 的行为无法达成. 所以我们在hang detect 中打印了关键的Process 的资讯，以便快速追查问题.

[  300.505542] (0)[90:hang_detect][Hang_Detect] init found pid:1.[  300.505616] (0)[90:hang_detect][Hang_Detect] mmcqd/0 found pid:158.[  300.505649] (0)[90:hang_detect][Hang_Detect] surfaceflinger found pid:265.[  300.505678] (0)[90:hang_detect][Hang_Detect] system_server found pid:734.[  300.505688] (0)[90:hang_detect][Hang_Detect] ndroid.systemui found pid:1071.[  300.505719] (0)[90:hang_detect][Hang_Detect] debuggerd found pid:4313.[  300.505726] (0)[90:hang_detect][Hang_Detect] debuggerd64 found pid:4314.[  300.505735] (0)[90:hang_detect][Hang_Detect] hang_detect thread counts down 0:24.

比如我们会将这些关键的process 的kernel thread 打印，还会打印系统的memory 状况，以及系统中所有的 ‘D’ 的process 状态以便快速分析问题。

init 卡住的话，就意味着任何system property 的设置，或者service 的重启，wifi 的设置等都会卡住.

mmcqd 卡住的话，就意味着emmc 可能卡住.

surfaceflinger 卡住的话，就意味着display driver 和 GPU 可能卡住.

systemui 卡住的话，就意味着keyguard 可能卡住.

debuggerd 卡住的话，Watchdog 抓取backtrace 时就会卡住.

......

4. 保存现场快速分析.

当前面的资讯都难以最终定位root cause 时，我们就需要转变思想，将重启再变成死机, 即我们把hang_detect_thread 中的重启(call bug) 去除，或者直接使用eng 版本复现，目标就是让其死机，然后再用死机现场来分析。

MTK 提供team viewer 远程debug 支持，如果贵司有死机现场，可以让MTK 同仁通过team viewer 远程debug 以便快速定位问题.

当我们找到root cause 之后，再回过头来想，hang detect 缺少了哪些资讯导致我们无法分析成功，然后再修改hang detect.

这是一个持续渐进的过程, 欢迎大家提供更多有效的建议.

1 0