安卓CPU高占用問題定位方法

今天測試報了一個問題說我們都某個應(yīng)用從top命令看cpu占用到了百分之90幾,這種問題要怎么分析呢?

首先adb連接上去之后用logcat | grep 應(yīng)用進程pid查看看看有沒有頻繁打印日志,如果有的話根據(jù)日志就能比較簡單的定位到代碼,但這次我看了下并沒有什么輸出。

然后可以adb連接上去用Profiler抓一下進程的CPU使用信息,例如下圖就可以看到Thread-2這個線程一直處于Running的狀態(tài)沒有停過,所以就是這個線程在不停占用CPU:

1.png

如果某些機器不能使用adb只能用串口查看的話還能怎么做呢?

我們可以用kill -3 應(yīng)用進程pid命令強行在/data/anr下生成所有線程的堆棧文件,然后可以一個個線程分析過去看看線程運行到哪里了。當(dāng)然如果線程數(shù)量比較多的時候就比較低效了,尤其是開了混淆的情況下。

但其實堆棧文件里面是有信息可以輔助我們分析是哪個線程不停在占用cpu的,例如Thread-6的線程堆棧如下:

"Thread-6" prio=5 tid=3 Native
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x75c801b8 self=0xb400007140d4ca60
  | sysTid=5030 nice=0 cgrp=default sched=0/0 handle=0x6fb6d0bcb0
  | state=R schedstat=( 43469364687935 414576037821 2915248 ) utm=2781704 stm=1565231 core=6 HZ=100
  | stack=0x6fb650c000-0x6fb650e000 stackSize=8191KB
  | held mutexes=
  native: #00 pc 00000000000a22d8  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+8) (BuildId: 058e3ec96fa600fb840a6a6956c6b64e)
  native: #01 pc 000000000005b40c  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156) (BuildId: 058e3ec96fa600fb840a6a6956c6b64e)
  ...

| state=R schedstat=( 43469364687935 414576037821 2915248 ) utm=2781704 stm=1565231 core=6 HZ=100這行其實能看到比較有用的信息但是可能很多人會忽略掉。

state

線程狀態(tài),root的情況下我們也可以直接cat /proc/{pid}/task/{tid}/stat獲取,它和cat /proc/{pid}/stat的進程狀態(tài)類似,從文檔看有下面的下面的值:

  • R Running
  • S Sleeping in an interruptible wait
  • D Waiting in uninterruptible disk sleep
  • Z Zombie
  • T Stopped (on a signal) or (before Linux 2.6.33) trace stopped
  • t Tracing stop (Linux 2.6.33 onward)
  • W Paging (only before Linux 2.6.0)
  • X Dead (from Linux 2.6.0 onward)
  • x Dead (Linux 2.6.33 to 3.13 only)
  • K Wakekill (Linux 2.6.33 to 3.13 only)
  • W Waking (Linux 2.6.33 to 3.13 only)
  • P Parked (Linux 3.9 to 3.13 only)
  • I Idle (Linux 4.14 onward)

schedstat

schedstat顯示了CPU的調(diào)度器統(tǒng)計數(shù)據(jù),它有三個數(shù)字的含義分別是

  1. 在CPU上運行花費的時間(單位是納秒)
  2. 在調(diào)度隊列上等待的時間(單位是納秒)
  3. CPU調(diào)度切換次數(shù)

root的情況下我們也可以直接cat /proc/{pid}/task/{tid}/schedstat獲取

所以schedstat=( 43469364687935 414576037821 2915248 )表示這個線程在CPU上運行了43469364687935ns, 等待了414576037821ns, 調(diào)度切換了2915248次。

HZ

系統(tǒng)時間是以tick(節(jié)拍)為單位進行計算的,維基百科上是這么說的:

The system clock is typically implemented as a programmable interval timer that periodically interrupts the CPU, which then starts executing a timer interrupt service routine. This routine typically adds one tick to the system clock (a simple counter) and handles other periodic housekeeping tasks (preemption, etc.) before returning to the task the CPU was executing before the interruption.

Linux核心每隔固定周期會發(fā)出timer interrupt (IRQ 0)，這個中斷會觸發(fā)系統(tǒng)時間的更新、系統(tǒng)資源使用率的更新、檢查alarm或者delay function之類的調(diào)用，檢查進程CPU的分配等。

HZ用來定義每秒有多少次timer interrupt，通過它可以計算出每個tick是多長，例如上面顯示的HZ=100代表的是每個tick為1s / 100 = 10ms

utm、stm

因為系統(tǒng)時間以tick為單位,所以進程的用戶態(tài)、內(nèi)核態(tài)運行時間都是以tick為單位的。

  • utime: 用戶態(tài)下使用了多少個tick的CPU
  • utime: 內(nèi)核態(tài)下使用了多少個tick的CPU

