Deadlock when closing sqlite database

Question

I'm investigating occassinal ANR in my project. It happens when there are a lot of requests to database in the background, user clicks button and database is being closed as a part of logout. I'm using saferoom and rx-java2.

Here is some code from test project, on which I tried to reproduce issue.(reproduces ~30% of time):

class MainActivity : AppCompatActivity() {

    lateinit var db: TestDb
    private val disposables = CompositeDisposable()

    override fun onCreate(savedInstanceState: Bundle?) {
        super.onCreate(savedInstanceState)
        setContentView(R.layout.activity_main)

        openStorage("password")

        val d = Observable.interval(100, TimeUnit.MICROSECONDS)
            .map { db.testDao().insert(TestEntity()) }
            .subscribeOn(Schedulers.io())
            .observeOn(AndroidSchedulers.mainThread())
            .subscribe({ status.text = "WRITING" }, {})
        disposables.add(d)

        closeDbButton.setOnClickListener {
            disposables.clear()
            db.close()
            status.text = "DB CLOSED"
        }
    }

    @Synchronized
    fun openStorage(storageSecret: String) {
        val factory = SafeHelperFactory(storageSecret.toCharArray())
        db = Room.databaseBuilder(this, TestDb::class.java, TestDb.DATABASE_NAME)
            .openHelperFactory(factory)
            .build()
    }
}

As you can see, to emulate the issue I'm trying to access database in the loop and at the same time closing database. Even though I dispose writing chain before closing, deadlock happens and app freezes.

I also tried to analyse thread dump:

"main" prio=5 tid=1 Waiting
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x727565f0 self=0x7b42cbea00
  | sysTid=24431 nice=-10 cgrp=default sched=0/0 handle=0x7bc78e99a8
  | state=S schedstat=( 3718987857 647207377 6247 ) utm=336 stm=34 core=3 HZ=100
  | stack=0x7fd4c9a000-0x7fd4c9c000 stackSize=8MB
  | held mutexes=
  at java.lang.Object.wait(Native method)
  - waiting on <0x017bb93d> (a java.lang.Object)
  at java.lang.Thread.parkFor$(Thread.java:2137)
  - locked <0x017bb93d> (a java.lang.Object)
  at sun.misc.Unsafe.park(Unsafe.java:358)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:190)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:868)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:900)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1223)
  at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:225)
  at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:286)
  at net.sqlcipher.database.SQLiteDatabase.lock(SQLiteDatabase.java:553)
  at net.sqlcipher.database.SQLiteDatabase.close(SQLiteDatabase.java:1284)
  at net.sqlcipher.database.SQLiteOpenHelper.close(SQLiteOpenHelper.java:272)
  - locked <0x064ca532> (a com.commonsware.cwac.saferoom.Helper$1)
  at com.commonsware.cwac.saferoom.Helper$OpenHelper.close(Helper.java:202)
  - locked <0x064ca532> (a com.commonsware.cwac.saferoom.Helper$1)
  at com.commonsware.cwac.saferoom.Helper.close(Helper.java:146)
  at androidx.room.RoomDatabase.close(RoomDatabase.java:189)
  at com.company.deadlocktest.MainActivity$onCreate$1.onClick(MainActivity.kt:38)
  at android.view.View.performClick(View.java:6294)
  at android.view.View$PerformClick.run(View.java:24770)
  at android.os.Handler.handleCallback(Handler.java:790)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:164)
  at android.app.ActivityThread.main(ActivityThread.java:6494)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)


"RxComputationThreadPool-1" daemon prio=5 tid=15 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x12fc0610 self=0x7b3a839c00
  | sysTid=24450 nice=0 cgrp=default sched=0/0 handle=0x7b2c5384f0
  | state=S schedstat=( 2462204096 250602566 3746 ) utm=209 stm=36 core=1 HZ=100
  | stack=0x7b2c436000-0x7b2c438000 stackSize=1037KB
  | held mutexes=
  at net.sqlcipher.database.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:-1)
  - waiting to lock <0x064ca532> (a com.commonsware.cwac.saferoom.Helper$1) held by thread 1
  at com.commonsware.cwac.saferoom.Helper$OpenHelper.getWritableSupportDatabase(Helper.java:158)
  at com.commonsware.cwac.saferoom.Helper.getWritableDatabase(Helper.java:120)
  at androidx.room.RoomDatabase.setTransactionSuccessful(RoomDatabase.java:286)
  at com.company.deadlocktest.TestDao_Impl.insert(TestDao_Impl.java:49)
  at com.company.deadlocktest.MainActivity$onCreate$d$1.apply(MainActivity.kt:30)
  at com.company.deadlocktest.MainActivity$onCreate$d$1.apply(MainActivity.kt:18)
  at io.reactivex.internal.operators.observable.ObservableMap$MapObserver.onNext(ObservableMap.java:59)
  at io.reactivex.internal.operators.observable.ObservableInterval$IntervalObserver.run(ObservableInterval.java:83)
  at io.reactivex.internal.schedulers.ScheduledDirectPeriodicTask.run(ScheduledDirectPeriodicTask.java:38)
  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:457)
  at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:307)
  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:302)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
  at java.lang.Thread.run(Thread.java:764)

As you can see Rx thread is blocked by lock, acquired by main thread (<0x064ca532> com.commonsware.cwac.saferoom.Helper$1), and main thread is in WAIT state.

So I'm trying to figure out if there is a way to avoid this issue or this is some kind of bug in saferoom / sqlcipher.

Answer 1

I'm no RxJava expert, but I don't think the threading effects of clear() will happen instantaneously.

In terms of a workaround, don't call close() on the main application thread. Usually, we don't close() at all, as we never know when is a good time, given everything that is going on in the app. If you really want to close(), then do so on the Schedulers.io() thread that you are using for your database access.