ANR基础

1、ANRbasic knowledge

ANR分类：

KeyDispatch Timeout

ServiceTimeout

BroadcastTimeout

关键词：

eventlog:“am_anr”

trace.txt -java

-native

CPUusage ago

CPUusage later

iowait

“EarlyANR” = The first ANR

2、Howto read Event Log

一些信息没有在logcatlog中而是在eventlog中，查看eventlog对与解决ANR问题很有帮助。

1)eventlog定义:event.logtags

( in code path /system/core/logcat/event.logtags )

( in phone path /system/etc/event-log-tags )

event.logtags:

30008am_anr(pid|1|5),(PackageName|3),(Flags|1|5),(reason|3)

SourceCode ActivityManagerService.java:

EventLog.writeEvent(EventLogTags.AM_ANR,app.pid, app.processName...))

2)LogExample:

I/am_anr ( 1776):[3274,com.sonyericsson.home,572997,keyDispatchingTimedOut]

3)Event: am_anr

system/core/logcat/event.logtags

52004 binder_sample (descriptor|3),(method_num|1|5),(time|1|3),(blocking_package|3),(sample_percent|1|6)

#Application Not Responding

30008am_anr(pid|1|5),(PackageName|3),(Flags|1|5),(reason|3)

I/am_anr ( 1776): [3274,com.sonyericsson.home,572997,keyDispatchingTimedOut]

4)重要的eventlog标志：

db_sample

content_query_sample

content_update_sample

bindersample

dvm_lock_sample

ActivityEvent Series：

am_proc_start

am_restart_activity

am_on_resume_called

am_finish_activity

am_pause_activity

am_on_paused_called

am_destroy_activity

5)Database related：

定义：

52000db_sample(db|3),(sql|3),(time|1|3),(blocking_package|3),(sample_percent|1|6)

#Database operation samples.

#db:数据库文件名

#sql: the executed query (without query args)

#time:cpu time millis (not wall time), including lock acquisition

#blocking_package:if this is on a main thread, the package name, otherwise ""

#sample_percent:the percent likelihood this query was logged (based on 500ms)

sample_percent? If time >= 500ms, then sample_percent show100.

例子1：

I/db_sample(27898):[/data/data/com.facebook.katana/databases/fb.db,INSERT INTOcache(value, timestamp, name) VALUES(?, ?,?);,99,com.facebook.katana,20]

信息解析：

Database:/data/data/com.facebook.katana/databases/fb.db

Sql:INSERT INTO cache(value, timestamp, name) VALUES(?, ?, ?)

Timespent: 99ms

Thisdatabase operation runs in com.facebook.katana main thread.

例子2:

I/db_sample(26092):[/data/data/com.google.android.gm/databases/XX@YY,COMMIT;DELETE FROMmessages WHERE conversation = ? AND synced = ,797,,100]

6)Events : binder_sample

定义：

52004 binder_sample (descriptor|3),(method_num|1|5),(time|1|3),(blocking_package|3),(sample_percent|1|6)

descriptor：接口描述符（任何一个binder都实现一个接口，IPC调用用的API，任何一个接口都有一个描述符，即一个字符串）

method_num：调用的方法的序列号

time：该方法调用耗用的时间(从client端发起到server端完成并返回）

blocking_package：从哪个进程发起的调用

例子：

I/binder_sample( 520):[com.android.internal.telephony.ITelephonyRegistry,7,12518,com.android.phone,100]

含义：从com.android.phone主线程发起了一个ITelephonyRegistry接口的第7个方法的binder调用，耗时12s。

（从后面的源代码可知，系统只记录从主线程发起的binder通讯）

查可知有ITelephonyRegistry.aidl，系统编译后会自动生成ITelephonyRegistry.java文件，里面定义了方法的序号。

out/target/common/obj/JAVA_LIBRARIES/framework_intermediates/src/telephony/java/com/android/internal/telephony/ITelephonyRegistry.java

privatestatic final java.lang.String DESCRIPTOR ="com.android.internal.telephony.ITelephonyRegistry";

staticfinal int TRANSACTION_listen =(android.os.IBinder.FIRST_CALL_TRANSACTION + 0);

staticfinal int TRANSACTION_notifyCallState =(android.os.IBinder.FIRST_CALL_TRANSACTION + 1);

......

staticfinal int TRANSACTION_notifyDataConnection =(android.os.IBinder.FIRST_CALL_TRANSACTION + 7);

由此知第7个方法是notifyDataConnection()

7)Events: dvm_lock_sample