由于從前面的HZ=100的到每個tick為10ms,所以utm=2781704 stm=1565231代表這個線程在用戶態(tài)下使用了2781704 * 10 = 27817040ms的CPU,在內(nèi)核態(tài)下使用了1565231 * 10 = 15652310ms的CPU,

它總的CPU使用總時間就是27817040ms + 15652310ms = 43469350ms和前面schedstat算出來的43469364687935ns = 43469364ms是匹配的

core

最后是CPU哪個核在執(zhí)行這個線程

定位方法

有了上面這些信息之后我們就能比較快速的定位是哪個線程在不斷占用cpu了:

  1. 使用kill -3 {pid}命令輸出第一份堆棧
  2. 等待1分鐘
  3. 使用kill -3 {pid}命令輸出第二份堆棧
  4. 編寫腳本對比兩份堆棧里面每個線程的schedstat,看每個線程在這一分鐘了使用了多久的cpu

這個腳本代碼如下:

import sys
import datetime

def readTrace(path):
    thread_run_time = {}
    with open(path) as f:
        for line in f.readlines():
            if line.startswith("----- pid "):
                trace_time = datetime.datetime.strptime(line.split(" at ")[1].split(".")[0], "%Y-%m-%d %H:%M:%S")
            elif " tid=" in line:
                thread_name = line.strip().split("\"")[1]
            elif "schedstat=(" in line:
                schedstat = line.split("schedstat=( ")[1].split(")")[0].split(" ")
                thread_run_time[thread_name] = (int(schedstat[0]) + int(schedstat[1])) / 1000000000.0
    return trace_time, thread_run_time


if __name__ == '__main__':
    trace_time_start, thread_run_time_start = readTrace(sys.argv[1])
    trace_time_end, thread_run_time_end = readTrace(sys.argv[2])
    duration = (trace_time_end - trace_time_start).total_seconds()
    result = []
    for thread, thread_run_time in thread_run_time_end.items():
        if thread in thread_run_time_start:
            thread_run_in_duration = thread_run_time_end[thread] -  thread_run_time_start[thread]
            result.append([thread, thread_run_in_duration, f"{thread_run_in_duration / duration:.{2}%}"])
    for it in sorted(result, key=lambda it: it[1], reverse=True):
        print(it[0], it[1], it[2])

執(zhí)行結(jié)果如下:

python3 test.py trace_04 trace_05
Thread-6 100.00285464500485 99.01%
main 0.4229402489999998 0.42%
HeapTaskDaemon 0.1186862900000012 0.12%
Signal Catcher 0.113778791 0.11%
Thread-7 0.11453095000000069 0.11%
DefaultDispatcher-worker-5 0.1086997830000005 0.11%
...

最后找到Thread-6線程在09:22:10.977080231到09:23:51.419991904這100秒左右,使用了43469364687935ns - 43402540633850ns = 66824054085ns秒的cpu,然后還在調(diào)度隊列上等待了414576037821ns - 381397237261ns = 33178800560ns,66824054085ns + 33178800560ns = 100002854645ns = 100.002854645s基本這100s它都在執(zhí)行了:

----- pid 1834 at 2024-10-16 09:22:10.977080231+0800 -----
...
"Thread-6" prio=5 tid=3 Native
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x75c801b8 self=0xb400007140d4ca60
  | sysTid=5030 nice=0 cgrp=default sched=0/0 handle=0x6fb6d0bcb0
  | state=R schedstat=( 43402540633850 381397237261 2772868 ) utm=2777362 stm=1562891 core=5 HZ=100
  | stack=0x6fb650c000-0x6fb650e000 stackSize=8191KB
  | held mutexes=
  native: #00 pc 00000000000a22d8  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+8) (BuildId: 058e3ec96fa600fb840a6a6956c6b64e)
  native: #01 pc 000000000005b40c  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156) (BuildId: 058e3ec96fa600fb840a6a6956c6b64e)
  ...

----- pid 1834 at 2024-10-16 09:23:51.419991904+0800 -----
...
"Thread-6" prio=5 tid=3 Native
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x75c801b8 self=0xb400007140d4ca60
  | sysTid=5030 nice=0 cgrp=default sched=0/0 handle=0x6fb6d0bcb0
  | state=R schedstat=( 43469364687935 414576037821 2915248 ) utm=2781704 stm=1565231 core=6 HZ=100
  | stack=0x6fb650c000-0x6fb650e000 stackSize=8191KB
  | held mutexes=
  native: #00 pc 00000000000a22d8  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+8) (BuildId: 058e3ec96fa600fb840a6a6956c6b64e)
  native: #01 pc 000000000005b40c  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156) (BuildId: 058e3ec96fa600fb840a6a6956c6b64e)

然后就可以根據(jù)堆棧定位到底是哪里的代碼邏輯異常不斷占用cpu。

最后編輯于 ：
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時請結(jié)合常識與多方信息審慎甄別。
平臺聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點，簡書系信息發(fā)布平臺，僅提供信息存儲服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容