utelle / wxsqlite3

wxSQLite3 - SQLite3 database wrapper for wxWidgets (including SQLite3 encryption extension)
http://utelle.github.io/wxsqlite3
Other
589 stars 178 forks source link

ExecuteQuery very slow #71

Closed Natulux closed 5 years ago

Natulux commented 5 years ago

Hi. I am using wxSQLite 3.0.0 to send a query to my (local) database. This used to work without problems. I need a new query now, which takes about 120ms in "DB Browser". But when I use the exact same query in ExecuteQuery, the execution needs about 60000ms and I dont knwo why.

Anything jumps to your eye?

` wxString sSQLQueryAnamnese = "SELECT DISTINCT frage, typ, strftime('%Y%m', datum) AS yearmonth, entity.countEntity, grp.countFrage"; sSQLQueryAnamnese << " FROM anamnese,"; sSQLQueryAnamnese << "(SELECT frage AS entity_frage, strftime('%Y%m', datum) AS entity_yearmonth, COUNT(strftime('%Y%m', datum)) AS countEntity FROM anamnese GROUP BY frage, strftime('%Y%m', datum)) AS entity,"; sSQLQueryAnamnese << "(SELECT frage AS grp_frage, COUNT(frage) AS countFrage FROM anamnese GROUP BY grp_frage) AS grp"; sSQLQueryAnamnese << " WHERE yearmonth like entity.entity_yearmonth AND anamnese.frage like entity.entity_frage AND anamnese.frage like grp.grp_frage"; sSQLQueryAnamnese << " ORDER BY frage ASC";

wxSQLite3ResultSet q1 = db.ExecuteQuery(sSQLQueryAnamnese);`

Thanks!

utelle commented 5 years ago

First of all, wxSQLite3 is a thin wrapper around SQLite. That is, it is very unlikely that the wrapper is to blame for the long execution time.

Next, do you really use wxSQLite 3.0.0. That version is really outdated as it was released in January 2012 and is based on a very old SQLite version (3.7.10). I don't know which SQLite version is used by DB Browser, but the version difference can hardly explain the difference in execution times.

Finally, without seeing the full database schema and without knowing the size of the database it is impossible to determine what might cause the behaviour observed by you. For example, if this query is the very first SQL command executed on the database connection, it could be that SQLite has to build indexes on the fly, and that can take quite some time depending on the database size.

Maybe you could check the execution time of the query if you execute it a second time in the same database connection. If it is much faster the second time, this may indicate that you should create permanent indexes on some of the fields.

One problem I see is the use of function strftime in the GROUP BY clause. This forces SQLite to do a full table scan, because the value of the grouping field has to be computed for every row. However, this would be true also if you execute the query in DB Browser.

Natulux commented 5 years ago

Thank you for your quick answer. In hinsight, I didnt give you enough information.

Next, do you really use wxSQLite 3.0.0. That version is really outdated as it was released in January 2012 and is based on a very old SQLite version (3.7.10). I don't know which SQLite version is used by DB Browser, but the version difference can hardly explain the difference in execution times.

Yes, wxSQLite 3.0.0 is used, as this project is quite old and written with wWidgets 2.9.2, which also is quite old. But as you said, it is unlikely, that this is the cause for a long executiontime like this.

For example, if this query is the very first SQL command executed on the database connection, it could be that SQLite has to build indexes on the fly, and that can take quite some time depending on the database size.

Maybe you could check the execution time of the query if you execute it a second time in the same database connection. If it is much faster the second time, this may indicate that you should create permanent indexes on some of the fields.

This query is the third of its kind, the other queries do about the same for different tables just before this and two small queries are following this. All queries are inside of: wxSQLite3Transaction t(&db); //all the queries t.Commit();

One problem I see is the use of function strftime in the GROUP BY clause. This forces SQLite to do a full table scan, because the value of the grouping field has to be computed for every row. However, this would be true also if you execute the query in DB Browser.

I can see that this is taking some time and I don't know yet if I would be faster, doing the grouping on the C++ side, but usually I felt that a bigger SQLite query is faster. On the other hand, test database I use is just 64 KB with some hundred entries and that shouldnt break the queries, I guess.

I guess I could test the query with a newer version. Also, I could split the wxSQLite3Transaction in parts, if there is maybe a buffer overflow or something like this..?

