Allow statements to auto close when consumed if no cache

[bcardiff]

Follow up to #194, to play nicer with statement lifecycle.

Before this PR when the result set finish iterating the results the connection was released but the statements no because they were always retained for later. With the option of no caching we need to properly close them. sqlite3 is strict about this but is good for every engine.

I want to add some specs before merging. 🙈

cc: @luislavena, it seems to fix the issue you found. Let me know if you are able to break it ;-)

[luislavena]

Hello @bcardiff, this corrected the exception caused in single-thread, but in multi-thread is now causing invalid memory access.

Changes applied to https://github.com/luislavena/test-crystal-sqlite3-db

diff --git a/shard.lock b/shard.lock
index 60b9e3b..ba33134 100644
--- a/shard.lock
+++ b/shard.lock
@@ -3,7 +3,7 @@ version: 2.0
 shards:
   db: # Overridden
     git: https://github.com/crystal-lang/crystal-db.git
-    version: 0.12.0+git.commit.285e865e3a7b0641dc83ce3505a14f3e8d0a3762
+    version: 0.12.0+git.commit.ad41c258c8beb4b59077c35b989cf5069ab902af
 
   sqlite3:
     git: https://github.com/crystal-lang/crystal-sqlite3.git
diff --git a/shard.override.yml b/shard.override.yml
index 6eb4a17..c70ff20 100644
--- a/shard.override.yml
+++ b/shard.override.yml
@@ -1,4 +1,4 @@
 dependencies:
   db:
     github: crystal-lang/crystal-db
-    branch: master
+    branch: auto-release-statements

Compiled using Alpine docker container as static:

$ shards build server --debug --release --static -Dpreview_mt

Then launched bin/server with the following ENV variables:

$ env CRYSTAL_WORKER=4 DATABASE_URL="sqlite3:data.db?journal_mode=wal&synchronous=normal&busy_timeout=5000&prepared_statements_cache=false" bin/server

(you can generate data.db using bin/generate)

Doing a simple curl works, doing single concurrency with plow or oha also works:

$ plow -c 1 -d 10s http://localhost:8080
Benchmarking http://localhost:8080 for 10s using 1 connection(s).
@ Real-time charts is listening on http://[::]:18888

Summary:
  Elapsed        10s
  Count        68415
    2xx        68415
  RPS       6840.763
  Reads    0.632MB/s
  Writes   0.378MB/s

Statistics    Min     Mean    StdDev    Max  
  Latency    75µs     142µs   348µs   6.91ms 
  RPS       6309.34  6840.64  417.03  7416.77

Latency Percentile:
  P50     P75    P90    P95    P99    P99.9   P99.99 
  107µs  120µs  210µs  235µs  272µs  6.542ms  6.828ms

Latency Histogram:
  107µs    53513  78.22%
  175µs    11630  17.00%
  299µs     3104   4.54%
  5.33ms      64   0.09%
  6.498ms     70   0.10%
  6.66ms      28   0.04%
  6.78ms       5   0.01%
  6.893ms      1   0.00%

But increasing concurrency to 5 crashes the server process:

Using: 'sqlite3:data.db?journal_mode=wal&synchronous=normal&busy_timeout=5000&prepared_statements_cache=false'
Listening on:
- 0.0.0.0:8080
Use Ctrl-C to stop
Invalid memory access (signal 11) at address 0x7f7faae16c38
[0x47d200] ???
[0x47d0b5] ???
[0x97e2ac] ???

(hit submit too soon) 😅

I'm going to try to debug this a bit further and come back with a proper stack trace that is more helpful 😁

Thank you for looking into this.
❤️ ❤️ ❤️

[bcardiff]

I got a "bad parameter or other API misuse" with % ab -c 10 -n 10000 http://127.0.0.1:8080/

% CRYSTAL_WORKER=4 DATABASE_URL="sqlite3:data.db?journal_mode=wal&synchronous=normal&busy_timeout=5000&prepared_statements_cache=false" bin/server
Using: 'sqlite3:data.db?journal_mode=wal&synchronous=normal&busy_timeout=5000&prepared_statements_cache=false'
Listening on:
- 0.0.0.0:8080
Use Ctrl-C to stop
2023-11-12T01:37:02.763790Z  ERROR - http.server: Unhandled exception on HTTP::Handler
bad parameter or other API misuse (SQLite3::Exception)
  from lib/sqlite3/src/sqlite3/statement.cr:81:5 in 'check'
  from lib/sqlite3/src/sqlite3/statement.cr:4:5 in 'initialize'
  from lib/sqlite3/src/sqlite3/statement.cr:2:3 in 'new'
  from lib/sqlite3/src/sqlite3/connection.cr:63:5 in 'build_prepared_statement'
  from lib/db/src/db/connection.cr:58:9 in 'fetch_or_build_prepared_statement'
  from lib/db/src/db/session_methods.cr:58:9 in 'build'
  from lib/db/src/db/pool_prepared_statement.cr:51:16 in 'build_statement'
  from lib/db/src/db/pool_statement.cr:43:22 in 'scalar:args'
  from lib/db/src/db/query_methods.cr:284:7 in 'scalar'
  from src/server.cr:21:5 in 'fetch_age'
  from src/server.cr:14:11 in 'call'
  from /opt/homebrew/Cellar/crystal/1.10.1/share/crystal/src/http/server/request_processor.cr:51:11 in 'process'
  from /opt/homebrew/Cellar/crystal/1.10.1/share/crystal/src/http/server.cr:521:5 in 'handle_client'
  from /opt/homebrew/Cellar/crystal/1.10.1/share/crystal/src/http/server.cr:451:5 in '->'
  from /opt/homebrew/Cellar/crystal/1.10.1/share/crystal/src/fiber.cr:146:11 in 'run'
  from /opt/homebrew/Cellar/crystal/1.10.1/share/crystal/src/fiber.cr:98:34 in '->'

Feels like back to crystal-lang/crystal-sqlite3#87 🤔

[bcardiff]

We need to improve the error handling in sqlite3 for MT. Usage of the connection handler and retrieving the error message needs to be wrapped in a mutex to guarantee soundness of the results.

[bcardiff]

Which might actually fix things entirely. Maybe sqlite3 multi-thread support is good as long as the access to the handler are serialized among threads, which is a requirement for doing things properly.

[bcardiff]

I think sqlite issues are of crystal-sqlite3 even without this PR I can get "bad parameter or other API misuse" or "unable to close due to unfinalized statements or unfinished backups (SQLite3::Exception)" using -Dpreview_mt src/test.cr of your example @luislavena .

I added a couple of specs to ensure the statement lifecycle is accurate regarding the cache and I think this is ready for review. What is going on with sqlite3 seems unrelated, but this PR seems to make them happen more frequently on MT.

Without MT the disable cache seems to work fine with sqlite3 so far.