見出し画像

RubyのGCがもたらす不思議な挙動とその裏側：ruby-duckdb Issueの解決まで

株式会社Ruby開発

こんにちは。
株式会社 Ruby 開発で社内エンジニアの教育を担当している助田です。

今回は、私が開発している OSS である ruby-duckdb で報告された Issue とその解決に至る道について紹介したいと思います。

突然ですが、クイズです。

GC.start がある場合とない場合で以下の結果はどうなるでしょうか？
（解答はこの記事の最後にあります）

def write_hello
  ofs = File.open('example.txt', 'w')
  ofs.puts "hello"
end

write_hello
GC.start # この行がある場合とない場合で出力はどう変わる？
file = File.open('example.txt', 'r')
puts file.gets # => ?

ruby-duckdb とは

簡単に言うと、 Ruby から DuckDB データベースを操作するためのライブラリです。 Sqlite3 における sqlite3-ruby や、 MySQL における mysql2 , PostgreSQL における pg のようなものです。

ある日報告された Issue

ある日、 以下のIssueが報告されました。
（記事にするにあたり、報告の内容を一部変更しています）

下記コードの（１）と （２）で、タイムスタンプが変わってしまっていて、db.close した後でもデータベースの書き込み処理が終わっていないように思えます。 即座に書き込みを終わらせる方法はありますか？

# example1.rb
require 'duckdb'

temp_file = "#{File.expand_path('.', __dir__)}/data.duckdb"

db = DuckDB::Database.open(temp_file)
con = db.connect

con.query('CREATE TABLE test (id INTEGER)')
con.query('INSERT INTO test VALUES (?), (?)', 1, 2)

con.close
db.close

file_last_saved1 = File.mtime(temp_file) # ファイルの最終更新日時を取得

i = 0
# 無限ループにならないように5000回まで
while file_last_saved1 == File.mtime(temp_file) && i < 5000 
  sleep 0.0001
  i += 1
end
file_last_saved2 = File.mtime(temp_file) # しばらくしてからファイルの最終更新日時を取得

# なぜか file_last_saved1 と file_last_saved2 が異なる => 即座に書き込みを終わらせる方法ある？
p file_last_saved1 # => 2024-11-27 13:18:42.213986983 +0900 (1)
p file_last_saved2 # => 2024-11-27 13:18:42.643766951 +0900 (2)

File.delete(temp_file)

 prepared statement を使わない場合は、タイムスタンプが変わらず、期待通りの動作であることも報告にありました。

# example2.rb
require 'duckdb'

temp_file = "#{File.expand_path('.', __dir__)}/data.duckdb"

db = DuckDB::Database.open(temp_file)
con = db.connect

con.query('CREATE TABLE test (id INTEGER)')
con.query('INSERT INTO test VALUES (1), (2)') # prepared statement を使わない

con.close
db.close

file_last_saved1 = File.mtime(temp_file) # ファイルの最終更新日時を取得
i = 0
# 無限ループにならないように5000回まで
while file_last_saved1 == File.mtime(temp_file) && i < 5000
  sleep 0.0001
  i += 1
end
file_last_saved2 = File.mtime(temp_file) # しばらくしてからファイルの最終更新日時を取得

p file_last_saved1 # => 2024-11-27 13:29:04.677105704 +0900
p file_last_saved2 # => 2024-11-27 13:29:04.677105704 +0900

File.delete(temp_file)

また、追加の情報として、db.close の直後に GC.start を実行すると、この場合もうまく動作していそうだとのことでした。

# example3.rb
require 'duckdb'

temp_file = "#{File.expand_path('.', __dir__)}/data.duckdb"

db = DuckDB::Database.open(temp_file)
con = db.connect

con.query('CREATE TABLE test (id INTEGER)')
con.query('INSERT INTO test VALUES (?), (?)', 1, 2)

con.close
db.close

GC.start # GC.start を実行するとタイムスタンプは変わらない

file_last_saved1 = File.mtime(temp_file) # ファイルの最終更新日時を取得
i = 0
# 無限ループにならないように5000回まで
while file_last_saved1 == File.mtime(temp_file) && i < 5000
  sleep 0.0001
  i += 1
end
file_last_saved2 = File.mtime(temp_file) # しばらくしてからファイルの最終更新日時を取得

p file_last_saved1 # => 2024-11-27 13:24:55.000012998 +0900
p file_last_saved2 # => 2024-11-27 13:24:55.000012998 +0900

File.delete(temp_file)

Prepared Statement の問題