[EDIT]: Splitting wxSQLite3Transaction has no effect. I tried the problematic query and also the whole function execution all queries in another app, which uses wxSQLite 4.0.3 and wxWidgets 3.1.1. It was considerably faster with 35s instead of 60s, but still - no comparison to DB Browser with 0,12s. I guess this means I can not execute the query like this.

utelle commented 5 years ago

Yes, wxSQLite 3.0.0 is used, as this project is quite old and written with wWidgets 2.9.2, which also is quite old.

At least I would recommend to upgrade to wxSQLite3 version 3.5.9 in this case. Although I doubt that this will solve the issue.

This query is the third of its kind, the other queries do about the same for different tables just before this and two small queries are following this.

Queries on different tables won't change anything. If the problem is related to creating indexes or to caching data, only repeating the very same query would reveal this. So, for testing purposes you could duplicate the code for the query execution and measure the time required for each execution.

All queries are inside of: wxSQLite3Transaction t(&db); //all the queries t.Commit();

I don't think that transactions have a noteworthy impact on the execution time in this case.

I can see that this is taking some time and I don't know yet if I would be faster, doing the grouping on the C++ side, but usually I felt that a bigger SQLite query is faster.

Doing the grouping in SQL is usually better/faster than doing it in C++. And at the moment it is still unclear what causes the extreme long execution time.

I tried the problematic query and also the whole function execution all queries in another app, which uses wxSQLite 4.0.3 and wxWidgets 3.1.1. It was considerably faster with 35s instead of 60s, but still - no comparison to DB Browser with 0,12s.

A difference by a factor of 300 to 500 is really strange. Could you provide for testing purposes a sample database file which exhibits this behaviour?

Another test you could perform would be to use the SQLite shell application and to measure the execution time of the query in the shell.

Natulux commented 5 years ago

Queries on different tables won't change anything. If the problem is related to creating indexes or to caching data, only repeating the very same query would reveal this. So, for testing purposes you could duplicate the code for the query execution and measure the time required for each execution.

I see. I did as you said. wxStopWatch reports: query1: 5833l ms query2: 5807l ms

In this case, it actually was faster - about 260ms.

I don't think that transactions have a noteworthy impact on the execution time in this case.

My tests support that oppinion.

Doing the grouping in SQL is usually better/faster than doing it in C++. And at the moment it is still unclear what causes the extreme long execution time.

The other queries I mentioned also do GROUP BY combined with COUNT and they are quite fast, e.g.: wxString sSQLQueryDoc = "SELECT DISTINCT description, substr(datum, 1, 6) AS yearmonth, appversion, entity.countEntity, grp.countDescription"; sSQLQueryDoc << " FROM archiv"; sSQLQueryDoc << ", (SELECT description AS entity_description, substr(datum, 1, 6) AS entity_yearmonth, COUNT(substr(datum, 1, 6)) AS countEntity FROM archiv GROUP BY description, substr(datum, 1, 6)) AS entity"; sSQLQueryDoc << ", (SELECT DISTINCT description AS grp_description, COUNT(description) AS countDescription FROM archiv GROUP BY grp_description) AS grp"; sSQLQueryDoc << " WHERE yearmonth like entity.entity_yearmonth AND archiv.description like entity.entity_description AND archiv.description like grp.grp_description"; sSQLQueryDoc << " ORDER BY description ASC";

The only difference I can see is substr instead of strftime (because the datum is formatted differently). Also, the problematic query has the biggest tables to work with: It returns 184 rows in about 60,000ms, the other queries return about 10 rows each in about 11ms. (compared to DB Browser: 184 in about 120ms, 10 in about 2ms)

A difference by a factor of 300 to 500 is really strange. Could you provide for testing purposes a sample database file which exhibits this behaviour?

Please check your github mail for that.

Another test you could perform would be to use the SQLite shell application and to measure the execution time of the query in the shell.

That could be an option, though Id rather have everything in one place.

utelle commented 5 years ago

I received the sample database. I'll take a look later today.

Another test you could perform would be to use the SQLite shell application and to measure the execution time of the query in the shell.

That could be an option, though Id rather have everything in one place.

This would be just for testing, and would not require more effort than executing the query in DB Browser.

The first step is to find out where the differences in execution time come from: From SQLite itself or from the wrapper (extracting data from the result set). BTW, do you use the 32-bit or 64-bit version of DB Browser?

utelle commented 5 years ago

I made a first quick check using DB Browser and the SQLite shell. For the first query, returning 184 rows, I got essentially the same running times for both tools. The execution time varied for both between 140 ms and 160 ms on repeated executions of the same query.

I will now check the behaviour of the wxSQLite3 wrapper.

utelle commented 5 years ago

I implemented a very simple test using the wxSQLite3 wrapper:

    wxStopWatch sw;
    int testCount = 0;
    wxSQLite3Database dbTest;
    dbTest.Open("daten.db");
    cout << "Time: " << sw.Time() << endl;
    wxSQLite3ResultSet qTest = dbTest.ExecuteQuery("SELECT DISTINCT frage, typ, strftime('%Y%m', datum) AS yearmonth, entity.countEntity, grp.countFrage FROM anamnese, (SELECT frage AS entity_frage, strftime('%Y%m', datum) AS entity_yearmonth, COUNT(strftime('%Y%m', datum)) AS countEntity FROM anamnese GROUP BY frage, strftime('%Y%m', datum)) AS entity, (SELECT frage AS grp_frage, COUNT(frage) AS countFrage FROM anamnese GROUP BY grp_frage) AS grp WHERE yearmonth like entity.entity_yearmonth AND anamnese.frage like entity.entity_frage AND anamnese.frage like grp.grp_frage ORDER BY frage ASC;");
    cout << "Time: " << sw.Time() << endl;
    while (qTest.NextRow())
    {
      ++testCount;
      cout << testCount
           << ": " << (const char*) qTest.GetString(0).mb_str(wxConvUTF8)
           << ", " << (const char*) qTest.GetString(1).mb_str(wxConvUTF8)
           << ", " << (const char*) qTest.GetString(2).mb_str(wxConvUTF8)
           << ", " << (const char*) qTest.GetAsString(3).mb_str(wxConvUTF8)
           << ", " << (const char*) qTest.GetAsString(4).mb_str(wxConvUTF8)
           << endl;
    }
    cout << "Time: " << sw.Time() << endl;
    dbTest.Close();

In debug mode I got the following time values: 10 ms, 110 ms, 427 ms In release mode I got the following time values: 0 ms, 30 ms, 345 ms

The second value designates the actual execution time of the query itself.

That is, the query execution itself is very fast and most effort is spent in retrieving and formatting the data from the result set. However, the execution times are far less than those reported by you.

Could you provide the exact code you use for retrieving the data from the result set?

Natulux commented 5 years ago

This is a little puzzling. I just took this one query which causes the problem and put it in a function (see code at the end). The result log message I get is:

11:33:52: After ExecuteQuery: 3461l ms 11:33:52: Whole Query: 3543l ms

These numbers come from wxWidgets 3.1.1, wxSQLite 4.0.3 project. In the old project, numbers are:

11:43:10: After ExecuteQuery: 5867l ms 11:43:10: Whole Query: 5877l ms

To be honest, it doesnt feel like a minute, maybe like 5 seconds. Maybe the stopwatch gets confused here somehow. But those 5 seconds still feel quite long, compared to the instant felt speed of the function if I simpify the query to:

SELECT frage, typ, strftime('%Y%m', datum) AS yearmonth FROM anamnese ORDER BY frage ASC";

[EDIT:] I dont know why the code tag is applied here. But if you copy the whole thing, the code is still valid. Code:

