Android手機性能問題一直是用戶關注的重點，分析性能問題則成為工程師日常工作的一部分。根據問題的類型通常有適合的工具可供使用，比如systrace ,traceview,simpleperf等可視化工具，然而這些工具對用戶而言操作相對復雜，比較雞肋但容易生成的bugreport就成為了解決用戶反饋問題時僅有的“黑匣子”（通常還有一段文字描述或者現場視頻）。這篇文章就來介紹如何用bugreport分析性能問題。

初學者分析bugreport時往往不得要領，原因有三個。第一，bugreport內容非常龐大繁雜，比如我現在手上這份有63M，73萬行；第二，要修車必須得先懂車，要解決bug必須先懂系統；第三，性能問題的原因很多，常見的比如等鎖，死鎖，cpu搶占，cpu頻率（boost或限頻），拔核，編譯問題導致的代碼執行效率低，IO搶占，物理內存不足，虛擬空間耗盡，內存碎片，binder調用耗時，優先級反轉，系統中各種cache異常，主線程忙，vsync異常，input事件異常，窗口失去焦點，繪圖buffer異常，GPU合成慢，kernel配置選項異常等等等等等。。。。。。有些原因隱藏的比較深且關系鏈長，進一步加大了分析的難度。

盡管如此，bugreport的分析還是有一些通用的套路。既然閣下骨骼驚奇，想必也是練武奇才，這份秘籍送給你，還望好好練習，他日若遂凌云志，江湖血雨腥風時。

1) 明確目標

一個即將被圍毆的劍客，最重要的是快速對敵人一劍封喉，而不僅僅是研究對方幾個人啥陣型，畢竟還要留點時間耍酷。一個快要脫發的碼農，拿到一份bugreport最重要是快速解決問題，而不僅僅是找出根因，畢竟還要留時間解下一個bug。

一劍封喉和研究陣型是目標與手段的關系，找出原因和解決問題同樣如此。常犯的錯誤是把手段當成了目標多走了彎路。這是因為，思路不同：查清一個問題的原因和判斷這個問題屬于哪個領域是兩個不同的問題，自然也有著不同的解法；代價不同：讓我發現萬有引力定律需要向天再借5000年，而請牛頓幫忙的話這事最多不超過23年。手機系統是由眾多的模塊組成的，不同的模塊由不同的工程師負責，而專業的事要找專業的人，這才是效率最大化的方式。區分目標和手段聽起來簡單，但工作中我的確見過很多人犯這個錯誤，尤其是陷入到一個復雜問題的時候。當然，時間允許的情況下，一定要刨根問底，畢竟劍客的耍酷是建立在耍劍基礎上的。

2) 定位問題。

用戶反饋時都會有對應的問題描述，覺悟高的用戶還會傳卡頓現場的視頻。一定要多讀幾遍描述，仔細看幾遍視頻，里面包含的信息量其實是很多的，卻很容易被忽視，這些蛛絲馬跡對解決問題至關重要，我們把它記為信息集I。在整個分析過程中I中的信息是不斷增加的，并且每一條都很重要。

private static final int SKIPPED_FRAME_WARNING_LIMIT = SystemProperties.getInt("debug.choreographer.skipwarning", 30);if (skippedFrames >= SKIPPED_FRAME_WARNING_LIMIT) {Log.i(TAG, "Skipped " + skippedFrames + " frames!  "+ "The application may be doing too much work on its main thread.");
}

通過以上代碼可以看到，當掉幀數超過SKIPPED_FRAME_WARNING_LIMIT（默認30幀）時會打印Skipped....的log。我們就以它作為切入點進行問題定位。bugreport中搜索這條log，得到兩種結果：

a) 搜到：通常搜索到不止1條，需要根據信息集I中的信息進行過濾，比如根據發生的時間，根據問題app，卡頓的嚴重程度或者問題前后的行為等。如果無法過濾出特定消息，返回上一步，完善信息集I或者溝通用戶補充信息。

舉個例子，通過微博17:52卡頓的描述可以定位下面的log:

02-17 17:52:30.443 10208 28958 28958 I Choreographer: Skipped 1150 frames!  
The application may be doing too much work on its main thread.----- pid 28958 at 2020-02-17 17:53:56 -----
Cmd line: com.sina.weibo

log解釋：微博在02-17 17:52:30.443掉了1150幀，也就是19166ms（正常情況1s 60幀，動態調頻除外）。到這里信息集I中的信息增加了，這里面的信息就是刷子，時刻知道自己有幾把刷子對解決問題是極其重要的。

