読者です 読者をやめる 読者になる 読者になる

Tokyo TyrantでテーブルDBを指定するとtcrtestがエラーになる。

Tokyo Cabinet / Tokyo Tyrant を使ってみているのだが、テーブルDBにTTのRuby binding経由で読み書きを繰り返していると、

  • エラーコードがずっとEMISC(9999)のままになる。
  • 結果がたまに空で返ってくる。
    • 再接続すると正しい結果が返る。
    • この時のエラーコードは大抵EMISCだがESUCCESSの場合も。

という問題が発生して困っている。原因を絞り込むためtcrtestを試したら、同じようにmiscエラーが出た。

  • ttservctlをテーブルDBに修正してttserverを起動。
  • tcrtest misc 127.0.0.1 1000
    • Linux(32bit) の場合、rnum=1000で2回に1回くらいmiscエラーが出る。
    • Mac OSX(64bit) の場合、rnum>4095でmiscエラーが出る。

自力で原因を調べると3年くらいかかりそうなので、mixiのサポートコミュニティで聞いてみることにする。

(追記) 回答いただけました。

テーブルDBと固定長DBは純粋なkey/valueストレージではないため、それを前提としたtcrtestの各種テストは正常に動作しません。ドキュメントに特にその旨を書いていなかったので、申し訳ありません。
TTにおけるテーブルDBのテストケースはtcrtest tableのみとなります。

うむー。やっぱりテストの内容をもうちょっと理解してから聞いたらよかったです。すいません。

そして手がかりが無くなってしまった……。EMISC……何かのエラー……。
(追記おわり)



以下詳細。

起動スクリプト

ttservctlをコピーし、以下の修正を行った。

  • tchをtctに変更。
  • ログファイルを指定。
# diff /usr/local/sbin/ttservctl ./ttservctl
14c14
< #logfile="$basedir/log"
---
> logfile="$basedir/log"
21c21
< dbname="$basedir/casket.tch#bnum=1000000"
---
> dbname="$basedir/casket.tct#bnum=1000000"

Fedora 8 (32bit)の場合。 (EC2 ami-5647a33f)

EC2のFedora 8で試した。他にEC2のdebian、EC2じゃないCentOSも試したが似たような結果だった。エラーが出る頻度はFedoraよりも多い感じがしたけど気のせいかも(あいまい)。

環境

# ttserver --version
Tokyo Tyrant version 1.1.28 (311:0.91) for Linux
Copyright (C) 2006-2009 Mikio Hirabayashi

# tctmgr --version
Tokyo Cabinet version 1.4.23 (814:1.0) for Linux
Copyright (C) 2006-2009 Mikio Hirabayashi

# gcc --version
gcc (GCC) 4.1.2 20070925 (Red Hat 4.1.2-33)

# tcucodec conf
myconf(version): 1.4.23
myconf(sysname): Linux
myconf(libver): 814
myconf(formatver): 1.0
myconf(prefix): /usr/local
myconf(includedir): /usr/local/include
myconf(libdir): /usr/local/lib
myconf(bindir): /usr/local/bin
myconf(libexecdir): /usr/local/libexec
myconf(appinc): -I/usr/local/include
myconf(applibs): -L/usr/local/lib -ltokyocabinet -lbz2 -lz -lrt -lpthread -lm -lc 
myconf(bigend): 0
myconf(usezlib): 1
myconf(usebzip): 1
sizeof(bool): 1
sizeof(char): 1
sizeof(short): 2
sizeof(int): 4
sizeof(long): 4
sizeof(long long): 8
sizeof(float): 4
sizeof(double): 8
sizeof(long double): 12
sizeof(void *): 4
sizeof(intptr_t): 4
sizeof(size_t): 4
sizeof(time_t): 4
sizeof(off_t): 4
sizeof(ino_t): 4
sizeof(wchar_t): 4
sizeof(sig_atomic_t): 4
macro(CHAR_MAX): 127
macro(SHRT_MAX): 32767
macro(INT_MAX): 2147483647
macro(LONG_MAX): 2147483647
macro(LLONG_MAX): 9223372036854775807
macro(FLT_MAX): 3.40282e+38
macro(DBL_MAX): 1.79769e+308
macro(LDBL_MAX): 1.18973e+4932
macro(PATH_MAX): 4096
macro(RAND_MAX): 2147483647
sysconf(_SC_CLK_TCK): 100
sysconf(_SC_OPEN_MAX): 1024
sysconf(_SC_PAGESIZE): 4096
stat(st_uid): 0
stat(st_gid): 0
stat(st_blksize): 4096

TTを起動。