prepared statement を使う場合と使わない場合で挙動が変わるとのことなので、 DuckDB::Connection#query の実装を確認することにしました。
実装は、以下のようになっていました（というか自分が実装したのですが...）。

    def query(sql, *args, **kwargs)
      # query の引数が sql １つだけの場合は、そのまま query_sql を呼ぶ
      return query_sql(sql) if args.empty? && kwargs.empty?

      # query の引数が sql の他にもある場合は、PreparedStatement を使う
      stmt = PreparedStatement.new(self, sql)
      stmt.bind_args(*args, **kwargs)
      stmt.execute
    end

prepared statement を使う場合は、query の引数が2つ以上になるので、 PreparedStatement.new が呼ばれます。

# query の引数が3つ。=> PreparedStatement を使う
con.query('INSERT INTO test VALUES (?), (?)', 1, 2)

duckdb の prepared statement

実は、 ruby-duckdb の PreaparedStatement.new は、C言語レベルの実装で、 duckdb の C-API duckdb_prepare を呼び出しています。 duckdb_prepare を呼び出したら、必ず、 duckdb_destroy_prepare を呼び出す必要があります。

Note that after calling duckdb_prepare, the prepared statement should always be destroyed using duckdb_destroy_prepare, even if the prepare fails.

PreparedStatement.new で、 duckdb_prepare が呼ばれているのですが、 duckdb_destroy_prepare は、どこで呼ばれているのでしょうか？ PreparedStatement オブジェクトが不要になったら、忘れずに、 duckdb_destroy_prepare を呼び出すようにしたかったので、 オブジェクトが GC されるときに、 duckdb_destroy_prepare が呼ばれるように実装していました（GC されるとは、参照されなくなったオブジェクトは不要なので、オブジェクトによって確保していたメモリを解放するという意味です）。

/* prepared_statement.c */
static const rb_data_type_t prepared_statement_data_type = {
    "DuckDB/PreparedStatement",
    {NULL, deallocate, memsize,}, /* PreparedStatement オブジェクトが GC されるときに deallocate 関数が呼ばれる */
    0, 0, RUBY_TYPED_FREE_IMMEDIATELY
};

/* 中略 */

static void deallocate(void *ctx) {
    rubyDuckDBPreparedStatement *p = (rubyDuckDBPreparedStatement *)ctx;
    duckdb_destroy_prepare(&(p->prepared_statement)); /* duckdb_destroy_prepare を呼び出す */
    xfree(p);
}

GC されるタイミング (= duckdb_destroy_prepare が呼ばれるタイミング)

さて、ここで、 もう一度 query メソッドを見てみましょう。

    def query(sql, *args, **kwargs)
      return query_sql(sql) if args.empty? && kwargs.empty?

      # PreparedStatement オブジェクトは、いつ GC される？
      stmt = PreparedStatement.new(self, sql)
      stmt.bind_args(*args, **kwargs)
      stmt.execute
    end

PreparedStatement.new で作られた PreparedStatement オブジェクトは、 stmt というローカル変数に代入されているだけで、query メソッドを抜けた後は、どこからも参照されません。 PreparedStatement オブジェクトは、どのタイミングで GC されるのでしょうか？ 実は、 PreparedStatement オブジェクトは、 query メソッドを抜けた瞬間に GC されるわけではありません。 いつかは必ず GC されますが、どのタイミングで GC されるかは、わからないのです。

  1. PreparedStatement.new が呼ばれたときには、 PreparedStatement オブジェクトが作られて、 duckdb_prepare が呼ばれる。

  2. PreparedStatement.new で作られたオブジェクトが GC されるときには、duckdb_destroy_prepare が必ず呼ばれる。

  3. query メソッドの中では、PreparedStatement.new オブジェクトは、 stmt というローカル変数に代入される。

  4. query メソッドを抜けた後、 PreparedStatement オブジェクトは、どこからも参照されないので、いつかは必ず GC される。

  5. しかし、いつ GC されるかは、わからない。

  6. duckdb_destroy_prepare は、 PreparedStatement オブジェクトが GC されるときに呼ばれるが、いつ GC されるかはわからないので、 duckdb_destroy_prepare が呼ばれるタイミングもわからない。

問題のコードでは何が起っていたのか？

調べてみると、問題のコード（example1.rb）では、 ループの中で PreparedStatement オブジェクトがGCされて、 duckdb_destroy_prepare が呼ばれていることがわかりました。 duckdb_destroy_prepare が呼ばれると、ファイルの最終更新日時が書き変わっているようだと予測しました。

# example1.rb
require 'duckdb'