void DatabaseManager::AddChartDataToJSON() { wxStopWatch sw; sw.Start();

wxString sSQLQueryAnamnese = "SELECT DISTINCT frage, typ, strftime('%Y%m', datum) AS yearmonth, entity.countPerMonth, grp.countFrage"; sSQLQueryAnamnese << " FROM anamnese,"; sSQLQueryAnamnese << "(SELECT frage AS entity_frage, strftime('%Y%m', datum) AS entity_yearmonth, COUNT(strftime('%Y%m', datum)) AS countPerMonth FROM anamnese GROUP BY frage, strftime('%Y%m', datum)) AS entity,"; sSQLQueryAnamnese << "(SELECT frage AS grp_frage, COUNT(frage) AS countFrage FROM anamnese GROUP BY grp_frage) AS grp"; sSQLQueryAnamnese << " WHERE yearmonth like entity.entity_yearmonth AND anamnese.frage like entity.entity_frage AND anamnese.frage like grp.grp_frage"; sSQLQueryAnamnese << " ORDER BY frage ASC";

wxJSONValue jsonValueAnamnese;

try { wxSQLite3ResultSet q1 = db.ExecuteQuery(sSQLQueryAnamnese); wxLogMessage("After ExecuteQuery: %dl ms", sw.Time()); wxString sFrage; wxString sYearMonth; wxJSONValue jsonValuePart;

  while (q1.NextRow())
  {
      if (sFrage != q1.GetAsString("frage"))
      {
          if (sFrage != wxEmptyString)
          {
              jsonValueAnamnese["entities"].Append(jsonValuePart);
              jsonValuePart = wxJSONValue();
          }
          sFrage = q1.GetAsString("frage");
          jsonValuePart["frage"] = sFrage;
          jsonValuePart["typ"] = q1.GetAsString("typ");
          jsonValuePart["countFrage"] = q1.GetAsString("countFrage");
      }

      sYearMonth = q1.GetAsString("yearmonth");
      jsonValuePart["permonth"][sYearMonth]["countPerMonth"] = q1.GetAsString("countPerMonth");
  }

  //letzten Wert auch noch schreiben
  jsonValueAnamnese["entities"].Append(jsonValuePart);
  jsonValuePart = wxJSONValue();

} catch (wxSQLite3Exception& e) { wxString cerr = "Caught: "; cerr << e.GetErrorCode() << ":" << (const char*)(e.GetMessage().mb_str()); wxLogMessage(cerr); }

wxLogMessage("Whole Query: %dl ms", sw.Time()); }

Natulux commented 5 years ago

In debug mode I got the following time values: 10 ms, 110 ms, 427 ms In release mode I got the following time values: 0 ms, 30 ms, 345 ms

I copied your function and applied it to my project in release mode:

Time: 0ms, 5849 ms, 5851 ms

Feels equaly slow and about 5000ms seem about right!

So it is not code per se. Does the compiler matter? The old project runs in vs2008 and the newer project runs in vs2015. Also, I dont have a console project. Instead of cout, I use wxLogMessage, which writes to a textfield and a log-textfile. But the speed is quite slow, even if I log nothing so that isnt the problem.

utelle commented 5 years ago

This is a little puzzling. I just took this one query which causes the problem and put it in a function (see code at the end). The result log message I get is:

11:33:52: After ExecuteQuery: 3461l ms 11:33:52: Whole Query: 3543l ms

These numbers come from wxWidgets 3.1.1, wxSQLite 4.0.3 project. In the old project, numbers are:

11:43:10: After ExecuteQuery: 5867l ms 11:43:10: Whole Query: 5877l ms

To be honest, it doesnt feel like a minute, maybe like 5 seconds. Maybe the stopwatch gets confused here somehow.

The execution time is reported as roughly 6 seconds. The problem lies in your logging code:

wxLogMessage("After ExecuteQuery: %dl ms", sw.Time());

I assume you intended to use the format code %ld for long integers, but you used %dl which appends a lowercase letter L to the output which can be easily misinterpreted as the digit 1.

Nevertheless, you have execution times which are almost 20 times higher than those observed by me. Unfortunately, I have no clue what may cause this behaviour.

If I understand you correctly, the execution times differ only by a factor of 2 between old (VS2008) and new (VS2015) project. So, the newer compiler increases the execution speed, but even the new project shows a rather long execution time.

