💎一站式轻松地调用各大LLM模型接口,支持GPT4、智谱、星火、月之暗面及文生图 广告
#### 15.1.4 响应速度优化和ANR日志分析 响应速度优化的核心思想是避免在主线程中做耗时操作,但是有时候的确有很多耗时操作,怎么办呢?可以将这些耗时操作放在线程中去执行,即采用异步的方式执行耗时操作。响应速度过慢更多地体现在Activity的启动速度上面,如果在主线程中做太多事情,会导致Activity启动时出现黑屏现象,甚至出现ANR。Android规定,Activity如果5秒钟之内无法响应屏幕触摸事件或者键盘输入事件就会出现ANR,而BroadcastReceiver如果10秒钟之内还未执行完操作也会出现ANR。在实际开发中,ANR是很难从代码上发现的,如果在开发过程中遇到了ANR,那么怎么定位问题呢?其实当一个进程发生ANR了以后,系统会在/data/anr目录下创建一个文件traces.txt,通过分析这个文件就能定位出ANR的原因,下面模拟一个ANR的场景。下面的代码在Activity的onCreate中休眠30s,程序运行后持续点击屏幕,应用一定会出现ANR: protected void onCreate(Bundle savedInstanceState) { super.onCreate(savedInstanceState); setContentView(R.layout.activity_main); SystemClock.sleep(30 * 1000); } 这里先假定我们无法从代码中看出ANR,为了分析ANR的原因,可以到处traces文件,如下所示,其中.表示当前目录: adb pull /data/anr/traces.txt . traces文件一般是非常长的,下面是traces文件的部分内容: ----- pid 29395 at 2015-05-31 16:14:36----- Cmd line: com.ryg.chapter_15 DALVIK THREADS: (mutexes: tll=0 tsl=0 tscl=0 ghl=0) "main" prio=5 tid=1 TIMED_WAIT | group="main" sCount=1 dsCount=0 obj=0x4185b700 self=0x4012d0b0 | sysTid=29395 nice=0 sched=0/0 cgrp=apps handle=1073954608 | schedstat=( 0 0 0 ) utm=3 stm=2 core=2 at java.lang.VMThread.sleep(Native Method) at java.lang.Thread.sleep(Thread.java:1031) at java.lang.Thread.sleep(Thread.java:1013) at android.os.SystemClock.sleep(SystemClock.java:114) at com.ryg.chapter_15.MainActivity.onCreate(MainActivity.java:42) at android.app.Activity.performCreate(Activity.java:5086) at android.app.Instrumentation.callActivityOnCreate(Instrumentation. java:1079) at android.app.ActivityThread.performLaunchActivity(ActivityThread. java:2056) at android.app.ActivityThread.handleLaunchActivity(ActivityThread. java:2117) at android.app.ActivityThread.access$600(ActivityThread.java:140) at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1213) at android.os.Handler.dispatchMessage(Handler.java:99) at android.os.Looper.loop(Looper.java:137) at android.app.ActivityThread.main(ActivityThread.java:4914) at java.lang.reflect.Method.invokeNative(Native Method) at java.lang.reflect.Method.invoke(Method.java:511) at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:808) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:575) at dalvik.system.NativeStart.main(Native Method) "Binder_2" prio=5 tid=10 NATIVE | group="main" sCount=1 dsCount=0 obj=0x42296d80 self=0x69068848 | sysTid=29407 nice=0 sched=0/0 cgrp=apps handle=1750664088 | schedstat=( 0 0 0 ) utm=0 stm=0 core=1 #00 pc 0000cc50 /system/lib/libc.so (__ioctl+8) #01 pc 0002816d /system/lib/libc.so (ioctl+16) #02 pc 00016f9d /system/lib/libbinder.so (android::IPCThreadState:: talkWithDriver(bool)+124) #03 pc 0001768f /system/lib/libbinder.so (android::IPCThreadState:: joinThreadPool(bool)+154) #04 pc 0001b4e9 /system/lib/libbinder.so #05 pc 00010f7f /system/lib/libutils.so (android::Thread::_threadLoop (void*)+114) #06 pc 00048ba5 /system/lib/libandroid_runtime.so (android::Android- Runtime::javaThreadShell(void*)+44) #07 pc 00010ae5 /system/lib/libutils.so #08 pc 00012ff0 /system/lib/libc.so (__thread_entry+48) #09 pc 00012748 /system/lib/libc.so (pthread_create+172) at dalvik.system.NativeStart.run(Native Method) 从traces的内容可以看出,主线程直接sleep了,而原因就是MainActivity的42行。第42行刚好就是SystemClock.sleep(30 * 1000),这样一来就可以定位问题了。当然这个例子太直接了,下面再模拟一个稍微复杂点的ANR的例子。 下面的代码也会导致ANR,原因是这样的,在Activity的onCreate中开启了一个线程,在线程中执行testANR(),而testANR()和initView()都被加了同一个锁,为了百分之百让testANR()先获得锁,特意在执行initView()之前让主线程休眠了10ms,这样一来initView()肯定会因为等待testANR()所持有的锁而被同步住,这样就产生了一个稍微复杂些的ANR。这个ANR是很参考意义的,这样的代码很容易在实际开发中出现,尤其是当调用关系比较复杂时,这个时候分析ANR日志就显得异常重要了。下面的代码中虽然已经将耗时操作放在线程中了,按道理就不会出现ANR了,但是仍然要注意子线程和主线程抢占同步锁的情况。 protected void onCreate(Bundle savedInstanceState) { super.onCreate(savedInstanceState); setContentView(R.layout.activity_main); new Thread(new Runnable() { @Override public void run() { testANR(); } }).start(); SystemClock.sleep(10); initView(); } private synchronized void testANR() { SystemClock.sleep(30 * 1000); } private synchronized void initView() { } 为了分析问题,需要从traces文件着手,如下所示。 ----- pid 32662 at 2015-05-31 16:40:21----- Cmd line: com.ryg.chapter_15 DALVIK THREADS: (mutexes: tll=0 tsl=0 tscl=0 ghl=0) "main" prio=5 tid=1 MONITOR | group="main" sCount=1 dsCount=0 obj=0x4185b700 self=0x4012d0b0 | sysTid=32662 nice=0 sched=0/0 cgrp=apps handle=1073954608 | schedstat=( 0 0 0 ) utm=0 stm=4 core=0 at com.ryg.chapter_15.MainActivity.initView(MainActivity.java:~62) - waiting to lock <0x422a0120> (a com.ryg.chapter_15.MainActivity) held by tid=11 (Thread-13248) at com.ryg.chapter_15.MainActivity.onCreate(MainActivity.java:53) at android.app.Activity.performCreate(Activity.java:5086) at android.app.Instrumentation.callActivityOnCreate(Instrumentation. java:1079) at android.app.ActivityThread.performLaunchActivity(ActivityThread. java:2056) at android.app.ActivityThread.handleLaunchActivity(ActivityThread. java:2117) at android.app.ActivityThread.access$600(ActivityThread.java:140) at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1213) at android.os.Handler.dispatchMessage(Handler.java:99) at android.os.Looper.loop(Looper.java:137) at android.app.ActivityThread.main(ActivityThread.java:4914) at java.lang.reflect.Method.invokeNative(Native Method) at java.lang.reflect.Method.invoke(Method.java:511) at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:808) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:575) at dalvik.system.NativeStart.main(Native Method) "Thread-13248" prio=5 tid=11 TIMED_WAIT | group="main" sCount=1 dsCount=0 obj=0x422b0ed8 self=0x683d20c0 | sysTid=32687 nice=0 sched=0/0 cgrp=apps handle=1751804288 | schedstat=( 0 0 0 ) utm=0 stm=0 core=0 at java.lang.VMThread.sleep(Native Method) at java.lang.Thread.sleep(Thread.java:1031) at java.lang.Thread.sleep(Thread.java:1013) at android.os.SystemClock.sleep(SystemClock.java:114) at com.ryg.chapter_15.MainActivity.testANR(MainActivity.java:57) at com.ryg.chapter_15.MainActivity.access$0(MainActivity.java:56) at com.ryg.chapter_15.MainActivity$1.run(MainActivity.java:49) at java.lang.Thread.run(Thread.java:856) 上面的情况稍微复杂一些,需要逐步分析。首先看主线程,如下所示。可以看得出主线程在initView方法中正在等待一个锁<0x422a0120>,这个锁的类型是一个MainActivity对象,并且这个锁已经被线程id为11(即tid=11)的线程持有了,因此需要再看一下线程11的情况。 at com.ryg.chapter_15.MainActivity.initView(MainActivity.java:~62) - waiting to lock <0x422a0120> (a com.ryg.chapter_15.MainActivity) held by tid=11 (Thread-13248) tid是11的线程就是“Thread-13248”,就是它持有了主线程所需的锁,可以看出“Thread-13248”正在sleep, sleep的原因是MainActivity的57行,即testANR方法。这个时候可以发现testANR方法和主线程的initView方法都加了synchronized关键字,表明它们在竞争同一个锁,即当前Activity的对象锁,这样一来ANR的原因就明确了,接着就可以修改代码了。 上面分析了两个ANR的实例,尤其是第二个ANR在实际开发中很容易出现,我们首先要有意识地避免出现ANR,其次出现ANR了也不要着急,通过分析traces文件即可定位问题。