Sporadic read latencies

[mmzeeman]

Sporadic read latencies

[mmzeeman]

I assumed all functions which open/close and do query processing are io bound, but maybe that is not the case in practice.

I haven't tested this, it was just my best effort assumption.

Having a representative dataset combined with some sort of workload on the node will probably help to improve. 👍

[mmzeeman]

Would it be an idea to use the sample database found here: https://github.com/lerocha/chinook-database/tree/master and get some query timings under some sort of load and check the request times and standard deviation?

[mmzeeman]

I wonder if it could be some kind of caching inside sqlite itself.

I see the increased read latency mostly after a bit of time has passed.

147> timer:tc(esqlite3,q, [Conn, "SELECT id FROM purchases WHERE ((user = 'bernard') AND (((status = 0) OR (status = 2)) OR (status = 1))) ORDER BY creation_ts DESC LIMIT 200015, 5;"]).
{409850,
 ...
148> timer:tc(esqlite3,q, [Conn, "SELECT id FROM purchases WHERE ((user = 'bernard') AND (((status = 0) OR (status = 2)) OR (status = 1))) ORDER BY creation_ts DESC LIMIT 200015, 5;"]).
{204779,
 ...

[mmzeeman]

Indeed... similar behavior

sqlite> .timer ON
sqlite> SELECT id FROM purchases WHERE ((user = 'bernard') AND (((status = 0) OR (status = 2)) OR (status = 1))) ORDER BY creation_ts DESC LIMIT 200015, 5;
  ...
Run Time: real 0.426 user 0.159040 sys 0.048730
sqlite> SELECT id FROM purchases WHERE ((user = 'bernard') AND (((status = 0) OR (status = 2)) OR (status = 1))) ORDER BY creation_ts DESC LIMIT 200015, 5;
   ...
Run Time: real 0.195 user 0.173158 sys 0.021259

[mmzeeman]

It sure is strange. If you set caching to 0 you get similar behavior, with occasional long latencies. So I think it isn't SQLite caching either. It could also be the os level disk cache.

[mmzeeman]

I haven't really done any profiling for things like these.

Do you have a test setup so I can take a look?

Maybe one of the functions of the NIF need a ERL_NIF_DIRTY_JOB_CPU_BOUND or ERL_NIF_DIRTY_JOB_IO_BOUND flag.

[Zabrane]

@mmzeeman Let me prepare a db after anonymizing the data set.

In the meantime, can you please tell me which functions I should test (ERL_NIF_DIRTY_JOB_CPU_BOUND + ERL_NIF_DIRTY_JOB_IO_BOUND) first?

[Zabrane]

Hi @mmzeeman

Here you are if you'd like to test it from command line:

$ gunzip slow_db.sqlite.gz
$ sqlite3 ./slow_db.sqlite

Then:

SELECT id FROM purchases WHERE ((user = 'bernard') AND (((status = 0) OR (status = 2)) OR (status = 1))) ORDER BY creation_ts DESC LIMIT 200015, 5;

The database is pretty big (+130MiB uncompressed) and GitHub limits upload to 25MiB.
You can download it from here:
https://we.tl/t-5OuKaSeb8r

Now, the read speed using ESQLite driver and sqlite3 command is pretty much the same in average (~ 190msec), but both suffer from this random latency (~ 340msec).

Let me know if you need anything else.
Thanks

[Zabrane]

Would it be an idea to use the sample database found here: https://github.com/lerocha/chinook-database/tree/master and get some query timings under some sort of load and check the request times and standard deviation?

@mmzeeman Very good idea. Didn't know about chinook database before. Thanks for sharing.

[Zabrane]

@mmzeeman glad you were able to reproduce the timings ;-)

This behavior's puzzling us for more than 2 weeks.
Could it be disk i/o ?

Would be great if we can find out what's causing this.

[Zabrane]

@mmzeeman when trying the DB in RAM only, there is no occasional latencies.
Everything is super stable.

[mmzeeman]

Good to hear. So it is something out of the scope of the sqlite nif.

[Zabrane]

@mmzeeman definitely not a NIF issue.
Keep up the good work and many thanks for your support.