Android教程網
  1. 首頁
  2. Android 技術
  3. Android 手機
  4. Android 系統教程
  5. Android 游戲
 Android教程網 >> Android技術 >> 關於Android編程 >> 通過Android trace文件分析死鎖ANR實例過程

通過Android trace文件分析死鎖ANR實例過程

編輯:關於Android編程

對於從事Android開發的人來說,遇到ANR(Application Not Responding)是比較常見的問題。一般情況下,如果有ANR發生,系統都會在/data/anr/目錄下生成trace文件,通過分析trace文件,可以定位產生ANR的原因。產生ANR的原因有很多,比如CPU使用過高、事件沒有得到及時的響應、死鎖等,下面將通過一次因為死鎖導致的ANR問題,來說明如何通過trace文件分析ANR問題。

對應的部分trace文件內容如下:
"PowerManagerService" prio=5 tid=24 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x41dd0eb0 self=0x5241b218
| sysTid=567 nice=0 sched=0/0 cgrp=apps handle=1380038664
| state=S schedstat=( 6682116007 11324451214 33313 ) utm=450 stm=219 core=1
at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:~13045)
- waiting to lock <0x41a874a0> (a com.android.server.am.ActivityManagerService) held by tid=12 (android.server.ServerThread)
at android.app.ContextImpl.sendBroadcast(ContextImpl.java:1144)
at com.android.server.power.PowerManagerService$DisplayBlankerImpl.unblankAllDisplays(PowerManagerService.java:3442)
at com.android.server.power.DisplayPowerState$PhotonicModulator$1.run(DisplayPowerState.java:456)
at android.os.Handler.handleCallback(Handler.java:800)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:194)
at android.os.HandlerThread.run(HandlerThread.java:60)
"Binder_B" prio=5 tid=85 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x42744770 self=0x58329e88
| sysTid=3700 nice=-20 sched=0/0 cgrp=apps handle=1471424616
| state=S schedstat=( 1663727513 2044643318 6806 ) utm=132 stm=34 core=1
at com.android.server.power.PowerManagerService$DisplayBlankerImpl.toString(PowerManagerService.java:~3449)
- waiting to lock <0x41a7e420> (a com.android.server.power.PowerManagerService$DisplayBlankerImpl) held by tid=24 (PowerManagerService)
at java.lang.StringBuilder.append(StringBuilder.java:202)
at com.android.server.power.PowerManagerService.dump(PowerManagerService.java:3052)
at android.os.Binder.dump(Binder.java:264)
at android.os.Binder.onTransact(Binder.java:236)
at android.os.IPowerManager$Stub.onTransact(IPowerManager.java:373)
at android.os.Binder.execTransact(Binder.java:351)
at dalvik.system.NativeStart.run(Native Method)
"android.server.ServerThread" prio=5 tid=12 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x41a76178 self=0x507837a8
| sysTid=545 nice=-2 sched=0/0 cgrp=apps handle=1349936616
| state=S schedstat=( 15368096286 21707846934 69485 ) utm=1226 stm=310 core=0
at com.android.server.power.PowerManagerService.isScreenOnInternal(PowerManagerService.java:~2529)
- waiting to lock <0x41a7e2e8> (a java.lang.Object) held by tid=85 (Binder_B)
at com.android.server.power.PowerManagerService.isScreenOn(PowerManagerService.java:2522)
at com.android.server.wm.WindowManagerService.sendScreenStatusToClientsLocked(WindowManagerService.java:7749)
at com.android.server.wm.WindowManagerService.setEventDispatching(WindowManagerService.java:7628)
at com.android.server.am.ActivityManagerService.updateEventDispatchingLocked(ActivityManagerService.java:8083)
at com.android.server.am.ActivityManagerService.wakingUp(ActivityManagerService.java:8077)
at com.android.server.power.Notifier.sendWakeUpBroadcast(Notifier.java:474)
at com.android.server.power.Notifier.sendNextBroadcast(Notifier.java:455)
at com.android.server.power.Notifier.access$700(Notifier.java:62)
at com.android.server.power.Notifier$NotifierHandler.handleMessage(Notifier.java:600)
at android.os.Handler.dispatchMessage(Handler.java:107)
at android.os.Looper.loop(Looper.java:194)
at com.android.server.ServerThread.run(SystemServer.java:1328)
從trace文件看,是因為TID為24的線程等待一個TID為12的線程持有的鎖,TID為12的線程等待一個TID為85的線程持有的鎖,而TID為85的線程確等待一個TID為24的線程持有的鎖,導致了循環等待的現象,對應的trace文件的語句如下:
TID 24:- waiting to lock <0x41a874a0> (a com.android.server.am.ActivityManagerService) held by tid=12 (android.server.ServerThread)
TID 12: - waiting to lock <0x41a7e2e8> (a java.lang.Object) held by tid=85 (Binder_B)
TID 85:- waiting to lock <0x41a7e420> (a com.android.server.power.PowerManagerService$DisplayBlankerImpl) held by tid=24 (PowerManagerService)
既然是死鎖,那麼先看各線程都有那些鎖。
先看TID=24的線程的棧頂,ActivityManagerService的broadcastIntent函數代碼如下:
復制代碼 代碼如下:
public final int broadcastIntent(IApplicationThread caller,
Intent intent, String resolvedType, IIntentReceiver resultTo,
int resultCode, String resultData, Bundle map,
String requiredPermission, boolean serialized, boolean sticky, int userId) {
enforceNotIsolatedCaller("broadcastIntent");
synchronized(this) {
intent = verifyBroadcastLocked(intent);
final ProcessRecord callerApp = getRecordForAppLocked(caller);
final int callingPid = Binder.getCallingPid();
final int callingUid = Binder.getCallingUid();
final long origId = Binder.clearCallingIdentity();
int res = broadcastIntentLocked(callerApp,
callerApp != null ? callerApp.info.packageName : null,
intent, resolvedType, resultTo,
resultCode, resultData, map, requiredPermission, serialized, sticky,
callingPid, callingUid, userId);
Binder.restoreCallingIdentity(origId);
return res;
}

可以看到TID=24需要ActivityManagerService這個鎖。再看TID=12線程的棧頂,PowerManagerService的isScreenOnInternal函數代碼如下:
復制代碼 代碼如下:
private boolean isScreenOnInternal() {
synchronized (mLock) {
return !mSystemReady
|| mDisplayPowerRequest.screenState != DisplayPowerRequest.SCREEN_STATE_OFF;
}
}

可以看到需要PowerManagerService的mlock這個鎖。最後看TID=85線程的棧頂,同樣在PowerManagerService裡面,內部類DisplayBlankerImpl的toString函數:
復制代碼 代碼如下:
public String toString() {
synchronized (this) {
return "blanked=" + mBlanked;
}
}

這是在內部類DisplayBlankerImpl裡面實現的,所以需要DisplayBlankerImpl這個鎖。
對應的表格如下:
 
表一 各線程等待的鎖情況
從表一來看,沒有出現死鎖現象,似乎並不是我們所想的那樣。難道不是死鎖?開始有點小懷疑自己了,難道別的原因導致的。也許只看調用堆棧的頂端可能不行,棧頂只能看出各線程需要的鎖,不能僅看自己要什麼吧!一味索取可不好!人不是這樣做的!看一下整個的堆棧調用流程,看看自己擁有了那些鎖。
跟蹤TID=24線程的堆棧,在PowerManagerService內部類DisplayBlankerImpl的unblankAllDisplays函數中持有鎖:
復制代碼 代碼如下:
public void unblankAllDisplays() {
synchronized (this) {
nativeSetAutoSuspend(false);
nativeSetInteractive(true);
mDisplayManagerService.unblankAllDisplaysFromPowerManager();
mBlanked = false;
///M: add for tvout and hdmi
mTvOut.tvoutPowerEnable(true);
mHDMI.hdmiPowerEnable(true);
///@}
if (DEBUG) {
Slog.d(TAG_P, "unblankAllDisplays out ...");
}
if (mBootCompleted) {
Intent intent = new Intent(ACTION_LOCK_SCREEN_SHOW);
mContext.sendBroadcast(intent);
}
}
}

最後發送廣播的代碼,是我們自己添加的。根據unblankAllDisplays函數和broadcastIntent函數,可以看到TID=24的線程此時持有了DisplayBlankerImpl鎖(unblankAllDisplays),等待ActivityManagerService鎖(broadcastIntent)釋放。
同樣,跟蹤TID=12線程的堆棧,在ActivityManagerService的wake_up函數中持有鎖:
復制代碼 代碼如下:
public void wakingUp() {
if (checkCallingPermission(android.Manifest.permission.DEVICE_POWER)
!= PackageManager.PERMISSION_GRANTED) {
throw new SecurityException("Requires permission "
+ android.Manifest.permission.DEVICE_POWER);
}
synchronized(this) {
Slog.i(TAG, "wakingUp");
mWentToSleep = false;
updateEventDispatchingLocked();
comeOutOfSleepIfNeededLocked();
}
}

根據wakingUp函數和isScreenOnInternal函數,可以看到TID=12的線程持有ActivityManagerService鎖(wakingUp),等待PowerManagerService.mLock鎖(isScreenOnInternal)。到這,似乎看到了希望,迷霧要撥開了,有點小自信是死鎖導致的,但還不能最終下結論。
一鼓作氣,跟蹤TID=85線程的堆棧,在PowerManagerService的dump有持有鎖的操作:
protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
....
synchronized (mLock) {
...
}
根據toString函數和dump函數,可以看到TID=85線程此時持有PowerManagerService.mLock鎖(dump),需要DisplayBlankerImpl(toString)。
似乎謎底已經揭曉了,如果你還沒有看出來(其實我也沒看出來),來個表看看吧!
 
表二 各線程鎖的情況
清楚了嗎?多麼清晰的循環等待呀!死鎖都死的這麼完美,還是圖表效果好,看來有時候在紙上畫畫還是有用的!
  1. 上一頁:
  2. 下一頁:
熱門文章
閱讀排行版
Copyright © Android教程網 All Rights Reserved