# ./ttservctl start
Starting the server of Tokyo Tyrant
Executing: ttserver -port 1978 -dmn -pid /var/ttserver/pid -log /var/ttserver/log
Done
# tcrtest misc 127.0.0.1 1000
<Miscellaneous Test>
  host=127.0.0.1  port=1978  cnum=1  tout=0  rnum=1000

writing:
......................... (00000100)
......................... (00000200)
......................... (00000300)
......................... (00000400)
......................... (00000500)
......................... (00000600)
......................... (00000700)
......................... (00000800)
......................... (00000900)
......................... (00001000)
reading:
tcrtest: (validation): error: 0: success
random writing:
tcrtest: (validation): error: 0: success
word writing:
.................... (00000041)
random erasing:
......................... (00000100)
......................... (00000200)
......................... (00000300)
......................... (00000400)
......................... (00000500)
......................... (00000600)
......................... (00000700)
......................... (00000800)
......................... (00000900)
......................... (00001000)
writing:
.......tcrtest: tcrdbput: error: 9999: miscellaneous error
erasing:
........tcrtest: tcrdbout: error: 7: no record found
random multi reading:
......................... (00000100)
......................... (00000200)
......................... (00000300)
......................... (00000400)
......................... (00000500)
......................... (00000600)
......................... (00000700)
......................... (00000800)
......................... (00000900)
......................... (00001000)
script extension calling:
......................... (00000100)
......................... (00000200)
......................... (00000300)
......................... (00000400)
......................... (00000500)
......................... (00000600)
......................... (00000700)
......................... (00000800)
......................... (00000900)
......................... (00001000)
checking versatile functions:
......................... (00000100)
......................... (00000200)
......................... (00000300)
......................... (00000400)
......................... (00000500)
......................... (00000600)
......................... (00000700)
......................... (00000800)
......................... (00000900)
......................... (00001000)
record number: 0
size: 14656
time: 0.428
error
  • tcrtest: (validation): error: 0: success は毎回発生。
  • tcrtest: tcrdbput: error: 9999: miscellaneous error は rnum=1000 で2回に1回くらい発生。

ログは以下のとおり。2回実行して終了させた。

2009-06-03T05:35:03-05:00       SYSTEM  --------- logging started [11085] --------
2009-06-03T05:35:03-05:00       SYSTEM  process ID configuration: path=/var/ttserver/pid pid=11085
2009-06-03T05:35:03-05:00       SYSTEM  server configuration: host=(any) port=1978
2009-06-03T05:35:03-05:00       SYSTEM  opening the database: /var/ttserver/casket.tct#bnum=1000000
2009-06-03T05:35:03-05:00       SYSTEM  service started: 11085
2009-06-03T05:35:03-05:00       INFO    timer thread 1 started
2009-06-03T05:35:03-05:00       INFO    worker thread 1 started
2009-06-03T05:35:03-05:00       INFO    worker thread 2 started
2009-06-03T05:35:03-05:00       INFO    worker thread 3 started
2009-06-03T05:35:03-05:00       INFO    worker thread 4 started
2009-06-03T05:35:03-05:00       INFO    worker thread 5 started
2009-06-03T05:35:03-05:00       INFO    worker thread 6 started
2009-06-03T05:35:03-05:00       INFO    worker thread 7 started
2009-06-03T05:35:03-05:00       INFO    worker thread 8 started
2009-06-03T05:35:03-05:00       SYSTEM  listening started
2009-06-03T05:39:07-05:00       INFO    connected: 127.0.0.1:36178
2009-06-03T05:39:07-05:00       INFO    doing vanish command
2009-06-03T05:39:08-05:00       INFO    doing sync command
2009-06-03T05:39:08-05:00       INFO    doing optimize command
2009-06-03T05:39:08-05:00       INFO    doing vanish command
2009-06-03T05:39:08-05:00       INFO    connection finished
2009-06-03T05:39:18-05:00       INFO    connected: 127.0.0.1:36179
2009-06-03T05:39:18-05:00       INFO    doing vanish command
2009-06-03T05:39:19-05:00       ERROR   do_put: operation failed
2009-06-03T05:39:19-05:00       INFO    doing sync command
2009-06-03T05:39:19-05:00       INFO    doing optimize command
2009-06-03T05:39:19-05:00       INFO    doing vanish command
2009-06-03T05:39:19-05:00       INFO    connection finished
2009-06-03T05:41:30-05:00       INFO    signal interruption
2009-06-03T05:41:30-05:00       SYSTEM  listening finished
2009-06-03T05:41:31-05:00       SYSTEM  closing the database
2009-06-03T05:41:31-05:00       INFO    worker thread 1 finished
2009-06-03T05:41:31-05:00       INFO    worker thread 2 finished
2009-06-03T05:41:31-05:00       INFO    worker thread 3 finished
2009-06-03T05:41:31-05:00       INFO    worker thread 4 finished
2009-06-03T05:41:31-05:00       INFO    worker thread 5 finished
2009-06-03T05:41:31-05:00       INFO    worker thread 6 finished
2009-06-03T05:41:31-05:00       INFO    worker thread 7 finished
2009-06-03T05:41:31-05:00       INFO    worker thread 8 finished
2009-06-03T05:41:31-05:00       INFO    timer thread 1 finished
2009-06-03T05:41:31-05:00       SYSTEM  service finished
2009-06-03T05:41:31-05:00       SYSTEM  --------- logging finished [11085] --------

Macの場合。

環境

# ttserver --version
Tokyo Tyrant version 1.1.27 (310:0.91) for Mac OS X
Copyright (C) 2006-2009 Mikio Hirabayashi

# tctmgr --version
Tokyo Cabinet version 1.4.23 (814:1.0) for Mac OS X
Copyright (C) 2006-2009 Mikio Hirabayashi

# gcc --version
i686-apple-darwin9-gcc-4.0.1 (GCC) 4.0.1 (Apple Inc. build 5488)

# tcucodec conf
myconf(version): 1.4.23
myconf(sysname): Mac OS X
myconf(libver): 814
myconf(formatver): 1.0
myconf(prefix): /usr/local
myconf(includedir): /usr/local/include
myconf(libdir): /usr/local/lib
myconf(bindir): /usr/local/bin
myconf(libexecdir): /usr/local/libexec
myconf(appinc): -I/usr/local/include
myconf(applibs): -L/usr/local/lib -ltokyocabinet -lbz2 -lz -lpthread -lm -lc 
myconf(bigend): 0
myconf(usezlib): 1
myconf(usebzip): 1
sizeof(bool): 1
sizeof(char): 1
sizeof(short): 2
sizeof(int): 4
sizeof(long): 4
sizeof(long long): 8
sizeof(float): 4
sizeof(double): 8
sizeof(long double): 16
sizeof(void *): 4
sizeof(intptr_t): 4
sizeof(size_t): 4
sizeof(time_t): 4
sizeof(off_t): 8
sizeof(ino_t): 4
sizeof(wchar_t): 4
sizeof(sig_atomic_t): 4
macro(CHAR_MAX): 127
macro(SHRT_MAX): 32767
macro(INT_MAX): 2147483647
macro(LONG_MAX): 2147483647
macro(LLONG_MAX): 9223372036854775807
macro(FLT_MAX): 3.40282e+38
macro(DBL_MAX): 1.79769e+308
macro(LDBL_MAX): 1.18973e+4932
macro(PATH_MAX): 1024
macro(RAND_MAX): 2147483647
sysconf(_SC_CLK_TCK): 100
sysconf(_SC_OPEN_MAX): 256
sysconf(_SC_PAGESIZE): 4096
stat(st_uid): 0
stat(st_gid): 0
stat(st_blksize): 4096

ttserverを起動。

# ./ttservctl start
Starting the server of Tokyo Tyrant
./ttservctl: line 49: ulimit: open files: cannot modify limit: Invalid argument
Executing: ttserver -port 1978 -dmn -pid /var/ttserver/pid -log /var/ttserver/log
Done

tcrtest miscを実行するとエラーになる。

# tcrtest misc 127.0.0.1 5000
<Miscellaneous Test>
  host=127.0.0.1  port=1978  cnum=1  tout=0  rnum=5000

writing:
......................... (00000500)
......................... (00001000)
......................... (00001500)
......................... (00002000)
......................... (00002500)
......................... (00003000)
......................... (00003500)
......................... (00004000)
......................... (00004500)
......................... (00005000)
reading:
tcrtest: (validation): error: 0: success
random writing:
tcrtest: (validation): error: 0: success
word writing:
.................... (00000041)
random erasing:
......................... (00000500)
......................... (00001000)
......................... (00001500)
......................... (00002000)
......................... (00002500)
......................... (00003000)
......................... (00003500)
......................... (00004000)
......................... (00004500)
......................... (00005000)
writing:
......................... (00000500)
......................... (00001000)
......................... (00001500)
......................... (00002000)
......................... (00002500)
......tcrtest: tcrdbput: error: 9999: miscellaneous error
erasing:
......................... (00000500)
......................... (00001000)
......................... (00001500)
......................... (00002000)
......................... (00002500)
......tcrtest: tcrdbout: error: 7: no record found
random multi reading:
......................... (00000500)
......................... (00001000)
......................... (00001500)
......................... (00002000)
......................... (00002500)
......................... (00003000)
......................... (00003500)
......................... (00004000)
......................... (00004500)
......................... (00005000)
script extension calling:
......................... (00000500)
......................... (00001000)
......................... (00001500)
......................... (00002000)
......................... (00002500)
......................... (00003000)
......................... (00003500)
......................... (00004000)
......................... (00004500)
......................... (00005000)
checking versatile functions:
......................... (00000500)
......................... (00001000)
......................... (00001500)
......................... (00002000)
......................... (00002500)
......................... (00003000)
......................... (00003500)
......................... (00004000)
......................... (00004500)
......................... (00005000)
record number: 0
size: 61728
time: 3.798
error
  • tcrtest: (validation): error: 0: success は毎回発生。
  • tcrtest: tcrdbput: error: 9999: miscellaneous error はrnumが4096から毎回発生するようだった。

