B4J Question Performance problem with SQLite

[Alessandro71]

while investigating on slow response time, I tracked down the issue to this code section

Dim entries As List
entries.Initialize

WriteLog("query start")
Dim rs As ResultSet = DB.ExecQuery2("SELECT DISTINCT carvaluename FROM carvalues WHERE timestamp>=? AND timestamp<=? ORDER BY carvaluename", Array As String(starttimestamp, endtimestamp))
WriteLog("query end")
Do While rs.NextRow
    WriteLog("add record")
    entries.Add(rs.GetString("carvaluename"))
Loop
rs.Close

the first 2 log messagest ("query start" and "query end") are printed in less than a second, while the "add record" lines come rather slowly, about 1 sec apart one another
the whole While loop ends in about 20 seconds, with no noticeable difference between Debug and Release mode

the query returns 21 records from a table (actually a view) with 300000 lines
the same query, when performed in "DB Browser for SQLite" takes about 900ms

from the elapsed time, it looks like every NextRecord call just performs the whole query again

i already run ANALYZE and PRAGMA optimize on the DB with no effect

am i missing something?

 

[Pendrush]

Do you have indexes on carvaluename, timestamp?
How many rows in carvalues?

 

[Alessandro71]

an index problem would affect performance even in "DB Browser for SQLite"
the issue here is that i have a 20x time increase when executed from B4J
as a reference, here is the EXPLAIN QUERY PLAN output

8    0    0    SEARCH TABLE carvaluevalues USING COVERING INDEX sqlite_autoindex_carvaluevalues_1 (timestamp>? AND timestamp<?)
13    0    0    SEARCH TABLE carvaluenames USING INTEGER PRIMARY KEY (rowid=?)
16    0    0    USE TEMP B-TREE FOR DISTINCT

 

[Alessandro71]

and, btw, i have a couple on indexes that do not seem to be used...

CREATE UNIQUE INDEX carvaluenames_carvaluename ON carvaluenames (carvaluename ASC)
CREATE INDEX carvaluevalues_timestamp ON carvaluevalues (timestamp ASC)

 

[Erel]

First step is to switch to ExecQueryAsync: https://www.b4x.com/android/forum/threads/b4x-sql-with-wait-for.79532/#content

Is it still slow?

Make sure to test in release mode.

 

[Alessandro71]

The ExexQuery statement is really fast.
It’s the NextRow loop that is slow.
using async may speed up that?
converting to resumable has some impact on the calling subs…

 

[Erel]

Make a test. Implement it in a different sub for now.

 

[Alessandro71]

First step is to switch to ExecQueryAsync: https://www.b4x.com/android/forum/threads/b4x-sql-with-wait-for.79532/#content

Is it still slow?

Make sure to test in release mode.

here is the async version:

WriteLog("query start")
Dim SenderFilter As Object = DB.ExecQueryAsync("SQL", "SELECT DISTINCT carvaluename FROM carvalues WHERE timestamp>=? AND timestamp<=? ORDER BY carvaluename", Array As String(starttimestamp, endtimestamp))
WriteLog("query end")
Wait For (SenderFilter) SQL_QueryComplete (Success As Boolean, rs As ResultSet)
If Success Then
Do While rs.NextRow
    WriteLog("add record")
    entries.Add(rs.GetString("carvaluename"))
Loop

and 2 executions the first one with the old version, the second one with the async

12:06:56.487    DB: query start
12:06:56.615    DB: query end
12:06:56.615    DB: add record
12:06:56.967    DB: add record
12:06:57.087    DB: add record
12:06:57.208    DB: add record
12:06:58.150    DB: add record
12:06:58.501    DB: add record
12:07:22.214    DB: add record
12:07:22.695    DB: add record
12:07:23.297    DB: add record
12:07:23.421    DB: add record
12:07:23.669    DB: add record
12:07:23.796    DB: add record
12:07:25.345    DB: add record
12:07:25.471    DB: add record
12:07:25.599    DB: add record
12:07:26.204    DB: add record
12:07:26.811    DB: add record
12:07:27.168    DB: add record
12:07:28.491    DB: add record
12:07:28.616    DB: add record
12:07:28.751    DB: add record

async:
12:07:28.752    DB: query start
12:07:28.752    DB: query end
12:07:28.963    DB: add record
12:07:29.342    DB: add record
12:07:29.465    DB: add record
12:07:29.591    DB: add record
12:07:30.575    DB: add record
12:07:30.948    DB: add record
12:07:54.574    DB: add record
12:07:55.045    DB: add record
12:07:55.634    DB: add record
12:07:55.762    DB: add record
12:07:56.001    DB: add record
12:07:56.125    DB: add record
12:07:57.640    DB: add record
12:07:57.769    DB: add record
12:07:57.891    DB: add record
12:07:58.483    DB: add record
12:07:59.081    DB: add record
12:07:59.428    DB: add record
12:08:00.744    DB: add record
12:08:00.865    DB: add record
12:08:00.990    DB: add record

no noticeable difference between the 2 versions

 

[Erel]

Are you using the latest version of the JDBC driver: https://github.com/xerial/sqlite-jdbc/releases ?

 

[OliverA]

Try

Dim entries As List
entries.Initialize

WriteLog("query start")
Dim rs As ResultSet = DB.ExecQuery2("SELECT DISTINCT carvaluename FROM carvalues WHERE timestamp>=? AND timestamp<=? ORDER BY carvaluename", Array As String(starttimestamp, endtimestamp))
WriteLog("query end")

WriteLog("add record start")
Do While rs.NextRow
    entries.Add(rs.GetString("carvaluename"))
Loop
WriteLog("add record stop")

rs.Close

Just to make sure it's not an issue with the WriteLog sub.

 

[Alessandro71]

Just to make sure it's not an issue with the WriteLog sub.

i assure you it's not
it's just a rich Log()

 

[Alessandro71]

Are you using the latest version of the JDBC driver: https://github.com/xerial/sqlite-jdbc/releases ?

    #AdditionalJar: sqlite-jdbc-3.36.0.3

no difference from the builtin jar

 

[Erel]

At this point you need to play with the query to better understand what slows it down. Start with removing the DISTINCT modifier.

 

[Heuristx]

Difficult to say more without the table definition. But:
Is it possible that uncommitted transactions were left open? That ResultSets were not closed? Perhaps another query or Update/Insert stuff going on at the same time?

 

[tchart]

You say it's a view. DBeaver is probably paging the data while you are reading every row.

I would try and execute the raw query from the view rather than accessing the view.

Also have you tried iterating all rows without accessing the data? Is it still slow?

I'd say the problem is not SQLite but probably the way you are querying the data. Like Erel mentioned sometimes some query statements like distinct will perform a full table scan.

 

[Alessandro71]

I will perform some more tests on the query itself, but the basic issue here is that the same query executed in a stand-alone tool like DB Browser for SQLite returns the result in about 1 second, while reading the result set from B4J takes about 30.
as a comparison, the same happens on B4A, I just switched to B4J for testing

 

[Heuristx]

Because DbBrowser doesn't do anything else than execute a query. What ELSE does your program do before this query?

 

[Alessandro71]

I don’t understand the question: the code is the one I posted.
just reading the results after the query

 

[Heuristx]

That code is just a fragment. There must be code before it.

 

[Alessandro71]

It’s just a reporting program, some read-only queries