ruby sqlite3 解決編

strace + rdbg
into database.c
sqlite3 by C
thread?
予行演習
Debianで実験

strace + rdbg

もうずっとdebianでsqlite3へアクセス出来無い問題に頭を悩ましている。cgi構成ならOK。処理をwebrickの中に閉じ込めるとNG。BSD系は問題無しなんで、わけわかめ。 rubyのdebuggerとして、最初はbyebugを使ってたけど、debug.gemに乗り換えた。そして、少しは頭を使って、straceを繰り出してみた。で結果は、本当に辞書を引いてくれない亊が判明した。

もう少し知恵を絞って、どこで辞書がオープンされるか調べてみたい。こんな時はdebug.gemのリモート機能が便利だ。まあ、gdb世界におけるgdbserverとgdbの組み合わせだな。

当初心配な亊が一つあった。gdbだと、デバックしたいアプリが子プロセスとして動いてしまうんで、それじゃstrace出来無いじゃんと言う亊。この心配はrdbgの場合、杞憂であった。

sakae@pen:/tmp/t$ strace rdbg -O ref.rb |& grep /usr/share/dict
lstat("/usr/share/dict/ejdict.sqlite3", {st_mode=S_IFREG|0644, st_size=6115328, ...}) = 0
openat(AT_FDCWD, "/usr/share/dict/ejdict.sqlite3", O_RDWR|O_CREAT|O_NOFOLLOW|O_CLOEXEC, 0644) = -1 EACCES (Permission denied)
openat(AT_FDCWD, "/usr/share/dict/ejdict.sqlite3", O_RDONLY|O_NOFOLLOW|O_CLOEXEC) = 7
stat("/usr/share/dict/ejdict.sqlite3", {st_mode=S_IFREG|0644, st_size=6115328, ...}) = 0

debug対象を丸ごとstraceしちゃう。straceの結果はstderrに流れてくるので、それに注意して( |& )パイプで受けて、grepする。

sakae@pen:/tmp/t$ rdbg -A
  :
[87, 96] in $(Gem)/sqlite3-1.4.2/lib/sqlite3/database.rb
    87|         end
    88|
    89|         open_v2 file.encode("utf-8"), mode, zvfs
    90|       end
    91|
=>  92|       @tracefunc        = nil
    93|       @authorizer       = nil
    94|       @encoding         = nil
    95|       @busy_handler     = nil
    96|       @collations       = {}
=>#0    SQLite3::Database#initialize(file="/usr/share/dict/ejdict.sqlite3", options={}, zvfs=nil) at $(Gem)/sqlite3-1.4.2/lib/sqlite3/database.rb:92
  #1    [C] Class#new at ref.rb:5
  # and 2 frames (use `bt' command for all frames)
(rdbg:remote) i    # info command
%self = #<SQLite3::Database:0x000055a747334c50>
file = "/usr/share/dict/ejdict.sqlite3"
options = {}
zvfs = nil
mode = 6

rdbgをコントロールする端末をもう一つ用意して(お望みなら前回紹介だけしたchromeでもいいけど)、既に起動させてあるrdbgにアタッチする。後は普通に使えばよい。

上記はデバック対象にcgi相当を選んだ結果だ。 open_v2 を実行した所で、straceから報告が有った。その時のローカル変数を確認してる。rubyはオブジェクト指向なんで、参照透明性が確保されてるか、今一心配だけど、まあ、いいでしょう。

(rdbg:remote) i    # info command
%self = #<SQLite3::Database:0x00007f7e40063630>
file = "/usr/share/dict/ejdict.sqlite3"
options = {}
zvfs = nil
mode = 6

こちらは、デバック対象にgd.rbを選んだ結果だ。straceからもファイルをオープンしたよって報告が無い。但し、環境状況はref.rbの時と一緒だな。

into database.c

open_v2 と言う関数がlibの中に無かったのでextの中を検索。対応を取る定義があって、そこを経由して rb_sqlite3_open_v2 に行くんだな。

