Skip to content

SQLite step serialization overhead #1175

Closed
@link2xt

Description

@link2xt

I have added the following profiling to f7775f7 (tag v0.5.2):

diff --git a/sqlx-core/src/sqlite/connection/executor.rs b/sqlx-core/src/sqlite/connection/executor.rs
index 6e09fdc2..f7d97c8e 100644
--- a/sqlx-core/src/sqlite/connection/executor.rs
+++ b/sqlx-core/src/sqlite/connection/executor.rs
@@ -125,7 +125,9 @@ impl<'c> Executor<'c> for &'c mut SqliteConnection {
 
                     // invoke [sqlite3_step] on the dedicated worker thread
                     // this will move us forward one row or finish the statement
+                    let time_start = std::time::SystemTime::now();
                     let s = worker.step(*stmt).await?;
+                    println!("worker: {:.3?}", time_start.elapsed().unwrap());
 
                     match s {
                         Either::Left(changes) => {
diff --git a/sqlx-core/src/sqlite/statement/worker.rs b/sqlx-core/src/sqlite/statement/worker.rs
index 8b1d2299..d1a120fa 100644
--- a/sqlx-core/src/sqlite/statement/worker.rs
+++ b/sqlx-core/src/sqlite/statement/worker.rs
@@ -31,7 +31,9 @@ impl StatementWorker {
             for cmd in rx {
                 match cmd {
                     StatementWorkerCommand::Step { statement, tx } => {
+                        let time_start = std::time::SystemTime::now();
                         let status = unsafe { sqlite3_step(statement.0.as_ptr()) };
+                        println!("sqlite3_step: {:.3?}", time_start.elapsed().unwrap());
 
                         let resp = match status {
                             SQLITE_ROW => Ok(Either::Right(())),

Executing a single statement returning multiple rows, I see a large per-row overhead:

sqlite3_step: 1.497ms
worker: 1.786ms
sqlite3_step: 4.250ms
worker: 4.694ms
sqlite3_step: 69.109µs
worker: 219.427µs
sqlite3_step: 183.521µs
worker: 325.917µs
sqlite3_step: 630.797µs
worker: 812.979µs
sqlite3_step: 25.389µs
worker: 130.274µs
sqlite3_step: 1.283ms
worker: 1.545ms
sqlite3_step: 236.185µs
worker: 426.723µs
sqlite3_step: 1.919ms
worker: 2.194ms
sqlite3_step: 381.938µs
worker: 622.630µs
sqlite3_step: 361.922µs
worker: 527.785µs
sqlite3_step: 49.781µs
worker: 155.005µs
sqlite3_step: 24.133µs
worker: 136.689µs
sqlite3_step: 647.297µs
worker: 812.152µs
sqlite3_step: 353.067µs
worker: 558.957µs
sqlite3_step: 415.232µs
worker: 571.597µs
sqlite3_step: 876.746µs
worker: 1.083ms
sqlite3_step: 42.917µs
worker: 177.336µs
sqlite3_step: 19.772µs
worker: 100.709µs
sqlite3_step: 718.207µs
worker: 924.504µs
sqlite3_step: 24.960µs
worker: 150.134µs

Overhead of about 0.1ms per row just to wait for the kernel to give some time to another thread instead of doing sqlite3_step ourselves is a lot and causes a visible performance degradation compared to rusqilte+r2d2: chatmail/core#2353

What is the point of having a separate thread to execute sqlite3_step?

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions