AsyncTaskが実行されない不具合の解析

Androidのアプリ開発でAsyncTaskが実行されない不具合があり、解析した際の解析方法をメモします。

## AsyncTaskが実行されない不具合
原因は、AsyncTask（executeOnExecutor(THREAD_POOL_EXECUTOR)）で実行した、タスクの処理が想定していたより多くの時間がかかったことで、poolのthreadが全て実行状態となり、新しいタスクが実行されていませんでした。

## 解析方法
再現性の低い不具合だったため、発生時のBugreportで解析を行いました。
※やはり、不具合発生時は[バグレポート](https://developer.android.com/studio/debug/bug-report?hl=ja)を取っておいた方が良いですね。

下記は、不具合が発生したコードを擬似的に再現したものです。
AsyncTaskのexecuteOnExecutor(THREAD_POOL_EXECUTOR)でタスクを実行していますが、sleepを入れて処理に時間がかかるようにしています。

```kotlin: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サイズは[こちら](https://qiita.com/yoshihiro-kato/items/945455809f60c021acad)を参照してください。
そのため、タスク３の実行が待たされてしまいます。

タスク３が待たされている間に取得した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を入れておいた方が良いですね。