sakae@pen:/var/lib/gems/2.7.0/gems/sqlite3-1.4.2/ext/sqlite3$ grep open_v2 *.c
database.c:static VALUE rb_sqlite3_open_v2(VALUE self, VALUE file, VALUE mode, VALUE zvfs)
database.c:      status = sqlite3_open_v2(
database.c:  rb_define_private_method(cSqlite3Database, "open_v2", rb_sqlite3_open_v2, 3);
sqlite3.c:  /* sqlite3_open_v2 flags for Database::new */

核心部分はラッパーだ。

static VALUE rb_sqlite3_open_v2(VALUE self, VALUE file, VALUE mode, VALUE zvfs)
{
  :
      status = sqlite3_open_v2(
          StringValuePtr(file),
          &ctx->db,
          NUM2INT(mode),
          NIL_P(zvfs) ? NULL : StringValuePtr(zvfs)
      );

  CHECK(ctx->db, status)

ここまで分ったら、本物のgdbが使えるかな。

sakae@pen:/tmp/t$ gdb -q ruby
Reading symbols from ruby...
(No debugging symbols found in ruby)
(gdb) b rb_sqlite3_open_v2
Function "rb_sqlite3_open_v2" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 (rb_sqlite3_open_v2) pending.
(gdb) r ref.rb
Starting program: /usr/bin/ruby ref.rb
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Content-type: text/html; charset=UTF-8

Breakpoint 1, rb_sqlite3_open_v2 (self=93824994554920, file=93824994554640,
    mode=13, zvfs=8) at database.c:41
41        Data_Get_Struct(self, sqlite3Ruby, ctx);
(gdb) n
1425        Check_Type(obj, RUBY_T_DATA);
(gdb)
41        Data_Get_Struct(self, sqlite3Ruby, ctx);
(gdb)
1426        return ((struct RData *)obj)->data;
(gdb)
41        Data_Get_Struct(self, sqlite3Ruby, ctx);
(gdb)
52            status = sqlite3_open_v2(
(gdb)
59        CHECK(ctx->db, status)
(gdb) p status
$1 = 0

こちらは、問題版。スレッドで動いてるな。

Thread 6 "server.rb:286" hit Breakpoint 1, rb_sqlite3_open_v2 (
    self=93824998186000, file=93824998185880, mode=13, zvfs=8) at database.c:41
41        Data_Get_Struct(self, sqlite3Ruby, ctx);
(gdb) info th
  Id   Target Id                                        Frame
  1    Thread 0x7ffff7855740 (LWP 1701) "ruby"          0x00007ffff7b828b3 in __GI___select (nfds=7, readfds=0x555555c823e0, writefds=0x0, exceptfds=0x0,
    timeout=0x0) at ../sysdeps/unix/sysv/linux/select.c:41
  3    Thread 0x7ffff38b4700 (LWP 1714) "utils.rb:163"  futex_abstimed_wait_cancelable (private=0, abstime=0x7ffff37b3400, clockid=-210029680, expected=0,
    futex_word=0x7fffec007d54) at ../sysdeps/nptl/futex-internal.h:323
 * 6    Thread 0x7ffff3ab5700 (LWP 1730) "server.rb:286" rb_sqlite3_open_v2 (
    self=93824998186000, file=93824998185880, mode=13, zvfs=8)
    at /usr/include/ruby-2.7.0/ruby/ruby.h:1425
  :
(gdb)
59        CHECK(ctx->db, status)
(gdb) p status
$3 = 0

でも、ちゃんとステータスがZEROの正常でしたってなってるな。

sqlite3 by C

ここまで分ったら、普通にC言語からsqlite3をアクセスする方法を見ておく。

C言語でSQLiteを使う

SQLite覚え書き

Write Programs That Use SQLite

なんか、ruby版のそれと、同等っぽいな。

sqlite3.gemが使っている sqlite3_open_v2 の説明は、新しいデータベース接続を開くに掲載されてた。DBオープンの結果がハンドルに保持されるのね。

データベース接続ハンドルは通常、エラーが発生した場合でも、* ppDbで返されます。
唯一の例外は、SQLiteがsqlite3オブジェクトを保持するメモリを割り当てることができない
場合、SQLite3オブジェクトへのポインタの代わりにNULLが* ppDbに書き込まれることです。
データベースが正常に開かれた（または作成された）場合、SQLITE_OKが返されます。
それ以外の場合は、エラーコードが返されます。

ハンドルって亊は場所の確保だな。それとruby側のスレッドが糸のように絡み付いてくる(だからスレッドって言うのよ)。何か問題になりそうな亊ないかな。

ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [i686-linux] にした時、ソースも残したので、doc/extension.ja.rdoc と言う年代物の資料でも読んでみるか。rubyを始めた頃読んだ記憶があるけど、あの頃はさっぱり理解出来無かったからね。

古い文書と思っていたら、Appendix E. Ractor サポートこんな新しい機能への案内が追加されてた。続きは、extension.rdoc の「Appendix F. Ractor support」ですって。

例にあったのをtest.cとして、普段なら -lsqlite3 ってのを、ソースレベルで混ぜ合せてみた。

sakae@pen:/tmp/s$ cc -g test.c sqlite3.c -lpthread -ldl

そして、gdbね。

(gdb) bt
#0  __libc_open64 (file=0x555555640074 "/tmp/s/db_test.sqlite3", oflag=655426)
    at ../sysdeps/unix/sysv/linux/open64.c:37
#1  0x0000555555568645 in posixOpen (
    zFile=0x555555640074 "/tmp/s/db_test.sqlite3", flags=655426, mode=420)
    at sqlite3.c:34005
#2  0x00005555555689c9 in robust_open (
    z=0x555555640074 "/tmp/s/db_test.sqlite3", f=131138, m=0)
    at sqlite3.c:34314
#3  0x000055555556c5fb in unixOpen (pVfs=0x55555563c900 <aVfs.82>,
    zPath=0x555555640074 "/tmp/s/db_test.sqlite3", pFile=0x55555563ff00,
    flags=262, pOutFlags=0x7fffffffe020) at sqlite3.c:39775
#4  0x000055555555fb51 in sqlite3OsOpen (pVfs=0x55555563c900 <aVfs.82>,
    zPath=0x555555640074 "/tmp/s/db_test.sqlite3", pFile=0x55555563ff00,
    flags=262, pFlagsOut=0x7fffffffe020) at sqlite3.c:23261
#5  0x0000555555574bf6 in sqlite3PagerOpen (pVfs=0x55555563c900 <aVfs.82>,
    ppPager=0x55555563f8c8, zFilename=0x55555563f83c "./db_test.sqlite3",
    nExtra=136, flags=0, vfsFlags=262, xReinit=0x55555557ec0f <pageReinit>)
    at sqlite3.c:56783
#6  0x000055555557f0bf in sqlite3BtreeOpen (pVfs=0x55555563c900 <aVfs.82>,
    zFilename=0x55555563f83c "./db_test.sqlite3", db=0x55555563f308,
    ppBtree=0x55555563f578, flags=0, vfsFlags=262) at sqlite3.c:67209
#7  0x00005555556149ba in openDatabase (
    zFilename=0x555555617004 "./db_test.sqlite3", ppDb=0x7fffffffe350,
    flags=6, zVfs=0x0) at sqlite3.c:165114
#8  0x0000555555614c55 in sqlite3_open (
    zFilename=0x555555617004 "./db_test.sqlite3", ppDb=0x7fffffffe350)
    at sqlite3.c:165228
#9  0x000055555555c423 in main () at test.c:15

ここで、straceにキャッチされるんだな。だから何なのさは下調べ。ああ、sqlite3.cは、rustでsqliteをやった時に、手元に来ていた。 ~/.cargo/registry/src/github.com-1ecc6299db9ec823/sqlite3-src-0.3.0/source/

wc *
      6      19     127 README.md
  21388   78099  654331 shell.c
 231756 1058285 8182289 sqlite3.c
    663    2214   35437 sqlite3ext.h
  12237   86558  583202 sqlite3.h
 266050 1225175 9455386 total

sqlite3.hは、なんだかhtmlぽい雰囲気だな。

thread?

家に唯一あるRuby本を見ていたら、スレッドの光と影なんて紹介が出てた。スレッド超難しいよって亊。それはいいんだけど、気になる亊が書かれていた。