定义：

dvm_lock_sample(process|3),(main|1|5),(thread|3),(time|1|3),(file|3),(line|1|5),(ownerfile|3),(ownerline|1|5),(sample_percent|1|6)

dvm_lock_sample会记录所有线程在java层（即dvm层）获取锁的记录。该log在获取到锁之后输出。

包括：所属进程，是否为主线程，线程名称，获取锁所用的时间，获取锁代码所在的源文件，行号，锁被占有的代码所在的源文件，行号，耗用时间所占比例。

如果ownerfile与file相同，用"-"表示。

Example:

11-2514:14:24.140 I/dvm_lock_sample( 296): [system_server,0,Binder Thread#10,12515,

PackageManagerService.java,1719,-,682,100]

含义：BinderThread #10 ，非主线程，属于system_server进程，获取锁耗用了12s,PackageManagerService.java, line1719获取锁，PackageManagerService.java，line682占用了锁。

3、OOM

Memoryleak will cause ANR. Because when memory is low, normal operationswill be blocked for lack of memory or wait GC to collect memory, thiswill make normal operations taking much more time than before. Lowmemory will cause system into very bad performance, ANR occurrencerate will increase greatly in this condition. You will see many outof memory issues are along with ANR issues.

Ifyou see frequent ANR occurs in short time and system is in OOMcondition. These ANRs often can be ignored. We should put effert onfixing memory leak. When the memory leak is fixed, these ANRs shoulddisappear.

Thereare 2 kinds of OOM. One is OOM in one dvm process. Another is systemoverall memory is not enough.

1)OOMin one dvm process

Oneprocess, one dvm, one GC.

Dvmheap limit in ICS: Change from dalvik.vm.heapsize todalvik.vm.heapgrowthlimit(64Mb now in ginger fuji ICS)

D/dalvikvm( 216): GC_CONCURRENT freed 4443K, 54% free 28546K/61347K, paused4ms+20ms

系统为进程216分配了61347K的dvmheap，有54%free，分母代表了历史上对Heap的最大需求。

D/dalvikvm(3142): GC_BEFORE_OOM freed 10K, 2% free64421K/65571K,paused 258msE/dalvikvm-heap( 3142): Out of memory on a 335888-byteallocation.

2)System overall OOM

Kerneloom killer – when there is no enough memory for allocating.

内核kernellog:

initinvoked oom-killer:gfp_mask=0xd0, order=2, oom_adj=-16, oom_score_adj=-941

[<c010d2ac>](>] (pgd_alloc+0x14/0xe0)

......unwind_backtrace+0x0/0x12c) from [<c021e1b0>](dump_header.clone.1+0xd8/0x22c)

<c021e1b0>](dump_header.clone.1+0xd8/0x22c) from [<c021e344>](oom_kill_process.clone.0+0x40/0x33c)

[<c021e344>](oom_kill_process.clone.0+0x40/0x33c)from [<c021e968>] (out_of_memory+0x328/0x458)

[<c021e968>](out_of_memory+0x328/0x458)from [<c02226a0>] (__alloc_pages_nodemask+0x4a0/0x608)

[<c02226a0>](__alloc_pages_nodemask+0x4a0/0x608)from [<c0222868>] (__get_free_pages+0x10/0x24)

[<c0222868>](__get_free_pages+0x10/0x24)from [<c01130a8

[<c0109720>](sys_fork+0x28/0x2c) from [<c0105dc0>](ret_fast_syscall+0x0/0x30)

……

Outof memory: Kill process 22591 (ckscreen.uxpnxt) score 754 orsacrifice child

Killedprocess 22591 (ckscreen.uxpnxt) total-vm:466932kB, anon-rss:23168kB,file-rss:8396kB

Android Low memory killer – when memory decrease to some value. So, itdoesn’t mean memory is used up.

select1381 (android.browser), adj 7, size 22194, to kill

select18759 (ndroid.crashsms), adj 8, size 7129, to kill

sendsigkill to 18759 (ndroid.crashsms), adj 8, size 7129