GRDB 5.26.0 cost more time on value Observation

[karthuszY]

What did you do?

I update GRDB from 5.24.0 to 5.26.0. And then I feel my App got not smooth.

What did you expect to happen?

What happened instead?

Environment

GRDB flavor(s): GRDB.swift/SQLCiphe
GRDB version: 5.26.0
Installation method: pod 'GRDB.swift/SQLCipher', :git => 'git@github.com:groue/GRDB.swift.git'
Xcode version: Version 13.0 (13A233)
Swift version: Swift 5
Platform(s) running GRDB: iOS
macOS version running Xcode: 12.0.1 (21A559)

Related

GRDB 5.24.0 open cost：

GRDB 5.26.0 open cost：

[groue]

Hello @karthuszY,

Do you happen to use a DatabaseQueue, or DatabasePool?

Also, I won't be able to look at the issue until mid of August. Meanwhile, it would be useful if you would extend the issue with enough detail so that it is possible to reproduce the problem.

[karthuszY]

I use DatabasePool.
Every ValueObservation.tracking I use costs more time than the old version of GRDB.

Here is the code:

        appInfoCancelable?.cancel()
        chainInfoCancelable?.cancel()
        
        let appInfoObserveation = ValueObservation.tracking(AppInfoModel
                                                                .filter(AppInfoModel.Columns.id == appId)
                                                                .fetchOne)
        appInfoCancelable = appInfoObserveation.start(in: db,
                                                      scheduling: .immediate) { error in
            
        } onChange: { [weak self] appInfo in
       
        }
        
        let chainInfoObserveation = ValueObservation.tracking(ChainInfoModel.fetchAll(_:))
        chainInfoCancelable = chainInfoObserveation.start(in: db,
                                                          scheduling: .immediate,
                                                          onError: { error in
            
        }, onChange: { [weak self] _ in
        })

[groue]

Hello @karthuszY,

I can't reproduce any significant performance difference. Is it possible for you to setup a minimal sample project?

[groue]

No news is good news! Feel free to reopen when it is possible to provide some more detailed feedback :)

[rpassis]

FWIW this is actually a problem we are also experiencing when updating from 5.25.0 to 5.26.1 (also using DatabasePool).
I changed it DatabaseQueue and the problem goes away. We narrowed it down to this PR.

I'll try and get a minimum reproducible and also see if we can figure out exactly what's going on.

[groue]

This will be greatly appreciated, @rpassis 👍

[rpassis]

Hi @groue just a quick update that I don't have a reproducible example yet but have been able to capture a bit more information that might be helpful in debugging this.

Firstly, I can only reproduce this when using SQLCipher alongside a DatabasePool configured with a passphrase i.e.

config.prepareDatabase { db in
    try db.usePassphrase(passphraseData)
}

It looks like while ValueObservation tracking is running, a computationally expensive operation is blocking the main thread. In our case this usually lasts several seconds and the UI remains non-responsive. I was able to capture the stack trace below while the main thread was blocked:

I'll keep digging and will update this thread with any new findings.

Thank you!
Rog

[groue]

It looks like while ValueObservation tracking is running, a computationally expensive operation is blocking the main thread.

ValueObservation only performs database operations on the main thread if the application instructs it to do so by starting the observation with the .immediate scheduling (see ValueObservation Scheduling).

When database operations are slow, this blocks the main thread for a noticeable delay. I hope it's clear that there is no magic here: to notify its initial value, ValueObservation can't be faster than the underlying SQLite requests.

To restore UI responsiveness, an application may make the database operations much faster. For example, could the request be enhanced with an index? When the request is very fast, you can keep running it on the main thread: the user won't notice.

Another way to avoid blocking the user interface is to stop performing the slow database operations on the main thread. Don't start the ValueObservation with the .immediate scheduling (which asks for blocking the main thread until the initial value is fetched), and prefer the default scheduling. Values are still notified on the main thread (so you can display them), but SQLite operations are not performed on the main thread (so that the app remains responsive). The app can display a loading screen until the first value is notified.

---

The above paragraphs do not describe a defect or a regression. It is the normal way to deal with ValueObservation: simple and easy .immediate scheduling for fast requests, and default asynchronous scheduling for slow requests (with a loading screen or any other UI until the slow I/O are completed).

In other words, GRDB can't be faster than SQLite/SQLCipher.

If this GitHub issue describes an actual GRDB performance regression, then I'm very curious to learn about it. But it is important to be focused on actual GRDB operations, not SQLite ones. I understand it is not easy, and I'm very thankful for the time spent.

[rpassis]

I think what you said above all makes sense however what I can't make sense of is why this behaviour is not present under 5.25.0 but is pretty evident starting with 5.26.0.

[groue]

What about profiling your app with Instruments.app, and looking for the GRDB api that starts performing worse? You could even share actual profiling information.

Hint: focus on the time spent inside ValueObservation.start

[groue]

With Instruments, you could see what is slow. In the screenshot below, ValueObservation.start is so fast that it barely details where time is spent. But in your app, you may discover something interesting. If you can, please take a few minutes to understand what you see, in order to reply with some usable information.

[rpassis]

Hi @groue here's a sample of the time profile intrumentation showing the same stack trace as you. You can see the call to ValueObservation.start in this sample takes ~450ms when running with GRDB 5.26.1. Also note the CPU usage peaking at 100%:

When I downgrade it back to 5.25.0 then I start seeing a sample that is more similar to the one you posted above:

I'd be happy to share (privately) the Instruments file that contains both runs if you think it might be helpful, just let me know how to do it.

Thanks again,
Rog

[groue]

I'd be happy to share (privately) the Instruments file that contains both runs if you think it might be helpful, just let me know how to do it.

Your first screenshot shows that quite some time (448ms !!!) is spent while creating a DatabaseSnapshot, totally dominated by SQLCipher.

I'm confident this is the change we were looking for, because GRDB 5.25.0 was using a different technique. 🎉

You're paying a hard price for using SQLCipher 😅

OK, we can reopen the issue. Waiting for SQLCipher up to 0.5 second before you can display the initial value, even without blocking the main thread, is not acceptable.

The enhancement will ship in GRDB 6, not GRDB 5. You may want to plan for an upgrade, especially if you want to beta-test it (which I would greatly appreciate, because I still don't have any recipe for reproducing the performance issue).

Thank you very much for your help so far.