b) 沒搜到：沒有信息本身就是信息。事實上沒搜到比搜到了包含的信息更多。這里至少包含了以下幾種可能。1. 掉幀但是主線程卡死，沒機會打log 2. 沒掉幀 3. 掉幀數沒達到閾值 4. 沒接收vsync。沒接收vsync包括 4.1 主線程卡死，4.2 沒有請求vsync。以上信息加入信息集I中（其中有些是互斥關系，當一個確定后，與之互斥的就要刪掉）。這種情況需要借助用戶在卡頓前后的行為進行定位，通常會鎖定到一個很小的時間段內。

3) 分析原因

通過上面的步驟，我們明確了目標，定位到了一條log或者鎖定了一個時間段，手里有了幾把刷子。這就是起點，接下來條條大路通羅馬，我分享我認為重要的幾點經驗。

問題分類。對問題進行分類一方面便于歸納總結，另一方面便于借鑒同類問題的解法。比如，卡死問題。常見原因無外乎主線程忙，窗口失去焦點，SurfaceFlinger合成出問題導致界面沒有繪制等。這種常見原因不多的問題適合逐一排除，crash、黑屏白屏問題也屬于此類。

對于其他很多問題，可能原因就太多了，文章開頭列出的還只是我遇到的一部分。這種問題顯然不能逐一排查。怎么辦呢，畢竟此時手上沒幾把刷子，但有時少即是多，這使我們可以充分利用僅有的信息。

以上面微博卡頓為例，我們只知道微博在02-17 17:52:30.443的時候卡了19166ms。信息很少，但可以肯定log是在卡頓結束后打出的（沒結束的話就不知道總共卡了多久），而且問題的原因肯定發生在02-17 17:52:30.443之前，大概率發生在離兩個端點（02-17 17:52:30.443和02-17 17:52:30.443-19166ms）不遠的地方。接下來我們同時掃描一下相應時間段的main log和event log，結果在event log中有如下發現:

02-17 17:52:30.433 10208 28958 28958 I binder_sample: [android.app.IActivityTaskManager,1,19175,
com.sina.weibo,100]

可見微博通過binder call IPC調用了IActivityTaskManager的接口1，并且耗時19175ms，(19175ms > 19166ms, 17:52:30.433在17:52:30.443前面，看似矛盾，但19166ms是跳過的幀，總時間還應加上正常幀的16.6ms)。這是一個跨進程的調用，對端是system_server進程，到這里，我們的信息集I中的元素進一步增加了，并且可以知道卡頓的原因轉移到了system_server進程。就這樣，一直分析下去。簡單貼一下system_server端的log，可見是在等鎖，持鎖方在執行dumpActivity:

02-17 17:52:30.377  1000  1639  8339 I dvm_lock_sample: [system_server,1,Binder:1639_1B,19119,
WindowProcessUtils.java,400,java.lang.String com.android.server.wm.WindowProcessUtils
.getCallerPackageName(...),
ActivityTaskManagerService.java,7253,boolean com.android.server.wm
.ActivityTaskManagerService$LocalService.dumpActivity(...),100]

全局觀察，用點想象力。通過邏輯推理從A到B可能需要n步，但通過想象只需要一步。這屬于只可意會不可言傳的騷操作領域，但還是有一點點技巧的，技巧就是從細節中跳出來，全局考慮，找規律。舉個例子，對于圖形化分析工具，比如systrace，如果有兩個操作的圖像能較好的拼在一起（板塊構造學說是不是這么來的？），或者一批操作的圖像的一端都嚴格對齊等等，這些反常的信號都在暗示它們之間可能存在很強的聯系或者它們受一個共同因素的影響。再比如bugreport中，如果一段時間內所有的app都卡，放心絕對不是有什么東方的神秘力量，而是系統在抽風，比如內存碎片化比較嚴重或者CPU降頻等影響全局的因素。

舉個例子：打開相機卡

定位Log:

07-27 18:37:56.222 1000 1586 1642 I am_activity_launch_time:[0,225986022,
com.android.camera/.Camera,19823]

的確是卡的不輕，19823ms相當嚴重了已經。根據上面說的方法，繼續找到下面的log：

07-27 18:37:55.799 10091  2248  2248 I binder_sample: [android.app.IActivityTaskManager,1,19439,
com.miui.home,100]
07-27 18:37:55.801 10091  2248  2248 I am_on_paused_called: [0,com.miui.home.launcher.Launcher,
performPause]

因為啟動相機的過程首先要pause桌面，然而這里pause桌面花了19439ms。常規操作應該向前找為什么這里binder調用花了這么久，但不好意思，不是找不到，前面是真的沒有直接相關的有效log了。需要發揮點想象力了，掃了一眼發現下面的log

