ソースの表示以前のリビジョンバックリンク全て展開する／折り畳む文書の先頭へ Share via Share via... Twitter LinkedIn Facebook Pinterest Telegram WhatsApp Yammer Reddit Teams最近の変更Send via e-Mail印刷パーマリンク × Netatalk 3でsendfileを無効にするとCannot allocate memoryが起きる？ (2016-01-04 追記) どうやらVirtualBoxが原因だった模様。詳細→FreeBSDでVirtualBoxを動かしていると巨大ファイルの転送で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を無効化したら直った。 全く以て謎だ… RAID-Z2の再構築速度 知人の業務用ファイルサーバという名の自作マシンに、悪名高きST3000DM001が5台も使われている。HDDの通電時間も15000時間を超え、そろそろ怖くなってきたので全部取り替えることになった。 CPU Intel Xeon E3-1225 V2 M/B Gigabyte Z77X-UP5 メモリ 16GB ストレージ HDD 6台（ST3000DM001×5 + HDS723030ALA640）のRAID-Z2 OS FreeBSD 9.2-RELEASE-p4 # zpool list NAME SIZE ALLOC FREE CAP DEDUP HEALTH ALTROOT zdata 16.2T 8.45T 7.80T 52% 1.00x DEGRADED - こんな環境。 早速1台をzpool replaceしてみたところ、6時間で1.41TBを同期して完了。既存データを総なめしてる訳だから、410MB/sほどの速度。他のRAIDシステムを使ったことがないので、これが速いのか遅いのかは判断できないが、遅くはないんじゃないかなーと思う。 ちなみに、再構築中のロードアベレージは0.5位で、CPUはsystemに15%前後取られていた。 さて、残り4台もこの調子で交換していこう。 続・L2ARCの空き容量が16EB(16.0E)と表示される件 こないだの続き。 その後システムをFreeBSD 10-STABLE (r283857)に更新しL2ARCを有効にしていたが、これまた、たまたまzpool iostatを流してたら16EBになる瞬間を捉えられた。 capacity operations bandwidth pool alloc free read write read write ---------- ----- ----- ----- ----- ----- ----- zhome 731G 197G 0 68 0 8.01M mirror 731G 197G 0 68 0 8.01M ada0p1 - - 0 68 0 8.13M ada3p1 - - 0 74 0 8.88M logs - - - - - - mirror 128K 7.94G 0 0 0 0 ada1p3 - - 0 0 0 0 ada9p3 - - 0 0 0 0 cache - - - - - - ada9p5 40.0G 1.78M 0 0 0 0 ---------- ----- ----- ----- ----- ----- ----- capacity operations bandwidth pool alloc free read write read write ---------- ----- ----- ----- ----- ----- ----- zhome 731G 197G 0 369 0 16.3M mirror 731G 197G 0 369 0 16.3M ada0p1 - - 0 197 0 16.2M ada3p1 - - 0 191 0 15.5M logs - - - - - - mirror 13.8M 7.92G 0 0 0 0 ada1p3 - - 0 0 0 0 ada9p3 - - 0 0 0 0 cache - - - - - - ada9p5 40.0G 16.0E 0 63 0 7.96M ★★ここ★★ ---------- ----- ----- ----- ----- ----- ----- capacity operations bandwidth pool alloc free read write read write ---------- ----- ----- ----- ----- ----- ----- zhome 731G 197G 0 0 0 0 mirror 731G 197G 0 0 0 0 ada0p1 - - 0 0 0 0 ada3p1 - - 0 0 0 0 logs - - - - - - mirror 13.8M 7.92G 0 0 0 0 ada1p3 - - 0 0 0 0 ada9p3 - - 0 0 0 0 cache - - - - - - ada9p5 40.0G 1.40M 0 33 0 4.25M ---------- ----- ----- ----- ----- ----- ----- capacity operations bandwidth pool alloc free read write read write ---------- ----- ----- ----- ----- ----- ----- zhome 731G 197G 0 0 0 0 mirror 731G 197G 0 0 0 0 ada0p1 - - 0 0 0 0 ada3p1 - - 0 0 0 0 logs - - - - - - mirror 13.8M 7.92G 0 0 0 0 ada1p3 - - 0 0 0 0 ada9p3 - - 0 0 0 0 cache - - - - - - ada9p5 40.0G 924K 0 37 0 4.74M ---------- ----- ----- ----- ----- ----- ----- capacity operations bandwidth pool alloc free read write read write ---------- ----- ----- ----- ----- ----- ----- zhome 731G 197G 0 0 0 0 mirror 731G 197G 0 0 0 0 ada0p1 - - 0 0 0 0 ada3p1 - - 0 0 0 0 logs - - - - - - mirror 13.8M 7.92G 0 0 0 0 ada1p3 - - 0 0 0 0 ada9p3 - - 0 0 0 0 cache - - - - - - ada9p5 40.0G 424K 0 41 0 5.24M ---------- ----- ----- ----- ----- ----- ----- capacity operations bandwidth pool alloc free read write read write ---------- ----- ----- ----- ----- ----- ----- zhome 731G 197G 0 0 0 0 mirror 731G 197G 0 0 0 0 ada0p1 - - 0 0 0 0 ada3p1 - - 0 0 0 0 logs - - - - - - mirror 13.8M 7.92G 0 0 0 0 ada1p3 - - 0 0 0 0 ada9p3 - - 0 0 0 0 cache - - - - - - ada9p5 40.0G 16.0E 0 46 0 5.86M ★★ここ★★ ---------- ----- ----- ----- ----- ----- ----- capacity operations bandwidth pool alloc free read write read write ---------- ----- ----- ----- ----- ----- ----- zhome 731G 197G 0 77 0 9.12M mirror 731G 197G 0 77 0 9.12M ada0p1 - - 0 77 0 9.24M ada3p1 - - 0 84 0 10.1M logs - - - - - - mirror 13.8M 7.92G 0 0 0 0 ada1p3 - - 0 0 0 0 ada9p3 - - 0 0 0 0 cache - - - - - - ada9p5 40.0G 16.0E 0 0 0 0 ---------- ----- ----- ----- ----- ----- ----- L2ARCの空きが無くなると16.0Eになるっぽい。unsignedな型で負数を扱おうとして爆発してるように見える。というか、r273060のコミットログに、思いっきり「the number became negative and overflows」と理由が載っていた(´・ω・｀) 更にarc.cのログを追っていたら、r275096で修正がリバートされてるやないか！4Kセクタデバイスを考慮しておらず正しい修正ではなかったとの事……。解決には時間が掛かりそうな雰囲気。 L2ARCの空き容量が16EB(16.0E)と表示される件 zpool iostat -vしてて気付いたが、L2ARCの容量表示がおかしい。FreeBSD 10.1-RELEASE-p6で確認。 capacity operations bandwidth pool alloc free read write read write -------------- ----- ----- ----- ----- ----- ----- zhome 759G 169G 2 14 247K 500K mirror 759G 169G 2 14 247K 499K ada0p1 - - 1 6 123K 500K ada3p1 - - 1 6 125K 500K logs - - - - - - mirror 128K 7.94G 0 0 0 12.1K ada1p3.nop - - 0 0 1 12.1K ada9p3.nop - - 0 0 1 12.1K cache - - - - - - ada9p5 151G 16.0E 0 2 22.2K 358K 空き容量16.0EBの確保済み151GBって…。ada9p5は40GBしか無いんですけど。 r273060で修正された風には書かれてるが、再発報告（その1, その2）が上がってる。本記事を書いている時点でarc.cの最新リビジョンは先のr273060止まりなので、 → (2015-06-10追記:ウソ。arc.cの最新リビジョンのリンクはこっちで、リビジョンはr281109だった。) どこかにバグが残ってるんだろうなぁ。現に自分の所でも出てるわけだし。 表示上の問題ならいいけど、中身がバグってたら嫌なので当面L2ARCは外しておくとしよう。 ZFSのslog追加時もashift量に注意しよう zpool statusしたら「block size: 512B configured, 4096B native」なるメッセージが出ていた。 $ zpool status zhome pool: zhome state: ONLINE status: One or more devices are configured to use a non-native block size. Expect reduced performance. action: Replace affected devices with devices that support the configured block size, or migrate data to a properly configured pool. scan: resilvered 389G in 2h31m with 0 errors on Sun Mar 29 16:58:56 2015 config: NAME STATE READ WRITE CKSUM zhome ONLINE 0 0 0 mirror-0 ONLINE 0 0 0 ada0p1 ONLINE 0 0 0 ada3p1 ONLINE 0 0 0 logs mirror-1 ONLINE 0 0 0 ada1p3 ONLINE 0 0 0 block size: 512B configured, 4096B native ada9p3 ONLINE 0 0 0 block size: 512B configured, 4096B native cache ada9p5 ONLINE 0 0 0 物理4kセクタのデバイスに512バイト単位でアクセスしてて性能低下してるかもよっていうアレ。わざわざ報告してくれるなんてZFSは神。てか、slogのブロックサイズはプール本体のashiftと連動しないんすね… というわけで、一旦slogを消し、例によってgnopで4kセクタ化してslogを作りなおした。 $ sudo zpool remove zhome mirror-1 $ zpool status zhome pool: zhome state: ONLINE status: Some supported features are not enabled on the pool. The pool can still be used, but some features are unavailable. action: Enable all features using 'zpool upgrade'. Once this is done, the pool may no longer be accessible by software that does not support the features. See zpool-features(7) for details. scan: resilvered 389G in 2h31m with 0 errors on Sun Mar 29 16:58:56 2015 config: NAME STATE READ WRITE CKSUM zhome ONLINE 0 0 0 mirror-0 ONLINE 0 0 0 ada0p1 ONLINE 0 0 0 ada3p1 ONLINE 0 0 0 cache ada9p5 ONLINE 0 0 0 errors: No known data errors $ sudo gnop create -S 4096 /dev/ada1p3 $ sudo gnop create -S 4096 /dev/ada9p3 $ sudo zpool add zhome log mirror ada1p3.nop ada9p3.nop $ zpool status zhome pool: zhome state: ONLINE status: Some supported features are not enabled on the pool. The pool can still be used, but some features are unavailable. action: Enable all features using 'zpool upgrade'. Once this is done, the pool may no longer be accessible by software that does not support the features. See zpool-features(7) for details. scan: resilvered 389G in 2h31m with 0 errors on Sun Mar 29 16:58:56 2015 config: NAME STATE READ WRITE CKSUM zhome ONLINE 0 0 0 mirror-0 ONLINE 0 0 0 ada0p1 ONLINE 0 0 0 ada3p1 ONLINE 0 0 0 logs mirror-1 ONLINE 0 0 0 ada1p3.nop ONLINE 0 0 0 ada9p3.nop ONLINE 0 0 0 cache ada9p5 ONLINE 0 0 0 errors: No known data errors 一応、zdbで確認（ログの必要箇所のみ抜粋） children[1]: type: 'mirror' id: 1 guid: 12556410678957656274 metaslab_array: 52 metaslab_shift: 26 ashift: 12 asize: 8585216000 is_log: 1 create_txg: 13992340 children[0]: type: 'disk' id: 0 guid: 10904489644541021375 path: '/dev/ada1p3.nop' phys_path: '/dev/ada1p3.nop' whole_disk: 1 create_txg: 13992340 children[1]: type: 'disk' id: 1 guid: 18335897789017456858 path: '/dev/ada9p3.nop' phys_path: '/dev/ada9p3.nop' whole_disk: 1 create_txg: 13992340 ashift: 12になってるし、これで大丈夫だろう。nopデバイスは次に再起動した時に勝手に消えるだろうから、放置で。 ついでに、もう1個のプールも確認してみると… $ zpool status zdata pool: zdata state: ONLINE status: One or more devices are configured to use a non-native block size. Expect reduced performance. action: Replace affected devices with devices that support the configured block size, or migrate data to a properly configured pool. scan: scrub canceled on Sun Mar 22 10:40:27 2015 config: NAME STATE READ WRITE CKSUM zdata ONLINE 0 0 0 raidz1-0 ONLINE 0 0 0 ada5p1 ONLINE 0 0 0 ada10p1 ONLINE 0 0 0 ada12p1 ONLINE 0 0 0 raidz1-1 ONLINE 0 0 0 ada14p1 ONLINE 0 0 0 block size: 512B configured, 4096B native ada8p1 ONLINE 0 0 0 block size: 512B configured, 4096B native ada15p1 ONLINE 0 0 0 block size: 512B configured, 4096B native logs mirror-2 ONLINE 0 0 0 ada1p4 ONLINE 0 0 0 block size: 512B configured, 4096B native ada9p4 ONLINE 0 0 0 block size: 512B configured, 4096B native cache ada1p5 ONLINE 0 0 0 spares ada2p1 AVAIL errors: No known data errors ぉぉぉぉ、、、RAID-Zストライピングの片割れraidz1-1が見事にashitf=9になってやがる…。raidz1-1は後からashiftを考慮せずに、というよりもashiftがvdev単位？なのを知らずに追加したものなので当然っちゃ当然だが……。AFTには気をつけて作業して来たつもりだけど、こんな罠があったとはねorz にしても困った。zdataは3TB HDD×6本のプールなので、先のslogみたいに気軽に削除＆作り直しって訳にもいかんしなぁ。raidz1-1にashift=12のミラーを追加して・・・とも思ったが、ミラーのashiftはraidz1-1のが継承されそうな気がする。そもそもraidz1-1をミラーに出来るかも分からんし。もしかして詰んでる？ < Newer Posts 1 2 ... 43 44 45 46 47 48 49 ... 83 84 Older Posts > start.txt 最終更新: 2022-07-27 15:26by Decomo