Nozbe / WatermelonDB

🍉 Reactive & asynchronous database for powerful React and React Native apps ⚡️
https://watermelondb.dev
MIT License
10.63k stars 602 forks source link

Unsafe Query Raw is extremely slow as it hangs on the last row #1583

Open mfbx9da4 opened 1 year ago

mfbx9da4 commented 1 year ago

I'm using unsafeQueryRaw and it's weirdly slow. I don't see why it is though as it's not too different from a normal query. I've added the following timings:

jsi::Array Database::unsafeQueryRaw(jsi::String &sql, jsi::Array &arguments) {
    // Create a timestamp at the beginning
    auto start = std::chrono::high_resolution_clock::now();

    auto &rt = getRt();
    const std::lock_guard<std::mutex> lock(mutex_);

    std::cout << "beforeExecuteQuery: " << std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now() - start).count() << std::endl;

    auto statement = executeQuery(sql.utf8(rt), arguments);

    std::cout << "executeQuery: " << std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now() - start).count() << std::endl;
    std::vector<jsi::Value> raws = {};

    while (true) {
        if (getNextRowOrTrue(statement.stmt)) {
            break;
        }

        jsi::Object raw = resultDictionary(statement.stmt);
        raws.push_back(std::move(raw));
    }

    std::cout << "Total time: " << std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now() - start).count() << std::endl;

    return arrayFromStd(raws);
}

The output timings in microseconds:

beforeExecuteQuery: 19
executeQuery: 251
Execution time: 986779

Note this query is returning just 367 results and each result looks like this:

{ "start_of_day_timestamp": 1678579200000, "calendar_id": "B72B254B-A431-4660-A075-E0B5E7A47D99" }

There must be something really funky going on for it to take 1 second to serialize 367 JS objects 🤔 .

Note I'm using Hermes and this profiling was done on simulator in debug mode.

Any ideas what to try next @radex? I'll keep digging though.

mfbx9da4 commented 1 year ago

Update, I've discovered that the line which is taking almost one second actually has nothing to do with serializing JS objects, it is in fact

if (getNextRowOrTrue(statement.stmt)) {

On the last iteration it takes 1 second to execute this line 🤯

mfbx9da4 commented 1 year ago

Update it's dependent on the query, see the culprit line in this query below:

WITH tmp AS (
  SELECT 
      e.id, 
      datetime(date(start_at / 1000, 'unixepoch', 'utc'), 'utc') AS start_of_day_timestamp
  FROM events e
  LIMIT 100
)
SELECT 
    e.id, 
    start_of_day_timestamp,
    -- Adding the below line causes the query to hang before returning SQLITE_DONE
    ROW_NUMBER() OVER ( PARTITION BY start_of_day_timestamp ) AS row_num
FROM tmp e;

Toggling the above line will cause sqlite3_step(stmt) to hang for 1 second before returning SQLITE_DONE, running the same query is instant when using a cli / other interface with sqlite so this could still be a watermelon bug

radex commented 1 year ago

There's nothing obviously wrong, so it's going to be hard for me to help or debug without a working reproducible demo.

It's strange that you say that it works instantly elsewhere. I can't rule out a 🍉 bug, but what can also be the difference is:

You can verify that you're using the exact same sqlite version and same configuration to try to narrow down where the issue is.

As for hanging at the last step - I suspect that after getting all rows, some final processing or cleanup is done and that's why you see a hang there. But I'm not sure what exactly it's doing. You can use a native profiler (e.g. Instruments) to get insights into where sqlite is spending its time on.

mfbx9da4 commented 1 year ago

Thanks for your response!

I suspect that after getting all rows, some final processing or cleanup is done

Yeah 💯

You can use a native profiler (e.g. Instruments) to get insights into where sqlite is spending its time on.

🍉 includes sqlite from iOS so when I hit pause I'm inside some arbitrary assembly. I'll have to compile from the amalgamated source.

sqlite configuration done at launch (e.g. WAL mode)

Good idea, I'll try toggling journal_mode and locking_mode.

sqlite version (bug in old sqlite version?)

Unlikely as I'm running on a recent iOS (16)