Rubyのスレッド機能の特徴は、制御の流れの切り換えをOSやライブラリィの機能に頼らず、自前で実装している亊です。

昔、一部のユーザーに人気だった青木さん著のRHGでも、採り上げられていたな。でも、今は違うだろう。ちょいと調べてみる。

vbox$ ldd ruby
ruby:
        Start    End      Type  Open Ref GrpRef Name
        1707f000 37091000 exe   2    0   0      ruby
        0799e000 279a0000 rlib  0    1   0      /usr/lib/libm.so.10.1
        0aaa5000 2aaa7000 rlib  0    1   0      /usr/lib/libpthread.so.26.1
        0cb55000 2cb66000 rlib  0    1   0      /usr/lib/libc.so.96.1
        0b54c000 0b54c000 ld.so 0    1   0      /usr/libexec/ld.so

これruby 2.7 なんだけど、しっかりpthreadを使っているじゃん。matzさんの著作１号は、さすがに古くなっているな。

で、初版本に、スレッドが死んだらお知らせするねフラグがあるよと案内あり。

sakae@pen:/tmp/t$ ruby -d gd.rb
Exception `NameError' at /usr/lib/ruby/vendor_ruby/rubygems/defaults/operating_system.rb:101 - undefined method `rubyforge_project=' for class `Gem::Specification'
Exception `LoadError' at /usr/lib/ruby/vendor_ruby/rubygems.rb:1356 - cannot load such file -- rubygems/defaults/ruby
Exception `LoadError' at /usr/lib/ruby/vendor_ruby/rubygems/core_ext/kernel_require.rb:85 - cannot load such file -- sqlite3
Exception `LoadError' at /usr/lib/ruby/vendor_ruby/rubygems/core_ext/kernel_require.rb:85 - cannot load such file -- sqlite3/2.7/sqlite3_native
Exception `LoadError' at /usr/lib/ruby/vendor_ruby/rubygems/core_ext/kernel_require.rb:162 - cannot load such file -- sqlite3/2.7/sqlite3_native
[2022-04-23 05:51:44] INFO  WEBrick 1.6.1
 :

どうも、オイラーは裏でこそこそやってるGemが嫌いだ。ベンダー優先なんて、今の今迄知らなかったぞ。

気を取り直して、 ri Thread してたらファイバーも紹介された。 Ruby】Fiber（ファイバー）を理解する

Ruby 3: FiberやRactorでHTTPサーバーを手作りする

Ruby 3.0 の Ractor を自慢したい

tarai(12, 6, 0) のように計算規模を縮小。2 core / 4 cpu

ob$ ruby test.rb
       user     system      total        real
seq  4.310000   0.000000   4.310000 (  4.303658)
par  7.940000   0.010000   7.950000 (  1.994743)

ruby 3.0.3p157 (2021-11-24 revision 3fb7d2cadc) [x86₆₄-openbsd] 4 CPUに負荷がかかるのは、いかにも動かしてるぞって感じで楽しいな。

予行演習

OpenBSDでsqlite3をOpenしてる所を探してみる。

(gdb) bt 10
#0  _libc_open_cancel (path=0x70fc49c8 "/usr/share/dict/ejdict.sqlite3",
    flags=66306) at /usr/src/lib/libc/sys/w_open.c:29
#1  0x0aab07b2 in posixOpen () from /usr/local/lib/libsqlite3.so.37.13
#2  0x0aab0a3e in robust_open () from /usr/local/lib/libsqlite3.so.37.13
#3  0x0aa9523c in unixOpen () from /usr/local/lib/libsqlite3.so.37.13
#4  0x0aab2453 in sqlite3BtreeOpen () from /usr/local/lib/libsqlite3.so.37.13
#5  0x0aaa98ca in openDatabase () from /usr/local/lib/libsqlite3.so.37.13
#6  0x0aaa9f25 in sqlite3_open_v2 () from /usr/local/lib/libsqlite3.so.37.13
#7  0x0e9c4488 in rb_sqlite3_open_v2 (self=1877505720, file=1877505600,
    mode=13, zvfs=<optimized out>) at database.c:52
