Netatalk 3でsendfileを無効にするとCannot allocate memoryが起きる？

いつ頃からから、Netatalk 3.1.7で提供しているボリュームとの接続が突然切れる現象が起きるようになった。

正確な発症条件は不明だが、ストレージの読み書き負荷が高い時や、巨大な動画ファイルでシークすると発生しやすい印象。いずれにせよ、何の前触れもなく発生し接続断のダイアログも出ないので地味にストレスが溜まる。

接続が切れる直前は決まって、ログにdsi_stream_sendかafp_read_extのCannot allocate memoryが記録されている。

Jun 02 23:55:18.897112 afpd[57517] {afp_dsi.c:624} (debug:AFPDaemon): <== Start AFP command: AFP_READ_EXT
Jun 02 23:55:18.897126 afpd[57517] {fork.c:829} (debug:AFPDaemon): afp_read(fork: 422 [data], off: 1310720, len: 65536, size: 2222591)
Jun 02 23:55:18.897156 afpd[57517] {fork.c:880} (debug:AFPDaemon): afp_read(name: "01 プロローグ・静かなる侵略.m4a", offset: 1310720, reqcount: 65536): got 65536 bytes from file
Jun 02 23:55:18.897170 afpd[57517] {dsi_read.c:29} (maxdebug:DSI): dsi_readinit: sending 65536 bytes from buffer, total size: 65536
Jun 02 23:55:18.897183 afpd[57517] {dsi_stream.c:530} (maxdebug:DSI): dsi_stream_send(65536 bytes): START
Jun 02 23:55:18.897353 afpd[57517] {dsi_stream.c:564} (error:DSI): dsi_stream_send: Cannot allocate memory
Jun 02 23:55:18.897375 afpd[57517] {fork.c:913} (error:AFPDaemon): afp_read(01 プロローグ・静かなる侵略.m4a): Cannot allocate memory
Jun 02 23:55:18.897397 afpd[57517] {dsi_stream.c:281} (maxdebug:DSI): dsi_stream_write(send: 18 bytes): START
Jun 02 23:55:18.897419 afpd[57517] {dsi_stream.c:325} (maxdebug:DSI): dsi_stream_write(send: 18 bytes): END
（中略）
Jun 02 23:55:18.898533 afpd[57517] {cnid_dbd.c:498} (debug:CNID): closing database connection for volume 'Decomo'
Jun 02 23:55:18.898578 cnid_dbd[57522] {comm.c:207} (maxdebug:CNID): comm_rcv: got data on fd 5
Jun 02 23:55:18.898980 afpd[57517] {afp_dsi.c:108} (note:AFPDaemon): AFP statistics: 3177.09 KB read, 2524196.96 KB written
Jun 02 23:55:18.899005 afpd[57517] {dircache.c:615} (info:AFPDaemon): dircache statistics: entries: 2088, lookups: 10018, hits: 7503, misses: 2463, added: 2140, removed: 52, expunged: 52, evicted: 0
Jun 02 23:55:18.899020 afpd[57517] {dsi_stream.c:530} (maxdebug:DSI): dsi_stream_send(0 bytes): START
Jun 02 23:55:18.899033 afpd[57517] {dsi_stream.c:538} (maxdebug:DSI): dsi_stream_send(16 bytes): DSI header, no data
Jun 02 23:55:18.899045 afpd[57517] {dsi_stream.c:281} (maxdebug:DSI): dsi_stream_write(send: 16 bytes): START
Jun 02 23:55:18.899068 afpd[57517] {dsi_stream.c:325} (maxdebug:DSI): dsi_stream_write(send: 16 bytes): END
Jun 02 23:55:18.899089 afpd[57517] {afp_dsi.c:137} (info:AFPDaemon): Connection terminated
Jun 02 23:55:18.899899 afpd[57498] {main.c:149} (info:AFPDaemon): child[57517]: exited 1

Mac側はOS X v10.9.5で、サーバ側はFreeBSD 10.1-RELEASE。10.1RにはZFSのARCがメモリを食いつぶすバグがあるらしく、それが原因かと思って10-STABLEに更新するも、症状は相変わらず。

で、試行錯誤を続けていたが、Netatalk 3のsendfileを有効にしたらピタッとおさまった。正確には未だ出るけど、Netatalkとの接続は維持自体はされるようになった（自動で再接続されている模様）。おぼろげな記憶をたどると「ZFS環境でApache等のsendfileを有効にするとキャッシュの二重持ちになる可能性がある」という資料を見て、sendfile無効でNetatalk 3を作り直してたような気がしないでもなく、丁度その辺から問題が出たような気がする……。

時を同じくして、同サーバのSamba 4でファイル一覧の取得がタイムアウトしたり、動画が全く再生できなくなったりしていたのだが、こちらは逆にuse sendfile = yesを無効化したら直った。

全く以て謎だ…