hiro99ma blog: [lmdb][win10]もう少しlmdbがうまく動作しない件を調査

以前、こういう記事を書いた。

hiro99ma blog: [lmdb][win10]Windows10 1803でWSLのファイル書込みがうまく動いてない？(2018/05/05)
https://hiro99ma.blogspot.com/2018/05/lmdbwin10windows10-1803wsl20180505.html

今日(2018/06/02)もまだ発生している。
Ubuntu 18.04も試してみたが、同じだ。
だから、これはOSよりもWSL側に何かあるんじゃなかろうかと考えた。

解決できないだろうけど、せっかくなので、もう少し調べてみよう。

前回からgistの内容を変更しているので、再掲しておこう(Revision 3)。

https://gist.github.com/hirokuma/4ea889b2a596c59ef4f862e9df54e469

これを実行させると、初回から3秒くらいまでの間はL.95でエラーが出力されている。

test1(): OK
ERR(95): MDB_BAD_TXN: Transaction must abort, has a child, or is invalid

前回のブログではmdb_put()でエラーになったと書いているが、mdb_get()だな。
勘違いして書いたのか、現象が変わったのか・・・。
mdb_put()がうまくいっていないから、mdb_get()に失敗したといいたかったのかもしれんが、よくわからんな。

まあ、よかろう。
mdb_get()で失敗しているのだ。

まず、実行するディレクトリを変えてみた。
前回動かしたときは、Windowsで作業しているディレクトリだったのだ。
もしかすると。WSLで管理しているディレクトリじゃないとうまくいかない、とかあるのかもしれん。

が、これは関係なさそうだった。
「~/」に移動させて実行したが、結果は同じだ。

次は、失敗したときと成功した時をstraceで眺めた。

失敗時の出力。
どのくらい抜粋すればよいかわからないので、いいところが載ってないかも。

mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x7f2044f1d000
open("testdb/data.mdb", O_RDWR|O_CREAT, 0644) = 4
fstatfs(4, {f_type=0x53464846, f_bsize=4096, f_blocks=58348607, f_bfree=35725114, f_bavail=35725114, f_files=999, f_ffree=1000000, f_fsid={1, 0}, f_namelen=255, f_frsize=4096, f_flags=1056}) = 0
pread64(4, "\0\0\0\0\0\0\0\0\0\0\10\0\0\0\0\0\336\300\357\276\1\0\0\0\0\0\0\0\0\0\0\0"..., 152, 0) = 152
pread64(4, "\1\0\0\0\0\0\0\0\0\0\10\0\0\0\0\0\336\300\357\276\1\0\0\0\0\0\0\0\0\0\0\0"..., 152, 4096) = 152
mmap(NULL, 1048576, PROT_READ, MAP_SHARED, 4, 0) = 0x7f20440e0000
open("testdb/data.mdb", O_RDWR|O_DSYNC) = 5
fcntl(3, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0
write(2, "test1(): OK\n", 12test1(): OK
)           = 12
lseek(4, 16384, SEEK_SET)               = 16384
writev(4, [{"\4\0\0\0\0\0\0\0\0\0\2\0\22\0\302\17\302\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}, {"\5\0\0\0\0\0\0\0\0\0\2\0\22\0\356\17\356\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}, {"\6\0\0\0\0\0\0\0\0\0\2\0\22\0\330\17\330\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}], 3) = 12288
fdatasync(4)                            = 0
pwrite64(5, "\0\0\20\0\0\0\0\0\0\20\0\0\10\0\1\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., 120, 32) = 120
write(2, "ERR(95): MDB_BAD_TXN: Transactio"..., 73ERR(95): MDB_BAD_TXN: Transaction must abort, has a child, or is invalid
) = 73

成功時。

mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x7f4d72ec0000
open("testdb/data.mdb", O_RDWR|O_CREAT, 0644) = 4
fstatfs(4, {f_type=0x53464846, f_bsize=4096, f_blocks=244189951, f_bfree=103944675, f_bavail=103944675, f_files=999, f_ffree=1000000, f_fsid={1, 0}, f_namelen=255, f_frsize=4096, f_flags=1056}) = 0
pread64(4, "\0\0\0\0\0\0\0\0\0\0\10\0\0\0\0\0\336\300\357\276\1\0\0\0\0\0\0\0\0\0\0\0"..., 152, 0) = 152
pread64(4, "\1\0\0\0\0\0\0\0\0\0\10\0\0\0\0\0\336\300\357\276\1\0\0\0\0\0\0\0\0\0\0\0"..., 152, 4096) = 152
mmap(NULL, 1048576, PROT_READ, MAP_SHARED, 4, 0) = 0x7f4d720e0000
open("testdb/data.mdb", O_RDWR|O_DSYNC) = 5
fcntl(3, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0
write(2, "test1(): OK\n", 12test1(): OK
)           = 12
lseek(4, 8192, SEEK_SET)                = 8192
writev(4, [{"\2\0\0\0\0\0\0\0\0\0\2\0\22\0\302\17\302\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}, {"\3\0\0\0\0\0\0\0\0\0\2\0\22\0\356\17\356\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}], 2) = 8192
pwrite64(4, "\n\0\0\0\0\0\0\0\0\0\2\0\24\0\240\17\320\17\240\17\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 40960) = 4096
fdatasync(4)                            = 0
pwrite64(5, "\0\0\20\0\0\0\0\0\0\20\0\0\10\0\1\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., 120, 32) = 120
write(2, "test2(): OK\n", 12test2(): OK
)           = 12

失敗straceログは、2回目の実行を載せている。
初回だとディレクトリ作成やファイル作成に違いが出てきてわかりにくいからだ。

文字色を付けたところが、コンソールログ("write"で始まる行)。
背景色を付けたところは、違いがありそうな箇所。

失敗時は、ファイル4へのpwrite64()が発生していない。
fd=4は、最初に開いた方のtestdb/data.mdbだ。。。あれ、fd=5もtestdb/data.mdbだな。
同じファイルをオープンしているのか？

2回目のopen()にはO_DSYNCが指定されていた。
「ファイルに対する書き込み操作は、同期 I/O のデータ完全性完了の要件に基づいて行われる」らしい。
https://linuxjm.osdn.jp/html/LDP_man-pages/man2/open.2.html

・・・などと、違いがあるところばかり気にしていたが、test1()でOKを出力させる前のところでファイル書込みをしてないよね？
mdb_put()に相当する処理がスキップされている？？
既にデータがあるから、書き込む前にデータを比較して、同じだからスキップされたのかもしれない。
まあ、ストレージへの書込みはコストが高いので、さもありなん。

そしてもう1つ。
成功する状態でいくつかstraceを取ってみたが、lseek()されるサイズは16384の場合もあったし、違うサイズの場合もあった。
その際、背景色が緑の出力は行われていなかった。。。

何が起きているのか、さっぱりわからんな。

WSLではないLinuxでのstraceを見よう。

mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x7f10690bc000
open("testdb/data.mdb", O_RDWR|O_CREAT, 0644) = 4
fstatfs(4, {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=7607162, f_bfree=594658, f_bavail=590562, f_files=3840000, f_ffree=2984847, f_fsid={-2044918571, 1650642210}, f_namelen=255, f_frsize=4096, f_flags=4128}) = 0
uname({sysname="Linux", nodename="lntest1", ...}) = 0
pread64(4, "\0\0\0\0\0\0\0\0\0\0\10\0\0\0\0\0\336\300\357\276\1\0\0\0\0\0\0\0\0\0\0\0"..., 152, 0) = 152
pread64(4, "\1\0\0\0\0\0\0\0\0\0\10\0\0\0\0\0\336\300\357\276\1\0\0\0\0\0\0\0\0\0\0\0"..., 152, 4096) = 152
mmap(NULL, 1048576, PROT_READ, MAP_SHARED, 4, 0) = 0x7f106839c000
open("testdb/data.mdb", O_RDWR|O_DSYNC) = 5
fcntl(3, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0
write(2, "test1(): OK\n", 12test1(): OK
)           = 12
lseek(4, 16384, SEEK_SET)               = 16384
writev(4, [{"\4\0\0\0\0\0\0\0\0\0\2\0\22\0\302\17\302\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}, {"\5\0\0\0\0\0\0\0\0\0\2\0\22\0\356\17\356\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}, {"\6\0\0\0\0\0\0\0\0\0\2\0\22\0\330\17\330\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}], 3) = 12288
fdatasync(4)                            = 0
pwrite64(5, "\0\0\20\0\0\0\0\0\0\20\0\0\10\0\1\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., 120, 32) = 120
write(2, "test2(): OK\n", 12test2(): OK
)           = 12

fd=4へのpwrite64()呼び出しは、起きたり起きなかったりで、これはWSLと同じだ。
連続して実行するとpwrite64()が呼び出されないようなので、キャッシュに吐き出されるまでは呼び出していないのかもしれん。

WSLで失敗したとき。

lseek(4, 16384, SEEK_SET)               = 16384
writev(4, [{"\4\0\0\0\0\0\0\0\0\0\2\0\22\0\302\17\302\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}, {"\5\0\0\0\0\0\0\0\0\0\2\0\22\0\356\17\356\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}, {"\6\0\0\0\0\0\0\0\0\0\2\0\22\0\330\17\330\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}], 3) = 12288
fdatasync(4)                            = 0
pwrite64(5, "\0\0\20\0\0\0\0\0\0\20\0\0\10\0\1\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., 120, 32) = 120
write(2, "ERR(95): MDB_BAD_TXN: Transactio"..., 73ERR(95): MDB_BAD_TXN: Transaction must abort, has a child, or is invalid
) = 73

Linuxで成功したときの例。

lseek(4, 16384, SEEK_SET)               = 16384
writev(4, [{"\4\0\0\0\0\0\0\0\0\0\2\0\22\0\302\17\302\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}, {"\5\0\0\0\0\0\0\0\0\0\2\0\22\0\356\17\356\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}, {"\6\0\0\0\0\0\0\0\0\0\2\0\24\0\240\17\320\17\240\17\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096}], 3) = 12288
fdatasync(4)                            = 0
pwrite64(5, "\0\0\20\0\0\0\0\0\0\20\0\0\10\0\1\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., 120, 32) = 120
write(2, "test2(): OK\n", 12test2(): OK
)           = 12

lseek()の結果と、pwrite64()の一番最後にある引数は毎回変わるので、Linuxの方は何度か実行して同じような出力を探した。

つまり、straceの結果からでは違いが分からんということだ。

まだだ・・・今のわしには力が足りんのだ。。。

hiro99ma blog

2018/06/02

[lmdb][win10]もう少しlmdbがうまく動作しない件を調査

0 件のコメント:

コメントを投稿