temp_file = "#{File.expand_path('.', __dir__)}/data.duckdb"

db = DuckDB::Database.open(temp_file)
con = db.connect

con.execute('CREATE TABLE test (id INTEGER)')

# (A) PreparedStatement オブジェクトが作られ duckdb_prepare が呼ばれる
con.execute('INSERT INTO test VALUES (?), (?)', 1, 2)

con.close
db.close

file_last_saved1 = File.mtime(temp_file) # DBクローズ直後にファイルの最終更新日時を取得
i = 0
while file_last_saved1 == File.mtime(temp_file) && i < 5000
  # ループの中で、(A) で作られた PreparedStatement オブジェクトがGCされて
  # duckdb_destroy_prepare が呼ばれ、ファイルの最終更新日時が書き変わる。
  sleep 0.0001
  i += 1
end
file_last_saved2 = File.mtime(temp_file) # ファイルの最終更新日時を取得

# なぜか file_last_saved1 と file_last_saved2 が異なる
p file_last_saved1 # => 2024-11-27 13:18:42.213986983 +0900 (1)
p file_last_saved2 # => 2024-11-27 13:18:42.643766951 +0900 (2)

File.delete(temp_file)

問題が発生しなかったコードは何が違うのか？

問題が発生しなかったコード（example2.rb）では、 prepared statement を使わずに、 con.query を使っていました。PreparedStatement オブジェクトが生成されないため、 duckdb_prepare が呼ばれず、 duckdb_destroy_prepare も呼ぶ必要がないため、問題が発生しませんでした。 また、 GC.start を実行する（example3.rb）と、 GC が即座に実行され、 PreparedStatement オブジェクトが GC され、 duckdb_destroy_prepare が呼ばれるため、問題が発生していませんでした。

解決策

prepared statement が不要になったら、即座に duckdb_destroy_prepare を実行できるようにするために、以下のように修正しました。

C言語レベルでは、以下の修正を行いました。

  1. PreparedStatement#destroy メソッドを追加し、 duckdb_destroy_prepare を Rubyのコードの中で（必要なら）好きなタイミングで呼び出せるようにする。

  2. PreparedStatement オブジェクトが GC されるときに再度  duckdb_destroy_prepare が呼ばれないようにするか、呼ばれても問題ないようにする。

Ruby レベルでは、 ensure を使って query メソッドを以下のように修正しました（実際のコードはもう少し複雑ですが、説明のため簡略化しています）。

    def query(sql, *args, **kwargs)
      return query_sql(sql) if args.empty? && kwargs.empty?

      stmt = PreparedStatement.new(self, sql)
      stmt.bind_args(*args, **kwargs)
      stmt.execute
    ensure
      stmt&.destroy # query メソッドを抜けるときに必ず stmt.destroy を呼び出し、 duckdb_destroy_prepare を実行する
    end

というわけで、無事、問題を解決することができました。

クイズの回答

さて、クイズの回答です。

def write_hello
  ofs = File.open('example.txt', 'w')
  ofs.puts "hello"
end

write_hello
GC.start # この行がある場合とない場合で出力はどう変わる？
file = File.open('example.txt', 'r')
puts file.gets # => ?

write_hello メソッド内で、 File.open で生成される File オブジェクトは、 ofs というローカル変数に代入されているだけで、メソッドを抜けた後は、どこからも参照されないので、いつかは GC されます。 GC される場合は、ファイルに hello と書き込まれ、ファイルがクローズされます。

GC.start がある場合には、 write_hello メソッド内で作られた File.open で作られた File オブジェクトが GC されるので、ファイルに hello と書き込まれてクローズされる。 したがって hello と出力される。 GC.start がない場合は、ファイルオブジェクトが GC されない（場合がある）ので、ファイルに hello と書き込まれず、hello と出力されない（ことがある）。

さいごに

GC 任せにせず、必要なときには、即座にリソースを解放できる手段を提供することも重要だと再認識した出来事でした（正直、 duckdb_destroy_prepare は、必ず呼び出すべきだということは、最初からわかっていたのですが、即座に解放しないといけないケースがあることに気づいてませんでした。また、 ruby-duckdb v1.1.3.0 では、デグレードしていて同じ問題が発生していることに、この記事を書いている途中で気付いてしまいました。 すぐに修正し、 v1.1.3.1 をリリースしました）。
その一方で、Rubyのコードを書いているときに、リソースの解放を気にするのは面倒です。 リソースを解放するコードを書かなくても、GC のタイミングで確実に解放されるようにしておくことも gem 作者としては重要だと考えています。


いいなと思ったら応援しよう！