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.

CommonsWare · Answer 1 · 2019-02-15T13:59:37.347

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.

edited Feb 15 '19 at 13:59

answered Feb 15 '19 at 13:35

CommonsWare

986,068
189
2,389
2,491

Thank you for the response! I need to close database as I want it to be inaccessible due to user logout. With your workaround a need to make all database requests from single thread, right? – mol Feb 19 '19 at 07:24
@mol: Yes, or otherwise make sure that nothing is accessing the database at the time that you want to close it. For example, if you initiate a query *after* you close the database, even if both of those things are done on the main application thread, the query will throw an error complaining about a closed database. – CommonsWare Feb 19 '19 at 11:42
It is okay to get an exception if you're trying to access db after closing, but ANR seems like a buggy behaviour to me. And I don't see how it is possible in a production app to access database from a single thread. But thanks anyway. – mol Feb 20 '19 at 07:04

Deadlock when closing sqlite database

1 Answers1