Jubatusのtimed out errorがtimed out error じゃなくて嵌った件

  • 07 Feb 2016

VagrantにインストールしたJubatusでtimeout errorが出てハマりました。これはハマる人も多いのでは…。

結論から言えばVMへの割り当てメモリ増やせって話しでした。

環境

  • Ubuntu 14.04
  • Python 3.4.3
  • Jubatus 0.8.7

現象

チュートリアルにあるpython turorial.pyを実行するとエラーが発生。

$ jubaclassifier --configpath config.json &
$ python3 tutorial.py

...

2016-02-07 07:11:03,116 1832 INFO  [server_base.cpp:139] starting save to /tmp/10.0.2.15_9199_classifier_tutorial.jubatus
2016-02-07 07:11:04,395 1832 INFO  [server_base.cpp:182] saved to /tmp/10.0.2.15_9199_classifier_tutorial.jubatus
{'10.0.2.15_9199': '/tmp/10.0.2.15_9199_classifier_tutorial.jubatus'}
2016-02-07 07:11:04,399 1832 INFO  [server_base.cpp:57] starting load from /tmp/10.0.2.15_9199_classifier_tutorial.jubatus
Traceback (most recent call last):
  File "tutorial.py", line 56, in <module>
    print(classifier.load("tutorial"))
  File "/usr/local/lib/python3.4/dist-packages/jubatus/common/client.py", line 74, in load
    return self.jubatus_client.call("load", [id], TBool(), [TString()])
  File "/usr/local/lib/python3.4/dist-packages/jubatus/common/client.py", line 38, in call
    ret = future.get()
  File "/usr/local/lib/python3.4/dist-packages/msgpackrpc/future.py", line 40, in get
    self._error_handler(self._error)
  File "/usr/local/lib/python3.4/dist-packages/jubatus/common/client.py", line 18, in error_handler
    raise msgpackrpc.error.RPCError(e)
msgpackrpc.error.RPCError: Request timed out
[1]+  Killed                  jubaclassifier --configpath config.json

/tmp/以下のファイルをロードした後の処理で落ちてます。Request timed outでjubaclassifierまで落ちるのは変だと思いつつ、一応timeout伸ばして再挑戦。

$ jubaclassifier --configpath config.json --timeout 1000 &
$ python3 tutorial.py


...

2016-02-07 07:14:49,284 1868 INFO  [server_base.cpp:139] starting save to /tmp/10.0.2.15_9199_classifier_tutorial.jubatus
2016-02-07 07:14:50,556 1868 INFO  [server_base.cpp:182] saved to /tmp/10.0.2.15_9199_classifier_tutorial.jubatus
{'10.0.2.15_9199': '/tmp/10.0.2.15_9199_classifier_tutorial.jubatus'}
2016-02-07 07:14:50,582 1869 INFO  [server_base.cpp:57] starting load from /tmp/10.0.2.15_9199_classifier_tutorial.jubatus
Traceback (most recent call last):
  File "tutorial.py", line 56, in <module>
    print(classifier.load("tutorial"))
  File "/usr/local/lib/python3.4/dist-packages/jubatus/common/client.py", line 74, in load
    return self.jubatus_client.call("load", [id], TBool(), [TString()])
  File "/usr/local/lib/python3.4/dist-packages/jubatus/common/client.py", line 38, in call
    ret = future.get()
  File "/usr/local/lib/python3.4/dist-packages/msgpackrpc/future.py", line 40, in get
    self._error_handler(self._error)
  File "/usr/local/lib/python3.4/dist-packages/jubatus/common/client.py", line 18, in error_handler
    raise msgpackrpc.error.RPCError(e)
msgpackrpc.error.RPCError: Request timed out
[1]+  Killed                  jubaclassifier --configpath config.json --timeout 1000

timeout伸ばしても同じエラーです。そもそもtimeoutが伸びた感じがしません。そこでメモリ周りを疑ってsyslog見ると

Feb  7 07:25:44 vagrant-ubuntu-trusty-64 kernel: [ 3539.201799] [ 1948]  1000  1946   145224   101869     249        0             0 jubaclassifier
Feb  7 07:25:44 vagrant-ubuntu-trusty-64 kernel: [ 3539.201802] [ 1950]  1000  1950    18632     3780      41        0             0 python3
Feb  7 07:25:44 vagrant-ubuntu-trusty-64 kernel: [ 3539.201804] [ 1951]  1000  1951     1500       27       8        0             0 sar
Feb  7 07:25:44 vagrant-ubuntu-trusty-64 kernel: [ 3539.201807] [ 1952]  1000  1952     2823       60       9        0             0 sadc
Feb  7 07:25:44 vagrant-ubuntu-trusty-64 kernel: [ 3539.201809] Out of memory: Kill process 1948 (jubaclassifier) score 814 or sacrifice child
Feb  7 07:25:44 vagrant-ubuntu-trusty-64 kernel: [ 3539.203725] Killed process 1948 (jubaclassifier) total-vm:580896kB, anon-rss:407476kB, file-rss:0kB
Feb  7 07:25:44 vagrant-ubuntu-trusty-64 kernel: [ 3539.207826] vmstats invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0

Out of memoryと出てます。メモリ不足でjubaclassifierが落ちてtimedout扱いになったということですね。RPCErrorは正しいと思いますが、Request timed outってエラーメッセージはちょっと変な気がします。エラーハンドラがまだしっかり作られていないのでしょうか。

ということで、VMのメモリ割り当てを増やします。現在のメモリは・・

vagrant@vagrant-ubuntu-trusty-64:~/jubatus-tutorial-python$ free
             total       used       free     shared    buffers     cached
Mem:        501788      95832     405956        660       3808      19776
-/+ buffers/cache:      72248     429540
Swap:            0          0          0

500MB（けちぃ）。これを1GBにします。

config.vm.provider "virtualbox" do |vb|
    vb.customize ["modifyvm", :id, "--memory", "1024"]
end

Vagrantをリロード。

$ vagrant reload

再びturtorial.pyを実行します。

$ jubaclassifier --configpath config.json &
$ python3 tutorial.py

...

OK,sci.med, sci.med, 0.5731951594352722
OK,sci.space, sci.space, 0.8587071299552917
OK,sci.med, sci.med, 0.5466979146003723
NG,talk.politics.mideast, talk.religion.misc, 0.43721216917037964
NG,alt.atheism, talk.religion.misc, 0.6170076131820679
NG,talk.politics.misc, sci.space, 0.761217474937439
OK,sci.crypt, sci.crypt, 1.516882300376892
OK,talk.politics.mideast, talk.politics.mideast, 1.423082709312439
OK,rec.sport.hockey, rec.sport.hockey, 1.2044557332992554
...

ちゃんと出ました。良かった良かった。