Androidのアプリ開発でAsyncTaskが実行されない不具合があり、解析した際の解析方法をメモします。
AsyncTaskが実行されない不具合
原因は、AsyncTask（executeOnExecutor(THREAD_POOL_EXECUTOR)）で実行した、タスクの処理が想定していたより多くの時間がかかったことで、poolのthreadが全て実行状態となり、新しいタスクが実行されていませんでした。
解析方法
再現性の低い不具合だったため、発生時のBugreportで解析を行いました。
※やはり、不具合発生時はバグレポートを取っておいた方が良いですね。
下記は、不具合が発生したコードを擬似的に再現したものです。
AsyncTaskのexecuteOnExecutor(THREAD_POOL_EXECUTOR)でタスクを実行していますが、sleepを入れて処理に時間がかかるようにしています。
Sample.kt
Log.d(TAG, "CPU_COUNT : " + Runtime.getRuntime().availableProcessors())
for (i in 1..3) {
val task = object : AsyncTask<Void, Void, Void>() {
override fun doInBackground(vararg params: Void): Void? {
Log.d(TAG, ("doInBackground start " + i))
Thread.sleep(100000)
Log.d(TAG, "doInBackground end " + i)
return null
}
}
task.executeOnExecutor(THREAD_POOL_EXECUTOR)
}
下記は、上記のコードを実行した際のlogcatです。
2020-03-20 19:05:08.828 10486-10486/com.ykato.sample D/MainActivity: CPU_COUNT : 2
2020-03-20 19:05:08.839 10486-11079/com.ykato.sample D/MainActivity: doInBackground start 1
2020-03-20 19:05:08.841 10486-11080/com.ykato.sample D/MainActivity: doInBackground start 2
2020-03-20 19:06:48.848 10486-11080/com.ykato.sample D/MainActivity: doInBackground end 2
2020-03-20 19:06:48.849 10486-11080/com.ykato.sample D/MainActivity: doInBackground start 3
2020-03-20 19:06:48.874 10486-11079/com.ykato.sample D/MainActivity: doInBackground end 1
2020-03-20 19:08:28.862 10486-11080/com.ykato.sample D/MainActivity: doInBackground end 3
CPU数が２の環境で実行したため、thread poolサイズが2となります。
※thread poolサイズはこちらを参照してください。
そのため、タスク３の実行が待たされてしまいます。
タスク３が待たされている間に取得したBugreportのスタック トレースは下記のようになっています。
プロセスID10486のスレッドID11079、11080が実行中であることが分かります。
また、どこで止まっているかも分かります。
MainActivity$onCreate$task$1.doInBackground(MainActivity.kt:21)
------ VM TRACES JUST NOW (/data/anr/dumptrace_64OkJO: 2020-03-20 19:05:26) ------
〜〜省略〜〜
----- pid 10486 at 2020-03-20 19:05:25 -----
Cmd line: com.ykato.sample
〜〜省略〜〜
"AsyncTask #1" prio=5 tid=16 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x12f4a558 self=0xd0186600
| sysTid=11079 nice=10 cgrp=default sched=0/0 handle=0xce41a970
| state=S schedstat=( 928855 3381136 1 ) utm=0 stm=0 core=0 HZ=100
| stack=0xce317000-0xce319000 stackSize=1042KB
| held mutexes=
at java.lang.Thread.sleep(Native method)
- sleeping on <0x0b069882> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:373)
- locked <0x0b069882> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:314)
at com.ykato.sample.MainActivity$onCreate$task$1.doInBackground(MainActivity.kt:21)
at com.ykato.sample.MainActivity$onCreate$task$1.doInBackground(MainActivity.kt:18)
at android.os.AsyncTask$2.call(AsyncTask.java:333)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:764)
"AsyncTask #2" prio=5 tid=17 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x12f4a778 self=0xd0186c00
| sysTid=11080 nice=10 cgrp=default sched=0/0 handle=0xce314970
| state=S schedstat=( 298657 4820846 1 ) utm=0 stm=0 core=1 HZ=100
| stack=0xce211000-0xce213000 stackSize=1042KB
| held mutexes=
at java.lang.Thread.sleep(Native method)
- sleeping on <0x0ad2bb93> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:373)
- locked <0x0ad2bb93> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:314)
at com.ykato.sample.MainActivity$onCreate$task$1.doInBackground(MainActivity.kt:21)
at com.ykato.sample.MainActivity$onCreate$task$1.doInBackground(MainActivity.kt:18)
at android.os.AsyncTask$2.call(AsyncTask.java:333)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:764)
補足
今回は、Bugreportから原因が判明しましたが、Bugreportは取るタイミングによって結果が変わるので、threadの処理にはlogを入れておいた方が良いですね。