Could you please show the compiler options used to build your application? (Visual Studio allows to look at the used command line in the properties dialog - Configuration Properties / C/C++ - Command Line.

Natulux commented 5 years ago

I assume you intended to use the format code %ld for long integers, but you used %dl which appends a lowercase letter L to the output which can be easily misinterpreted as the digit 1.

Oh my... good to know that that was just a simple human error xD

Nevertheless, you have execution times which are almost 20 times higher than those observed by me. Unfortunately, I have no clue what may cause this behaviour.

If I understand you correctly, the execution times differ only by a factor of 2 between old (VS2008) and new (VS2015) project. So, the newer compiler increases the execution speed, but even the new project shows a rather long execution time.

Exactly right. I experience the same behaviour between both projects. The build options for the projects are somewhat different. However, both are executed on my Win10x64 machine and both apps are build as x86 (compatibilty), release.

Could you please show the compiler options used to build your application? (Visual Studio allows to look at the used command line in the properties dialog - Configuration Properties / C/C++ - Command Line.

Sure, if you can read that ;-) vs2008, wx292, sqlite300: C++ cmnd line:

/O2 /I ".....\chilkat-9.5.0-x86-vc8\libs" /I ".....\chilkat-9.5.0-x86-vc8\include" /I ".....\lib\vc_lib\mswu" /I ".....\include" /I "." /I ".....\samples" /I "C:\wxsqlite3-3.0.0\include" /D "WIN32" /D "WXMSW" /D "NDEBUG" /D "_UNICODE" /D "_WINDOWS" /D "NOPCH" /D "UNICODE" /FD /EHsc /MD /Fo"vc_mswu\minimal\" /Fd"vc_mswu\minimal.pdb" /W4 /nologo /c /Zi /TP /errorReport:prompt

vs2015, wx311, sqlite403: C++ cmnd line:

/GS /analyze- /W4 /Zc:wchar_t /I".....\lib\vc_lib\mswu" /I".....\include" /I"." /I".....\samples" /I".......\wxsqlite3-4.0.3\include" /I".......\chilkat-9.5.0-x86-vc2015\include" /I"C:\Program Files (x86)\Visual Leak Detector\include" /Zi /Gm- /O2 /Fd"vc_mswu\minimal.pdb" /Zc:inline /fp:precise /D "WIN32" /D "_CRT_SECURE_NO_DEPRECATE=1" /D "_CRT_NON_CONFORMING_SWPRINTFS=1" /D "_SCL_SECURE_NO_WARNINGS=1" /D "WXMSW" /D "NDEBUG" /D "_UNICODE" /D "_WINDOWS" /D "NOPCH" /D "UNICODE" /errorReport:prompt /WX- /Zc:forScope /GR /Gd /Oy- /MT /Fa"vc_mswu\minimal\" /EHsc /nologo /Fo"vc_mswu\minimal\" /Fp"vc_mswu\minimal\infoskop-Client.pch"

Natulux commented 5 years ago

Btw.: I have 6 queries running in this function. With the problematic query simplified (as posted before) and locally analyzed, the function is now executed in 13 ms. This seems efficient enough, alltough I need to test this with a bigger database as well.

But if you'd find anything for the original query, I would test it just for the sake of knowledge. :-)

utelle commented 5 years ago

I compared the compiler options you used for your VS2015 project with mine. Following a list of the noteworthy differences:

Your options My options Remark
MT MD Static vs DLL runtime
O2 Ox Max speed vs full optimization
Oi Enable intrinsic functions

AFAICT the option /Oi is the only one making a runtime difference. However, I tested it in my development environment and the difference in execution time for your query was neglectable.

My testing environment is similar to yours: Windows 10 x64 with x32 binaries.

Sorry, I really don't have the slightest idea what might cause those long execution times on your machine.

However, I just performed another test on a virtual machine where I still have VS2008 installed. The test was based on wxSQLite3 3.1.0 with SQLite 3.7.17 and wxWidgets 2.8.12. And guess what, the execution of your query took roughly 4 seconds. The main difference is that SQLite itself is compiled as a DLL (while recent versions of wxSQLite3 compile SQLite as an integrated part).

This leads me to the question whether your project uses SQLite compiled as a static library or as a DLL. Which options did you use to compile SQLite?

utelle commented 5 years ago

Now, that I could see those long execution times in my environment, I was able to further track down what is going on.

The first observation was that the first execution of the SQLite function sqlite3_step took most of those 4 seconds. That is, the problem lies within the SQLite library, not the wrapper.

The second observation was that the original SQLite DLL was used, that is, the one coming with the SQLite release. Or to be precise: a SQLite version 3.7.17 DLL in my case, while wxSQLite3 3.1.0 was actually based on SQLite version 3.8.4.3. So the next logical step was to force the sample application to use the right SQLite DLL. And now I got execution times similar to those I got with the most recent SQLite version, namely about 50 ms (resp 300 ms for processing the whole result set).

Conclusion: Make sure that your application uses a recent SQLite version.

Natulux commented 5 years ago

Conclusion: Make sure that your application uses a recent SQLite version.

Afaik my wxSQLite compilations used the sqlite versions, that came with them. That is: For the old project: sqlite 3.7.10 as dll For the new project: sqlite 3.23.1 included, static build

So the next logical step was to force the sample application to use the right SQLite DLL

Was the sqlite version you finally used newer than 3.23.1? Because I was able to reproduce this behaviour, albeit less intense, with this version. But according to the SQLite history, 3.23.1 came out 2018-04-10, so there is plenty to upgrade.

utelle commented 5 years ago

While testing with VS2008 I used wxSQLite3 3.1.0 together with SQLite built as DLL. The SQLite 3.7.17 DLL showed long execution times (~ 4 seconds); all other SQLite DLLs showed short execution times - I tested SQLite version 3.8.4.3 (the version which was current when wxSQLite3 3.1.0 was released) and SQLite version 3.29.0 (the most recent version).

You say that you use a static build of SQLite 3.23.1 for your new project. I have absolutely no explanation, why you see long execution times. I was not able to reproduce this behaviour. All my tests with VS2015 and recent versions of wxSQLite3 and SQLite showed the expected short execution times.

Double check that you really link against the right SQLite library.

Natulux commented 5 years ago

Sry, it took me a while. I can partly confirm. I downloaded "sqlite-dll-win32-x86-3290000" for my old project and exchanged the old sqlite3.dll with the new, without changing any code. Result: 32ms instead of ~5000ms

For the new project with wxSqlite3-4.0.3 static build, I tried to make sure, which version of sqlite3 is used. In "wxsqlite3-4.0.3\sqlite3secure\src\sqlite3.rc" I found: FILEVERSION 3,23,1,1 PRODUCTVERSION 3,23,1,1

To be sure, I checked out the newest wxSqlite3 master, first compiled sqlite3lib (vs2015, Release, Win32, /MT) and then compiled wxSqlite as before: Vs2015, Release, x32, /MT Again in "wxsqlite3-4.4.3_pre\sqlite3secure\src\sqlite3.rc" I found: FILEVERSION 3,29,0,0 PRODUCTVERSION 3,29,0,0

Still, for both static builds I had about 3500ms for the same query, that my old project with the new precompiled sqlite3.dll is now able to execute...

utelle commented 5 years ago

I can partly confirm. I downloaded "sqlite-dll-win32-x86-3290000" for my old project and exchanged the old sqlite3.dll with the new, without changing any code. Result: 32ms instead of ~5000ms

With SQLite version 3.8.0 a new query planner was introduced, and I guess that this is the main reason for better performance. I tested your database and query with several recent SQLite versions up to version 3.29.0, and I always got very good performance.

Still, for both static builds I had about 3500ms for the same query, that my old project with the new precompiled sqlite3.dll is now able to execute...

I really don't have any plausible explanation, except that for some obscure reason your application is still using an old SQLite version.

Of course I believe you that you compiled the latest wxSQLite3 version for use with your application. The question is whether your application really uses it for accessing your database file.

Could you please add a call to wxSQLite3Database::GetVersion() to check at runtime which SQLite version is actually used?

Natulux commented 5 years ago

I really don't have any plausible explanation, except that for some obscure reason your application is still using an old SQLite version.

Of course I believe you that you compiled the latest wxSQLite3 version for use with your application. The question is whether your application really uses it for accessing your database file.

Could you please add a call to wxSQLite3Database::GetVersion() to check at runtime which SQLite version is actually used?

As a developer, I understand that you can't just trust that I am as Im saying here. Good thing to have a possibility to check on runtime.

I tested both my compiled versions.

wxSqlite3-4.0.3 static build, wxSQLite3Database::GetVersion( ): => Version: 3.23.1 Query: 3378 ms

wxSqlite3 master static build, wxSQLite3Database::GetVersion( ): => Version: 3.29.0 Query: 3724 ms

EDIT: I'll try a smaller sample project later, to see if the static build is the problem. The sqlite3 version per se is fine, because the dll is working.

utelle commented 5 years ago

As a developer, I understand that you can't just trust that I am as I'm saying here. Good thing to have a possibility to check on runtime.

No offence meant. Often enough I have introduced myself obscure bugs into my own software, convinced I didn't change anything ... except for some small minor modification ... 😅

It is very unlikely that static vs shared build makes the difference, since I tested your database and query successfully with a statically linked SQLite version.

I'm pretty sure that SQLite is to blame for the long execution time, not the wxSQLite3 wrapper. For some reason SQLite treats your query differently - no idea, why. Please do the following to get further information:

Prepend the keyword EXPLAIN (or EXPLAIN QUERY PLAN) to your query and show here the results from an application with short execution time as well as from an application with long execution time. Maybe the query plan can give hints what's going on. See here for details about the EXPLAIN command.

Natulux commented 5 years ago

No offence meant. Often enough I have introduced myself obscure bugs into my own software, convinced I didn't change anything ... except for some small minor modification ... 😅

No offence taken. Same here. "It doesn't work anymore!" "What did you change?" "Nothing!" :D

Prepend the keyword EXPLAIN (or EXPLAIN QUERY PLAN) to your query and show here the results from an application with short execution time as well as from an application with long execution time. Maybe the query plan can give hints what's going on. See here for details about the EXPLAIN command.

Ok. Starting with the long execution time query, 3317ms: 08:22:03: Version: 3.23.1 08:22:03: selectid: 1, order: 0, from: 0, detail: SCAN TABLE anamnese 08:22:03: selectid: 1, order: 0, from: 0, detail: USE TEMP B-TREE FOR GROUP BY 08:22:03: selectid: 2, order: 0, from: 0, detail: SCAN TABLE anamnese 08:22:03: selectid: 2, order: 0, from: 0, detail: USE TEMP B-TREE FOR GROUP BY 08:22:03: selectid: 0, order: 0, from: 0, detail: SCAN TABLE anamnese 08:22:03: selectid: 0, order: 1, from: 1, detail: SCAN SUBQUERY 1 AS entity 08:22:03: selectid: 0, order: 2, from: 2, detail: SCAN SUBQUERY 2 AS grp 08:22:03: selectid: 0, order: 0, from: 0, detail: USE TEMP B-TREE FOR DISTINCT 08:22:03: selectid: 0, order: 0, from: 0, detail: USE TEMP B-TREE FOR ORDER BY

Short execution query, 12ms: 08:47:31: Version: 3.23.1 08:47:31: selectid: 0, order: 0, from: 0, detail: SCAN TABLE anamnese 08:47:31: selectid: 0, order: 0, from: 0, detail: USE TEMP B-TREE FOR DISTINCT 08:47:31: selectid: 0, order: 0, from: 0, detail: USE TEMP B-TREE FOR ORDER BY

(I think the output format has changed, I could get only the detail param here) Newer version, long execution time query, 3705ms: 08:53:45: Version: 3.29.0 09:00:34: selectid: , order: , from: , detail: MATERIALIZE 1 09:00:34: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:00:34: selectid: , order: , from: , detail: USE TEMP B-TREE FOR GROUP BY 09:00:34: selectid: , order: , from: , detail: MATERIALIZE 2 09:00:34: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:00:34: selectid: , order: , from: , detail: USE TEMP B-TREE FOR GROUP BY 09:00:34: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:00:34: selectid: , order: , from: , detail: SCAN SUBQUERY 1 AS entity 09:00:34: selectid: , order: , from: , detail: SCAN SUBQUERY 2 AS grp 09:00:34: selectid: , order: , from: , detail: USE TEMP B-TREE FOR DISTINCT 09:00:34: selectid: , order: , from: , detail: USE TEMP B-TREE FOR ORDER BY

Short execution query, 14ms: 09:02:30: Version: 3.29.0 09:03:32: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:03:32: selectid: , order: , from: , detail: USE TEMP B-TREE FOR DISTINCT 09:03:32: selectid: , order: , from: , detail: USE TEMP B-TREE FOR ORDER BY

Natulux commented 5 years ago

For comparison with a working sample on my hardware: Old project with new dll:

Starting with the query, that took a long time before this dll version, 14ms: 09:15:59: Version: 3.29.0 09:15:59: selectid: , order: , from: , detail: MATERIALIZE 1 09:15:59: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:15:59: selectid: , order: , from: , detail: USE TEMP B-TREE FOR GROUP BY 09:15:59: selectid: , order: , from: , detail: MATERIALIZE 2 09:15:59: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:15:59: selectid: , order: , from: , detail: USE TEMP B-TREE FOR GROUP BY 09:15:59: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:15:59: selectid: , order: , from: , detail: SCAN SUBQUERY 1 AS entity 09:15:59: selectid: , order: , from: , detail: SCAN SUBQUERY 2 AS grp 09:15:59: selectid: , order: , from: , detail: USE TEMP B-TREE FOR DISTINCT 09:15:59: selectid: , order: , from: , detail: USE TEMP B-TREE FOR ORDER BY

Short execution query, 1ms: 09:11:18: Version: 3.29.0 09:11:18: selectid: , order: , from: , detail: SCAN TABLE archiv 09:11:18: selectid: , order: , from: , detail: USE TEMP B-TREE FOR ORDER BY

Natulux commented 5 years ago

I'll try a smaller sample project later, to see if the static build is the problem. The sqlite3 version per se is fine, because the dll is working.

I made a fresh example of wxWidgets311 static build and wxSqlite3-4.0.3 static build and used my classes from the other app to query the same database with the same questionable query.

09:35:48: Version: 3.23.1 09:35:48: After ExecuteQuery: 16 ms 09:35:48: Whole Query: 21

It seems it is only that one app that is still having problems with the execution time.

utelle commented 5 years ago

Ok. Starting with the long execution time query, 3317ms: 08:22:03: Version: 3.23.1 08:22:03: selectid: 1, order: 0, from: 0, detail: SCAN TABLE anamnese 08:22:03: selectid: 1, order: 0, from: 0, detail: USE TEMP B-TREE FOR GROUP BY 08:22:03: selectid: 2, order: 0, from: 0, detail: SCAN TABLE anamnese 08:22:03: selectid: 2, order: 0, from: 0, detail: USE TEMP B-TREE FOR GROUP BY 08:22:03: selectid: 0, order: 0, from: 0, detail: SCAN TABLE anamnese 08:22:03: selectid: 0, order: 1, from: 1, detail: SCAN SUBQUERY 1 AS entity 08:22:03: selectid: 0, order: 2, from: 2, detail: SCAN SUBQUERY 2 AS grp 08:22:03: selectid: 0, order: 0, from: 0, detail: USE TEMP B-TREE FOR DISTINCT 08:22:03: selectid: 0, order: 0, from: 0, detail: USE TEMP B-TREE FOR ORDER BY

In my test environment I get the very same query plan, but short execution time.

Short execution query, 12ms: 08:47:31: Version: 3.23.1 08:47:31: selectid: 0, order: 0, from: 0, detail: SCAN TABLE anamnese 08:47:31: selectid: 0, order: 0, from: 0, detail: USE TEMP B-TREE FOR DISTINCT 08:47:31: selectid: 0, order: 0, from: 0, detail: USE TEMP B-TREE FOR ORDER BY

This is a bit strange, because the query plan is much shorter. Is this really the exact same query as in the previous example? In my test environment I always got essentially the same query plan as your first one.

(I think the output format has changed, I could get only the detail param here) Newer version, long execution time query, 3705ms: 08:53:45: Version: 3.29.0 09:00:34: selectid: , order: , from: , detail: MATERIALIZE 1 09:00:34: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:00:34: selectid: , order: , from: , detail: USE TEMP B-TREE FOR GROUP BY 09:00:34: selectid: , order: , from: , detail: MATERIALIZE 2 09:00:34: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:00:34: selectid: , order: , from: , detail: USE TEMP B-TREE FOR GROUP BY 09:00:34: selectid: , order: , from: , detail: SCAN TABLE anamnese 09:00:34: selectid: , order: , from: , detail: SCAN SUBQUERY 1 AS entity 09:00:34: selectid: , order: , from: , detail: SCAN SUBQUERY 2 AS grp 09:00:34: selectid: , order: , from: , detail: USE TEMP B-TREE FOR DISTINCT 09:00:34: selectid: , order: , from: , detail: USE TEMP B-TREE FOR ORDER BY

Yes, the output format changed, but the query plan steps are exactly the same I get. And that is really puzzling, because I get short execution time.

For an older SQLite version, namely version 3.7.16, I got long execution time, but also a slightly different query plan. For newer versions I couldn't reproduce the long execution times.

I'm running out of ideas ...

Natulux commented 5 years ago

In my test environment I get the very same query plan, but short execution time.

I'm running out of ideas ...

As I've written in my last post: In my little static sample application, I also have short execution times. It is solely this one app that is still having this particular behaviour. Must be some compiler flag or another library that gets in the way..

This is a bit strange, because the query plan is much shorter. Is this really the exact same query as in the previous example? In my test environment I always got essentially the same query plan as your first one.

Sorry to confuse you. This is NOT the same query. I used for every test the large, problem causing query and a shorter non problem causing query for comparison. The query is quite simple, that is why the query plan is also short.

Well, you already found the solution for the app that is supposed to send this query. (new sqlite3 version). The other app also uses wxSqlite3, but no query I use showed this behaviour before. Simpler queries seem to be alright. Not to worry.

Thanks for your time. You have been very helpfull!