#8  0x177d2b55 in call_cfunc_3 (recv=1877505720, argc=3, argv=0x437b7dd4,
    func=0xe9c4400 <rb_sqlite3_open_v2>) at ./vm_insnhelper.c:2361
#9  0x177cb091 in vm_call_cfunc_with_frame (ec=<optimized out>,
    reg_cfp=<optimized out>, calling=<optimized out>, cd=<optimized out>,
    empty_kw_splat=<optimized out>) at ./vm_insnhelper.c:2514

一旦 sqlite3_open_v2 にBPを配置して、止ったら、今度はopenにBPを置いて、contする。もっと詳しく中を見たい時は、自前で -lsqlite3を組み込んじゃえ。

gemのsqliteのextに、sqlite3.cをXsqlite3.cって名前でコピー。そしてMakefileを編集。

vbox$ diff -u Makefile.org Makefile
--- Makefile.org        Sat Apr 23 14:38:08 2022
+++ Makefile    Sat Apr 23 14:47:40 2022
@@ -137,10 +137,10 @@
 extout_prefix =
 target_prefix = /sqlite3
 LOCAL_LIBS =
-LIBS =  -lsqlite3 -lpthread  -lsqlite3 -lm   -lc
-ORIG_SRCS = aggregator.c backup.c database.c exception.c sqlite3.c statement.c
+LIBS =   -lpthread   -lm   -lc
+ORIG_SRCS = aggregator.c backup.c database.c exception.c sqlite3.c statement.c Xsqlite3.c
 SRCS = $(ORIG_SRCS)
-OBJS = aggregator.o backup.o database.o exception.o sqlite3.o statement.o
+OBJS = aggregator.o backup.o database.o exception.o sqlite3.o statement.o Xsqlite3.o
 HDRS = $(srcdir)/aggregator.h $(srcdir)/backup.h $(srcdir)/database.h $(srcdir)/exception.h $(srcdir)/sqlite3_ruby.h $(srcdir)/statement.h
 LOCAL_HDRS =
 TARGET = sqlite3_native

コンパイルしておけば、それが使われそうだけど、罠がある。実際にロードされる場所に結果を配置の亊(下記は配置前)

/EXTd/opt/lib/ruby/gems/2.7.0
vbox$ find . -name sqlite3_native.so -ls
783503  180 -rwxr-xr-x    1 sakae    wheel       91356 Apr 21 14:20 ./extensions/x86-openbsd-6.8/2.7.0-static/sqlite3-1.4.2/sq
lite3/sqlite3_native.so
783849 9024 -rwxr-xr-x    1 sakae    wheel     4601804 Apr 23 14:50 ./gems/sqlite3-1.4.2/ext/sqlite3/sqlite3_native.so

それから、走らせる。

(gdb) info th
  Id   Target Id         Frame
  1    thread 126109     _thread_sys_select () at /tmp/-:3
 *2    thread 375646     sqlite3BtreeOpen (
    pVfs=0x23a75700 <sqlite3_os_init.aVfs>,
    zFilename=0x5650dacc "/usr/share/dict/ejdict.sqlite3", db=0x5650e608,
    ppBtree=0x5650e7b4, flags=0, vfsFlags=262) at Xsqlite3.c:67078
  3    thread 546059     _thread_sys_poll () at /tmp/-:3
  4    thread 370206     futex () at /tmp/-:3
(gdb) bt 6
#0  sqlite3BtreeOpen (pVfs=0x23a75700 <sqlite3_os_init.aVfs>,
    zFilename=0x5650dacc "/usr/share/dict/ejdict.sqlite3", db=0x5650e608,
    ppBtree=0x5650e7b4, flags=0, vfsFlags=262) at Xsqlite3.c:67078
#1  0x03aa9a5d in openDatabase (zFilename=<optimized out>,
    ppDb=<error reading variable: Unhandled dwarf expression opcode 0xa3>,
    flags=<optimized out>, zVfs=0x0) at Xsqlite3.c:165114
