android 常見宕機問題--log分析
1、程式異常退出 uncaused exception
2、程式強制關閉 Force Closed
(簡稱FC)
3、程式無響應 Application No
Response(簡稱ANR),一般主執行緒超過5秒麼有處理就會ANR4、手動生成進入控制檯輸入:logcat命令即可進行輸出第一部分1、分析工具介紹a、cat /proc/meminfo
顯示基本的記憶體資訊------ MEMORY INFO (/proc/meminfo) ------MemTotal:
285184 kBMemFree: 106360 kBBuffers: 0
kBCached: 60036 kBSwapCached: 0 kBActive:
98160 kBInactive: 49100 kBActive(anon): 87260
kBInactive(anon): 288 kBActive(file): 10900
kBInactive(file): 48812 kBUnevictable: 0 kBMlocked:
0 kBSwapTotal: 0 kBSwapFree: 0
kBDirty: 0 kBWriteback: 0 kBAnonPages:
87240 kBMapped: 26500 kBShmem: 324
kBSlab: 13340 kBSReclaimable: 1672 kBSUnreclaim:
11668 kBKernelStack: 2160 kBPageTables: 5600
kBNFS_Unstable: 0 kBBounce: 0
kBWritebackTmp: 0 kBCommitLimit: 142592
kBCommitted_AS: 1065600 kBVmallocTotal: 417792 kBVmallocUsed:
137700 kBVmallocChunk: 254980
kB重點關注這下面幾個值:MemTotal: 285184 kB
//總計實體記憶體的大小MemFree: 106360 kB //可用記憶體有多少Buffers:
0 kB//磁碟快取記憶體的大小Cached:
60036 kB# freefreetotal used
free shared buffersMem: 285184 178884
106300 0 0Swap: 0 0
0Total: 285184 178884
106300在linux中有這麼一種思想,記憶體不用白不用,因此它儘可能的cache和buffer一些資料,以方便下次使用。但實際上這些記憶體也是可以立刻拿來使用的。所以空閒記憶體=free+buffers+cached=total-used還有幾個命令可使用:/proc/meminfo
機器的記憶體使用資訊/proc/pid/maps pid為程序號,顯示當前程序所佔用的虛擬地址。/proc/pid/statm
程序所佔用的記憶體b、檢視程序資訊------ CPU INFO (top -n 1 -d 1
-m 30 -t) ------能夠實時顯示系統中各個程序的資源佔用狀況,類似於 Windows 的工作管理員c、android提供的一些操作工具------ PROCRANK
(procrank) ------------ PROCMEM (procmem) ------------ SHOWMAP (showmap)
------... 就不一一列舉了,有興趣的朋友可以去看看這此工具的程式碼位於android的
/system/extrasd、虛擬記憶體的檢視工具------ VIRTUAL MEMORY STATS
(/proc/vmstat) ------------ VMALLOC INFO (/proc/vmallocinfo)
------2、時間資訊,也是我們主要分析的資訊格式如下:------ SYSTEM LOG
(logcat -b system -v time -d *:v) ------$:logcat -b system -v time -d
*:v01-02 08:00:02.570 I/SystemServer( 957): Notification
Manager01-02 08:00:02.570 I/SystemServer( 957): Device Storage
Monitor01-02 08:00:02.580 I/SystemServer( 957): Location Manager01-02
08:00:02.580 I/SystemServer( 957): Search Service01-02 08:00:02.590
I/SystemServer( 957): DropBox Service01-02 08:00:02.590 I/SystemServer(
957): Wallpaper Service3、虛擬機器資訊,包括程序的,執行緒的跟蹤資訊,這是用來跟蹤程序和執行緒具體點的好地方
。------ VM TRACES JUST NOW (/data/anr/traces.txt.bugreport:
2011-01-15 16:49:02) ------------ VM TRACES AT LAST ANR
(/data/anr/traces.txt: 2011-01-15 16:49:02) ------格式如下 :-----
pid 1516 at 1970-01-02 08:03:07 -----Cmd line:
com.ipanel.join.appstoreDALVIK THREADS:(mutexes: tll=0 tsl=0
tscl=0 ghl=0 hwl=0 hwll=0)"main" prio=5 tid=1 NATIVE| group="main"
sCount=1 dsCount=0 obj=0x4001f188 self=0xd028| sysTid=1516 nice=0
sched=3/0 cgrp=[fopen-error:2] handle=-1345017744
第二部分
如何分析log資訊1、查詢錯誤資訊的關鍵字眼"error" "failxx" "E/" 等的錯誤資訊將這些問題先行解決掉2、動態庫宕機檢視類似的“Build fingerprint:”這些關鍵字I/DEBUG ( 692): *** *** *** *** *** *** *** *** ***
*** *** *** *** *** *** ***I/DEBUG (
692): Build fingerprint:
'generic/generic/generic:2.3.1/GRH78/eng.userdev-rd6-input.20120221.113348:eng/test-keys'I/DEBUG ( 692): pid: 694, tid: 694 >>>
/system/bin/mediaserver <<<I/DEBUG ( 692): signal 11 (SIGSEGV), code 1
(SEGV_MAPERR), fault addr 00000input module init -->010對於這此資訊,可以檢視動態庫的分析:http://blog.csdn.net/andyhuabing/article/details/70749793、解決java拋異常的問題解決E/UsbObserver( 957):
java.lang.NullPointerExceptionE/UsbObserver( 957): at
com.android.server.UsbObserver.init(UsbObserver.java:131)E/UsbObserver( 957): at
com.android.server.UsbObserver.<init>(UsbObserver.java:65)E/UsbObserver( 957): at
com.android.server.ServerThread.run(SystemServer.java:419)I/SystemServer( 957): UI Mode Manager
Service這個直接找到java程式碼,分析其實現即可解決4、ANR問題搜尋“ANR”關鍵詞,快速定位到關鍵事件資訊 。定位到關鍵的事件資訊如下:I/dalvikvm( 1014): Wrote stack traces to
'/data/anr/traces.txt'I/Process (
957): Sending signal. PID: 1124 SIG: 9E/ActivityManager( 957): ANR in
com.ipanel.join.appstoreE/ActivityManager( 957): Reason: Broadcast of Intent {
act=android.appwidget.action.APPWIDGET_UPDATE
cmp=com.ipanel.join.appstore/.widget.SmallWidget1 (has extras) }E/ActivityManager( 957): Load: 1.57 / 0.38 /
0.13E/ActivityManager( 957): CPU usage
from 6290ms to 0ms ago:E/ActivityManager( 957): 70% 957/system_server: 1.1%
user + 69% kernel / faults: 204 minorE/ActivityManager( 957): 8.7%
1014/com.ipanel.join.home.jelly: 7.7% user + 0.9% kernel / faults: 899
minorE/ActivityManager( 957): 0.3%
687/yaffs-bg-1: 0% user + 0.3% kernelE/ActivityManager( 957): 0.3% 688/yaffs-bg-1: 0% user
+ 0.3% kernelE/ActivityManager( 957):
0.3% 935/irkeyservice: 0% user + 0.3% kernelE/ActivityManager( 957): 0% 890/galcore daemon : 0%
user + 0% kernelE/ActivityManager(
957): 0.1% 1076/com.ipanel.join.browser: 0.1% user + 0%
kernelE/ActivityManager( 957): 0.1%
1124/com.ipanel.join.appstore: 0.1% user + 0% kernelE/ActivityManager( 957): 75% TOTAL: 4.7% user + 70%
kernelE/ActivityManager( 957): CPU
usage from 622ms to 1169ms later:E/ActivityManager( 957): 71% 957/system_server: 0%
user + 71% kernel / faults: 2 minorE/ActivityManager( 957): 67% 965/SurfaceFlinger: 0%
user + 67% kernelE/ActivityManager(
957): 1.9% 973/ActivityManager: 1.9% user + 0% kernelE/ActivityManager( 957): 1.9% 991/CursorMove: 0%
user + 1.9% kernelE/ActivityManager(
957): 7.6% 1014/com.ipanel.join.home.jelly: 7.6% user + 0% kernel / faults:
31 minorE/ActivityManager( 957):
5.7% 1119/Thread-13: 5.7% user + 0% kernelE/ActivityManager( 957): 1.9% 1123/Thread-13: 1.9%
user + 0% kernelE/ActivityManager(
957): 76% TOTAL: 1.8% user + 72% kernel + 1.8% softirq指定哪個java包出問題E/ActivityManager( 957): ANR in
com.ipanel.join.appstore程序號為957發生瞭如下錯誤:com.ipanel.join.appstore 包下面
Broadcast問題ANR原因:E/ActivityManager( 957): Reason: Broadcast of Intent {
act=android.appwidget.action.APPWIDGET_UPDATE
cmp=com.ipanel.join.appstore/.widget.SmallWidget1 (has extras)
}這是ANR的堆疊呼叫檔案I/dalvikvm( 1014): Wrote stack traces to
'/data/anr/traces.txt'通過上面的log資訊分析,應該是接收一個廣播訊息時超時了我們再分析虛擬機器資訊 ,開啟/data/anr/traces.txt,可有通過adb pull
/data/anr/traces.txt .這裡每一段都是一個執行緒
,當然我們還是看執行緒號為1的主執行緒了。通過分析發現關鍵問題是這樣:搜尋“DALVIK THREADS”關鍵詞,快速定位到本應用程式的虛擬機器資訊日誌----- pid 1516
at 1970-01-02 08:03:07 -----Cmd line:
com.ipanel.join.appstoreDALVIK
THREADS:(mutexes: tll=0 tsl=0 tscl=0
ghl=0 hwl=0 hwll=0)"main" prio=5 tid=1
NATIVE| group="main" sCount=1
dsCount=0 obj=0x4001f188 self=0xd028|
sysTid=1516 nice=0 sched=3/0 cgrp=[fopen-error:2]
handle=-1345017744at
org.apache.harmony.luni.platform.OSNetworkSystem.connect(Native
Method)at
dalvik.system.BlockGuard$WrappedNetworkSystem.connect(BlockGuard.java:357)at
org.apache.harmony.luni.net.PlainSocketImpl.connect(PlainSocketImpl.java:204)at
org.apache.harmony.luni.net.PlainSocketImpl.connect(PlainSocketImpl.java:437)at
java.net.Socket.connect(Socket.java:983)at
org.apache.harmony.luni.internal.net.www.protocol.http.HttpConnection.<init>(HttpConnection.java:74)at
org.apache.harmony.luni.internal.net.www.protocol.http.HttpConnection.<init>(HttpConnection.java:48)at
org.apache.harmony.luni.internal.net.www.protocol.http.HttpConnection$Address.connect(HttpConnection.java:298)at
org.apache.harmony.luni.internal.net.www.protocol.http.HttpConnectionPool.get(HttpConnectionPool.java:89)at
org.apache.harmony.luni.internal.net.www.protocol.http.HttpURLConnectionImpl.getHttpConnection(HttpURLConnectionImpl.java:285)at
org.apache.harmony.luni.internal.net.www.protocol.http.HttpURLConnectionImpl.makeConnection(HttpURLConnectionImpl.java:267)at
org.apache.harmony.luni.internal.net.www.protocol.http.HttpURLConnectionImpl.retrieveResponse(HttpURLConnectionImpl.java:1018)at
org.apache.harmony.luni.internal.net.www.protocol.http.HttpURLConnectionImpl.getResponseCode(HttpURLConnectionImpl.java:726)at
com.ipanel.join.appstore.http.DefaultHttpRequest.doGet(DefaultHttpRequest.java:35)at
com.ipanel.join.appstore.widget.AbsSmallWidget.requestApps(AbsSmallWidget.java:117)at
com.ipanel.join.appstore.widget.AbsSmallWidget.getRemoteViews(AbsSmallWidget.java:56)其實從這句話:at
org.apache.harmony.luni.platform.OSNetworkSystem.connect(Native
Method)基本上確認是 socket ->connect
連線超時了,導致主執行緒5s內沒有響應從而產生ANR錯誤。預設的connect連線timeout時間是75s其實解決辦法就是利用非阻塞方式進行連線即可。從CPU佔用率上也可以看出是在kernel中執行堵塞住了E/ActivityManager( 957): 75% TOTAL: 4.7% user + 70%
kernel5、執行DexOpt錯誤W/dalvikvm( 1803): DexOpt: --- END
'SettingsProvider.apk' --- status=0x000a, process failedE/dalvikvm( 1803): Unable to extract+optimize DEX from
'/system/app/SettingsProvider.apk'E/SystemServer( 1803): Failure starting Input Manager
ServiceE/SystemServer( 1803):
java.lang.RuntimeException: Unable to get provider
com.android.providers.settings.SettingsProvider:
java.lang.ClassNotFoundException:
com.android.providers.settings.SettingsProvider in loader
dalvik.system.PathClassLoader[/system/app/SettingsProvider.apk]E/SystemServer( 1803): at
android.app.ActivityThread.installProvider(ActivityThread.java:3557)E/SystemServer( 1803): at
android.app.ActivityThread.getProvider(ActivityThread.java:3356)從上面的列印看,是在解壓或優化extract+optimize
DEX的apk檔案時出錯了1、沒有出現magic
number錯誤,這個原因與原子操作無關(這是一快速的加鎖和解鎖的輕量級操作函式)2、執行dexopt出錯查明是伺服器硬碟沒空間了,導致引導檔案系統的時候沒有空間進行解壓而失敗6、系統啟動後預設其妙或隨機宕機情況出現這種錯誤:12-01
08:11:56.027: WARN/SharedBufferStack(312): waitForCondition(LockCondition) timed
out (identity=19, status=0). CPU may be pegged. trying again.12-01 08:11:57.315: WARN/SharedBufferStack(312):
waitForCondition(LockCondition) timed out (identity=19, status=0). CPU may be
pegged. trying again.12-01
08:11:59.318: WARN/SharedBufferStack(312): waitForCondition(LockCondition) timed
out (identity=19, status=0). CPU may be pegged. trying again.12-01 08:12:03.332: WARN/SharedBufferStack(312):
waitForCondition(LockCondition) timed out (identity=19, status=0). CPU may be
pegged. trying again.12-01
08:12:05.329: WARN/SharedBufferStack(312): waitForCondition(LockCondition) timed
out (identity=19, status=0). CPU may be pegged. trying again.12-01 08:12:07.216: WARN/KeyCharacterMap(312): No
keyboard for id 012-01 08:12:07.216:
WARN/KeyCharacterMap(312): Using default keymap:
/system/usr/keychars/qwerty.kcm.bin
檢視記憶體: cat /proc/meminfo
發現空閒記憶體只剩下幾M空間了。請加大android系統的記憶體即可解決問題
還有一種情況是實現gralloc模組時有死鎖的情況,請查明即可。