SQLite3::BusyException thrown when busy_timeout is set

[krists]

While working on Rails application which is using SQLite3 I noticed that timeout parameter in database.yml has no effect if pool size is larger than 1.
Application was using Puma in theaded mode and if there were multiple incoming requests one of them succeded and rest got "database is locked" exceptions.

After digging deeper in ActiveRecord SQLite3 adapter i found that timeout config parameter is used in busy_timeout method within SQLite3::Database class.

Here is an example application without ActiveRecord:

require 'bundler/inline'
require "thread"
require "tempfile"

gemfile do
  source 'https://rubygems.org'
  gem 'sqlite3', '1.3.13'
  gem 'pry'
end

puts 'Gems installed and loaded!'
puts "The SQLite3 version #{SQLite3::SQLITE_VERSION}"

begin
  database_path = Tempfile.open("testdb")
  db = SQLite3::Database.new(database_path.path)
  db.transaction do
    db.execute("CREATE TABLE `test_1` (connection_role VARCHAR (255))")
    db.execute("INSERT INTO test_1 VALUES ('main-1')")
  end

  thread = Thread.new do
    begin
      thread_db = SQLite3::Database.new(database_path.path)
      thread_db.transaction(:immediate) do
        puts "puts:bg:1 #{thread_db.execute("SELECT * FROM test_1")}"
        thread_db.execute("INSERT INTO test_1 VALUES ('bg-1')")
        puts "puts:bg:2 #{thread_db.execute("SELECT * FROM test_1")}"
        sleep 2
        thread_db.execute("INSERT INTO test_1 VALUES ('bg-2')")
        puts "puts:bg:3 #{thread_db.execute("SELECT * FROM test_1")}"
      end
      puts "puts:bg:4 transaction closed"
    ensure
      thread_db.close if thread_db
    end
  end

  puts "puts:main:1 #{db.execute("SELECT * FROM test_1")}"

  sleep 1

  puts "puts:main:2 #{db.execute("SELECT * FROM test_1")}"

  db.busy_timeout 3000 # <-- raises: .rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:108:in `step': database is locked (SQLite3::BusyException)

  # busy_handler works as expected
  # db.busy_handler do
  #   true
  # end

  puts "puts:main:3 #{db.execute("SELECT * FROM test_1")}"

  db.execute("INSERT INTO test_1 VALUES ('main-2')")

  puts "puts:main:4 #{db.execute("SELECT * FROM test_1")}"

  thread.join
ensure
  database_path.close
  database_path.unlink
end

It outputs:

Gems installed and loaded!
The SQLite3 version 3.22.0
puts:main:1 [["main-1"]]
puts:bg:1 [["main-1"]]
puts:bg:2 [["main-1"], ["bg-1"]]
puts:main:2 [["main-1"]]
puts:main:3 [["main-1"]]
puts:bg:3 [["main-1"], ["bg-1"], ["bg-2"]]
puts:bg:4 transaction closed
Traceback (most recent call last):
	8: from sqlite3_busy_timeout.rb:54:in `<main>'
	7: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:137:in `execute'
	6: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:95:in `prepare'
	5: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:156:in `block in execute'
	4: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:156:in `to_a'
	3: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:107:in `each'
	2: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:107:in `loop'
	1: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:108:in `block in each'
/home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:108:in `step': database is locked (SQLite3::BusyException)

As the busy_timeout is 3000ms which is larger than total time that thread blocks I was not expecting an error.

If you comment out db.busy_timeout call and uncomment lines below with db.busy_handler you can see that it works as expected - insert statement with value main-2 succeeds.

Is this a bug or I haven't understood how these methods should be used?

[greneholt]

This article explains the issue: http://nerdjusttyped.blogspot.com/2014/11/threaded-sqlite-access-and-ruby-sqlite.html

Summary: the busy_timeout method uses the SQLite internal busy timeout handler to sleep when the database is locked. Unfortunately, on MRI the GIL (global intepreter lock) is not released during these sleep periods, so the other Ruby thread that is locking the database does not advance.

In your example this behavior isn't obvious unless you run it because of the apparent order of the messages. While running it, it is obvious the "bg:3" and "bg:4" messages aren't printed until the exception is being generated (try increasing the timeout to ten seconds or so). This is because the main thread is stuck in a busy timeout inside the SQLite C code, so the background thread can't advance and finish its transaction. Once SQLite in the main thread times out, the background thread has a few moments to finish running, and it somehow manages to print its messages before the backtrace is printed.

My conclusion from this: don't use busy_timeout in the sqlite3-ruby gem with MRI. On JRuby or Rubinious this problem shouldn't occur, as there is no GIL so the background thread should continue advancing even while the main thread is blocked inside SQLite.

[krists]

@greneholt Thank you for the detailed explanation!

[jarthod]

Thanks @greneholt for this great article, I was able to patch my implementation to get some concurrency working again as expected (I'm copying the code here which is for ActiveReccord 7.0.4 as it may help other users and also in case this article goes away as some point):

require 'active_record/connection_adapters/sqlite3_adapter'
# Patch for ActiveReccord 7.0.4 to use ruby sleep instead of C sleep which does not release MRI lock
# http://nerdjusttyped.blogspot.com/2014/11/threaded-sqlite-access-and-ruby-sqlite.html
# Without this the busy timeout isn't really working because other thread are blocked to finish what they were doing
class ActiveRecord::ConnectionAdapters::SQLite3Adapter
  RETRY_INTERVAL = 0.1 # seconds
  private
  def configure_connection
    # default C implementation, commented out
    # @connection.busy_timeout(self.class.type_cast_config_to_integer(@config[:timeout])) if @config[:timeout]
    # replacement ruby implementation
    if @config[:timeout]
      @connection.busy_handler do |count|
        if count * RETRY_INTERVAL > @config[:timeout] / 1000.0
          false
        else
          sleep(RETRY_INTERVAL)
          true
        end
      end
    end
    # unchanged line
    execute("PRAGMA foreign_keys = ON", "SCHEMA")
  end
end

But I am wondering, shouldn't we do something in the gem itself at least for MRI? (like a fallback to ruby sleep or a custom C function which sleeps but also unlocks the GVL). Or are there any good reasons to keep using the blocking C implementation?

Thanks!