ログは以下のとおり。

2009-06-03T19:17:55+09:00       SYSTEM  --------- logging started [2886] --------
2009-06-03T19:17:55+09:00       SYSTEM  process ID configuration: path=/var/ttserver/pid pid=2886
2009-06-03T19:17:55+09:00       SYSTEM  server configuration: host=(any) port=1978
2009-06-03T19:17:55+09:00       SYSTEM  opening the database: /var/ttserver/casket.tct#bnum=1000000
2009-06-03T19:17:55+09:00       SYSTEM  service started: 2886
2009-06-03T19:17:55+09:00       INFO    timer thread 1 started
2009-06-03T19:17:55+09:00       INFO    worker thread 1 started
2009-06-03T19:17:55+09:00       INFO    worker thread 2 started
2009-06-03T19:17:55+09:00       INFO    worker thread 3 started
2009-06-03T19:17:55+09:00       INFO    worker thread 4 started
2009-06-03T19:17:55+09:00       INFO    worker thread 5 started
2009-06-03T19:17:55+09:00       INFO    worker thread 6 started
2009-06-03T19:17:55+09:00       INFO    worker thread 7 started
2009-06-03T19:17:55+09:00       INFO    worker thread 8 started
2009-06-03T19:17:55+09:00       SYSTEM  listening started
2009-06-03T19:18:00+09:00       INFO    connected: 127.0.0.1:64081
2009-06-03T19:18:00+09:00       INFO    doing vanish command
2009-06-03T19:18:02+09:00       ERROR   do_put: operation failed
2009-06-03T19:18:04+09:00       INFO    doing sync command
2009-06-03T19:18:04+09:00       INFO    doing optimize command
2009-06-03T19:18:04+09:00       INFO    doing vanish command
2009-06-03T19:18:04+09:00       INFO    connection finished
2009-06-03T19:18:06+09:00       INFO    signal interruption
2009-06-03T19:18:06+09:00       SYSTEM  listening finished
2009-06-03T19:18:06+09:00       SYSTEM  closing the database
2009-06-03T19:18:06+09:00       INFO    worker thread 1 was canceled
2009-06-03T19:18:06+09:00       INFO    worker thread 1 finished
2009-06-03T19:18:06+09:00       INFO    worker thread 2 was canceled
2009-06-03T19:18:06+09:00       INFO    worker thread 2 finished
2009-06-03T19:18:06+09:00       INFO    worker thread 3 was canceled
2009-06-03T19:18:06+09:00       INFO    worker thread 3 finished
2009-06-03T19:18:06+09:00       INFO    worker thread 4 was canceled
2009-06-03T19:18:06+09:00       INFO    worker thread 4 finished
2009-06-03T19:18:06+09:00       INFO    worker thread 5 was canceled
2009-06-03T19:18:06+09:00       INFO    worker thread 5 finished
2009-06-03T19:18:06+09:00       INFO    worker thread 6 was canceled
2009-06-03T19:18:06+09:00       INFO    worker thread 6 finished
2009-06-03T19:18:06+09:00       INFO    worker thread 7 was canceled
2009-06-03T19:18:06+09:00       INFO    worker thread 7 finished
2009-06-03T19:18:06+09:00       INFO    worker thread 8 was canceled
2009-06-03T19:18:06+09:00       INFO    worker thread 8 finished
2009-06-03T19:18:06+09:00       INFO    timer thread 1 was canceled
2009-06-03T19:18:06+09:00       INFO    timer thread 1 finished
2009-06-03T19:18:06+09:00       SYSTEM  service finished
2009-06-03T19:18:06+09:00       SYSTEM  --------- logging finished [2886] --------