07-27 18:37:55.802  1000  1586  2179 I dvm_lock_sample: [system_server,1,ClientModeImpl,18041,
..........................,int com.android.server.am.ActivityManagerService.broadcastIntent(),
-,1524,void com.android.server.am.ActivityManagerService$AppDeathRecipient.
binderDied(),100]
07-27 18:37:55.803  1000  1586  4970 I dvm_lock_sample: [system_server,1,Binder:1586_18,16790,
..........................int com.android.server.am.ActivityManagerService.broadcastIntent(),
-,1524,void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied(),100]
07-27 18:37:55.803  1000  1586  2174 I dvm_lock_sample: [system_server,0,NetworkStats,16783,
.........................,int com.android.server.am.ActivityManagerService.broadcastIntent(),
-,1524,void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied(),100]

這里的等鎖單從時間上看就跟桌面pause扯不上關系，但是有一個binderDied，app進程被殺了？lowmemorykiller（LMK）殺的？看了一下果然這段時間有大量殺進程的日志，取其中一個如下：

07-27 18:37:55.975  I lowmemorykiller: Killing ':accountservice' (15215) (tgid 15215), adj 965,
07-27 18:37:55.975  I         : to free 121500kB on behalf of 'kswapd0' (90) because
07-27 18:37:55.975  I         : cache 1925820kB is below limit 347440kB for oom score 606
07-27 18:37:55.975  I         : Free memory is -28000kB above reserved.
07-27 18:37:55.975  I         : Free CMA is 17836kB
07-27 18:37:55.975  I         : Total reserve is 133660kB
07-27 18:37:55.975  I         : Total free pages is 150736kB
07-27 18:37:55.975  I         : Total file cache is 2844160kB
07-27 18:37:55.975  I         : GFP mask is 0x14000c0

信息量不小，解釋一下，Total free pages is 150736kB，剩余內存僅有約150M。cache 1925820kB is below limit 347440kB，1925820kB < 347440kB，顯然矛盾。for oom score 606與adj 965也不一致。理解這些矛盾需要對kernel LMK機制有所掌握，我直接給出答案。由于kswapd無法回收文件頁，導致LMK機制無法發揮作用（因為LMK需要同時判斷文件頁和剩余內存小于閾值minfree才會起作用，minfree通常幾百M，這里文件cache接近2G,顯然太大），進而導致緩存進程無法被殺，內存得不到釋放。內存得不到釋放帶來的后果就是內存壓力逐漸變大，當內存壓力超過一定的閾值后，kernel強制使能LMK，這時候log中就會出現上面的矛盾。（kernel這種雙反饋思想還是值得學習的；另外，為什么LMK的判斷條件里還要加一個文件頁<minfree的判斷？這是因為正常情況下文件頁是容易被kswapd回收的，釋放出來的內存可以供App使用，所以不需要殺掉后臺緩存進程這種影響性能的方式）。到這里最大的疑問就是kernel為什么沒有回收掉文件頁，有一些可能的原因，不過不在本文討論范圍內了。

所以由于文件頁回收不掉，加上空閑內存只有150M左右（這是一個極低的值，一般當空閑內存低到300M左右，手機就會出現明顯卡頓），導致相機啟動時間長的可能是非常大的。

檢查確認。google原生log是比較有限的，為了更好的定位問題，各大手機廠商都有自己的log系統，但即使這樣仍然有很多問題是無法100%確定原因的，就像上面的例子，我們也只能說大概率是內存原因。另外多數情況下信息集I中的信息是非常多的，每一條信息都可能會把我們引到不同的解決路徑上，而這條路通向的是否是羅馬也是值得商榷的。所以，比較好的習慣是得出結論后，回頭看看它與我們信息集中的信息是否有沖突，一個正確的結論與條件應該是和諧的。

4)解決問題

通過前面的步驟，我們現在已經調查清楚了原因，這會引導我們解決現有的bug或者做出新的優化，也是工作的重點。這一部分需要注意的也挺多的，但不打算寫了，因為對大多數人來說意義不大，再者我們的宗旨就是廢話少說，盡管已經說了不少廢話。

收工前總結一下，這篇文章說明了bugreport分析的必要性，描述了初學者分析困難的原因，其中重點提到了常見的導致性能問題的因素，接著主要分享了更好的分析bugreport的經驗，包括明確目標來規劃思路和提高效率，從Skipped frames入手定位問題，對問題進行分類來確定解題思路，發揮想象另辟蹊徑，用信息集來檢查結論，最后解決問題。正如文章開頭說的，bugreport只是性能問題的診斷工具之一，工具沒有好壞之分只有適不適合，都幾把工具總是有好處的，后面有機會再介紹simpleperf,systrace等核武器。

總結

以上是生活随笔為你收集整理的android camera 降低帧率_Android性能问题分析之bugreport的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。