#2  0x03aaa145 in sqlite3_open_v2 (
    filename=0x6ef0d2c0 "/usr/share/dict/ejdict.sqlite3", ppDb=0x5653c790,
    flags=6, zVfs=0x0) at Xsqlite3.c:165237
#3  0x03a8af18 in rb_sqlite3_open_v2 (self=1301676680, file=1301676620,
    mode=13, zvfs=<optimized out>) at database.c:52
#4  0x17948b55 in call_cfunc_3 (recv=1301676680, argc=3, argv=0x7eedcab4,
    func=0x3a8ae90 <rb_sqlite3_open_v2>) at ./vm_insnhelper.c:2361
#5  0x17941091 in vm_call_cfunc_with_frame (ec=<optimized out>,
    reg_cfp=<optimized out>, calling=<optimized out>, cd=<optimized out>,
    empty_kw_splat=<optimized out>) at ./vm_insnhelper.c:2514

Debianで実験

早速、sqlite3.soを使わない独自バージョンで実行。

(gdb) info th
  Id   Target Id                                    Frame
  1    Thread 0xb7ba8100 (LWP 1451) "ruby"          0xb7fd2559 in __kernel_vsyscall ()
  3    Thread 0xb4effb40 (LWP 1461) "utils.rb:158"  0xb7fd2559 in __kernel_vsyscall ()
 *5    Thread 0xb5116b40 (LWP 1477) "server.rb:289" posixOpen (
    zFile=0xb4f17a48 "/usr/share/dict/ejdict.sqlite3", flags=688194, mode=420)
    at Xsqlite3.c:34005
(gdb) bt 6
#0  posixOpen (zFile=0xb4f17a48 "/usr/share/dict/ejdict.sqlite3",
    flags=688194, mode=420) at Xsqlite3.c:34005
#1  0xb5154ffd in robust_open (
    z=z@entry=0xb4f17a48 "/usr/share/dict/ejdict.sqlite3", f=f@entry=163906,
    m=m@entry=0) at Xsqlite3.c:34314
#2  0xb518bfef in unixOpen (pVfs=<optimized out>, zPath=<optimized out>,
    pFile=<optimized out>, flags=<optimized out>, pOutFlags=<optimized out>)
    at Xsqlite3.c:39775
#3  0xb51a277d in sqlite3OsOpen (pFlagsOut=0xb5095958, flags=<optimized out>,
    pFile=<optimized out>, zPath=<optimized out>, pVfs=0xb523e4e0 <aVfs.78>)
    at Xsqlite3.c:23261
#4  sqlite3PagerOpen (nExtra=84, xReinit=0xb515a240 <pageReinit>,
    vfsFlags=<optimized out>, flags=0, zFilename=<optimized out>,
    ppPager=<optimized out>, pVfs=0xb523e4e0 <aVfs.78>) at Xsqlite3.c:56783
#5  sqlite3BtreeOpen (pVfs=<optimized out>, zFilename=<optimized out>,
    db=db@entry=0xb4f19e38, ppBtree=<optimized out>, flags=<optimized out>,
    vfsFlags=<optimized out>) at Xsqlite3.c:1673

この通り、無事に動いた。

一方、OSが用意したsqlite3.soを使う素直な奴では

(gdb) info b
Num     Type           Disp Enb Address    What
1       breakpoint     keep y   <PENDING>  sqlite3BtreeOpen
2       breakpoint     keep y   <PENDING>  openDatabase
3       breakpoint     keep y   0xb51bbcc0 <sqlite3_open_v2>
        breakpoint already hit 1 time

この通り、深い所まで潜っていかない。すなわち辞書ファイルがオープンされていないって亊。それなのにエラーも出さずに動いてしまうって所が、今回のいやらしい所であった。

深くは追求しないけど、Debianが用意した -sqlite3は、スレッド対応になっていないんでしょうな。これにて一件落着って亊にしておきますかね。

起承転結の起承転までだな。だって、リナックス余り好きじゃないもの。まあrubyのリハビリが出来たから佳とするか。素敵なdebbug.gemにも出会えたしね。

そろそろFreeBSDは新しい版が出るはず。そしてOpenBSDは、7.1が4/21に出たしね。UPGRADEするかな。

This year's Index

Home