VMサーバが壊れた話 - アーキテクチャをスマートに。

開発のVM母艦となっていたサーバがどうにも調子悪い。
VM上のLinuxで突然lsコマンドが異常終了したり、Windowsがブルースクリーンで落ちてしまったり。
そうなると、母艦のOS自体がおかしくなってシャットダウンさせようとするとフリーズしてしまう。

これはまずい。壊れたかも。慌ててデータをバックアップして別PCにVMを移行し、そっちで開発を継続しながら、サーバを復旧させることにした。
なお構築時の記録はこちら。 http://d.hatena.ne.jp/architect-wat/20130311/1363015729 http://d.hatena.ne.jp/architect-wat/20130312/1363080429

とりあえず

とりあえず apt-get upgrade してみたが、状況は変わらず。むしろ余計調子が悪くなった気がする。（汗
ちなみに使用OSは Ubuntu Server 12.04.02、VMファイル保存領域のファイルシステムは SSD RAID 5 上のXFS、搭載メモリは 8GB x4。

upgradeしない方が良かったかなと思い、いっそのことOSを入れ替えてみた。

安定性を求めるならやっぱりCentOS！と思って CentOS 6.4 のインストールを試みるもチップセットのドライバがないようであっさり失敗。
やはりサーバ機の安定運用には枯れたハードウェアが一番だと痛感。
そうは言っても仕方ないので、Ubuntu Server 13.04 をインストール、ついでに XFS をやめて EXT4 にしてみた。
それでもやっぱりダメ。
バックアップファイルを rsync でコピーしてくる最中にコンソールにドカドカとログを吐いて止まってしまう。shutdown -h now するとフリーズ。
コンソールにはこんなログが。

Aug 11 16:53:12 cambria kernel: [21382.947033] BUG: soft lockup - CPU#0 stuck for 22s! [ATA-0:2299]
Aug 11 16:53:12 cambria kernel: [21382.948512] Modules linked in: xfs(F) libcrc32c(F) pci_stub vboxpci(OF) vboxnetadp(OF) vboxnetflt(OF) vb
oxdrv(OF) ib_iser rdma_cm ib_addr iw_cm ib_cm ib_sa ib_mad ib_core iscsi_tcp(F) libiscsi_tcp(F) libiscsi(F) scsi_transport_iscsi(F) snd_hda
_codec_hdmi snd_hda_codec_realtek coretemp kvm_intel kvm ghash_clmulni_intel(F) aesni_intel(F) aes_x86_64(F) xts(F) lrw(F) gf128mul(F) ablk
_helper(F) cryptd(F) snd_hda_intel snd_hda_codec snd_hwdep(F) snd_pcm(F) snd_page_alloc(F) snd_seq_midi(F) snd_seq_midi_event(F) psmouse(F)
 microcode(F) serio_raw(F) lpc_ich snd_rawmidi(F) snd_seq(F) i915 snd_seq_device(F) snd_timer(F) snd(F) mei drm_kms_helper soundcore(F) drm
 i2c_algo_bit video(F) mac_hid lp(F) parport(F) raid10(F) raid456(F) async_raid6_recov(F) async_memcpy(F) async_pq(F) async_xor(F) xor(F) a
sync_tx(F) r8169 ahci(F) libahci(F) raid6_pq(F) raid1(F) raid0(F) multipath(F) linear(F)
Aug 11 16:53:12 cambria kernel: [21382.959215] CPU 0 
Aug 11 16:53:12 cambria kernel: [21382.959231] Pid: 2299, comm: ATA-0 Tainted: GF     D    O 3.8.0-19-generic #29-Ubuntu To Be Filled By O.
E.M. To Be Filled By O.E.M./H77 Pro4-M
Aug 11 16:53:12 cambria kernel: [21382.963606] RIP: 0010:[<ffffffff8112f71e>]  [<ffffffff8112f71e>] find_get_page+0x1e/0xa0
Aug 11 16:53:12 cambria kernel: [21382.965104] RSP: 0018:ffff8806804f3ae0  EFLAGS: 00000202
Aug 11 16:53:12 cambria kernel: [21382.966592] RAX: ffff880278255660 RBX: ffffffff81829780 RCX: ffff880278255660
Aug 11 16:53:12 cambria kernel: [21382.968087] RDX: 0000000000000001 RSI: 0000000000004143 RDI: 0000000000000000
Aug 11 16:53:12 cambria kernel: [21382.969596] RBP: ffff8806804f3af0 R08: ffff880278255630 R09: 0000000000000005
Aug 11 16:53:12 cambria kernel: [21382.971131] R10: ffffffff81829780 R11: 0000000000000000 R12: ffffffff81829780
Aug 11 16:53:12 cambria kernel: [21382.972649] R13: ffff8806804f3ad0 R14: ffffea0009b7c4c0 R15: ffff8806804f3ac0
Aug 11 16:53:12 cambria kernel: [21382.974155] FS:  00007fabf0121700(0000) GS:ffff88081f200000(0000) knlGS:0000000000000000
Aug 11 16:53:12 cambria kernel: [21382.975693] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 11 16:53:12 cambria kernel: [21382.977195] CR2: 00007f2b33e9ca08 CR3: 00000007f22f3000 CR4: 00000000001407f0
Aug 11 16:53:12 cambria kernel: [21382.978711] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Aug 11 16:53:12 cambria kernel: [21382.980240] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Aug 11 16:53:12 cambria kernel: [21382.981751] Process ATA-0 (pid: 2299, threadinfo ffff8806804f2000, task ffff880682e01740)
Aug 11 16:53:12 cambria kernel: [21382.983300] Stack:
Aug 11 16:53:12 cambria kernel: [21382.984795]  0000000000000004 ffff8807e1edf3f8 ffff8806804f3b18 ffffffff8112fb6a
Aug 11 16:53:12 cambria kernel: [21382.986338]  0000000000000004 ffff8807e1edf3f8 0000000000004143 ffff8806804f3b58
Aug 11 16:53:12 cambria kernel: [21382.987880]  ffffffff8112ff8c ffff8806804f3b58 0000000000000004 ffff8807e1edf2b0
Aug 11 16:53:12 cambria kernel: [21382.989410] Call Trace:
Aug 11 16:52:41 cambria kernel: [21352.689371]  [<ffffffff8112fb6a>] find_lock_page+0x2a/0x80
Aug 11 16:52:41 cambria kernel: [21352.689400]  [<ffffffff8112ff8c>] grab_cache_page_write_begin+0x6c/0xf0
Aug 11 16:52:41 cambria kernel: [21352.689436]  [<ffffffff812344a1>] ext4_da_write_begin+0xb1/0x250
Aug 11 16:52:41 cambria kernel: [21352.689467]  [<ffffffff8112edc3>] generic_file_buffered_write+0x113/0x270
Aug 11 16:52:41 cambria kernel: [21352.689502]  [<ffffffff81130a84>] __generic_file_aio_write+0x1b4/0x3d0
Aug 11 16:52:41 cambria kernel: [21352.689537]  [<ffffffff81196174>] ? __sb_start_write+0x54/0x110
Aug 11 16:52:41 cambria kernel: [21352.689568]  [<ffffffff81130d1f>] generic_file_aio_write+0x7f/0x100
Aug 11 16:52:41 cambria kernel: [21352.689600]  [<ffffffff8122da49>] ext4_file_write+0xa9/0x420
Aug 11 16:52:41 cambria kernel: [21352.689630]  [<ffffffff811a6924>] ? set_fd_set+0x44/0x60
Aug 11 16:52:41 cambria kernel: [21352.689658]  [<ffffffff811939e7>] do_sync_write+0xa7/0xe0
Aug 11 16:52:41 cambria kernel: [21352.689687]  [<ffffffff811940cc>] vfs_write+0xac/0x180
Aug 11 16:52:41 cambria kernel: [21352.689714]  [<ffffffff81194412>] sys_write+0x52/0xa0
Aug 11 16:52:41 cambria kernel: [21352.689742]  [<ffffffff816d379d>] system_call_fastpath+0x1a/0x1f
Aug 11 16:52:41 cambria kernel: [21352.691133] Code: e5 41 54 49 89 f4 53 48 8d 5f 08 4c 89 e6 48 89 df e8 b2 c2 21 00 48 85 c0 48 89 c6 74 3a 48 8b 10 48 85 d2 74 26 f6 c2 03 75 4c <8b> 4a 1c 85 c9 74 d9 8d 79 01 4c 8d 4a 1c 89 c8 f0 0f b1 7a 1c 
Aug 11 16:52:41 cambria kernel: [21352.694262] RIP  [<ffffffff8112f733>] find_get_page+0x33/0xa0
Aug 11 16:52:41 cambria kernel: [21352.695800]  RSP <ffff8807eff27ae0>
Aug 11 16:52:41 cambria kernel: [21352.697272] CR2: 000000000010001c
Aug 11 16:52:41 cambria kernel: [21352.703295] ---[ end trace f2e38340029b4322 ]---


Aug 11 16:52:41 cambria kernel: [21352.688024] BUG: unable to handle kernel paging request at 000000000010001c
Aug 11 16:52:41 cambria kernel: [21352.688072] IP: [<ffffffff8112f733>] find_get_page+0x33/0xa0
Aug 11 16:52:41 cambria kernel: [21352.688109] PGD 7f1437067 PUD 7f08da067 PMD 0 
Aug 11 16:52:41 cambria kernel: [21352.688140] Oops: 0000 [#1] SMP 
Aug 11 16:52:41 cambria kernel: [21352.688164] Modules linked in: xfs(F) libcrc32c(F) pci_stub vboxpci(OF) vboxnetadp(OF) vboxnetflt(OF) vb
oxdrv(OF) ib_iser rdma_cm ib_addr iw_cm ib_cm ib_sa ib_mad ib_core iscsi_tcp(F) libiscsi_tcp(F) libiscsi(F) scsi_transport_iscsi(F) snd_hda
_codec_hdmi snd_hda_codec_realtek coretemp kvm_intel kvm ghash_clmulni_intel(F) aesni_intel(F) aes_x86_64(F) xts(F) lrw(F) gf128mul(F) ablk
_helper(F) cryptd(F) snd_hda_intel snd_hda_codec snd_hwdep(F) snd_pcm(F) snd_page_alloc(F) snd_seq_midi(F) snd_seq_midi_event(F) psmouse(F)
 microcode(F) serio_raw(F) lpc_ich snd_rawmidi(F) snd_seq(F) i915 snd_seq_device(F) snd_timer(F) snd(F) mei drm_kms_helper soundcore(F) drm
 i2c_algo_bit video(F) mac_hid lp(F) parport(F) raid10(F) raid456(F) async_raid6_recov(F) async_memcpy(F) async_pq(F) async_xor(F) xor(F) a
sync_tx(F) r8169 ahci(F) libahci(F) raid6_pq(F) raid1(F) raid0(F) multipath(F) linear(F)
Aug 11 16:52:41 cambria kernel: [21352.688690] CPU 0 
Aug 11 16:52:41 cambria kernel: [21352.688705] Pid: 2215, comm: rsync Tainted: GF          O 3.8.0-19-generic #29-Ubuntu To Be Filled By O.
E.M. To Be Filled By O.E.M./H77 Pro4-M
Aug 11 16:52:41 cambria kernel: [21352.688766] RIP: 0010:[<ffffffff8112f733>]  [<ffffffff8112f733>] find_get_page+0x33/0xa0
Aug 11 16:52:41 cambria kernel: [21352.688809] RSP: 0018:ffff8807eff27ae0  EFLAGS: 00010246
Aug 11 16:52:41 cambria kernel: [21352.688836] RAX: ffff8802782554c0 RBX: ffff880683c25780 RCX: ffff8802782554c0
Aug 11 16:52:41 cambria kernel: [21352.688869] RDX: 0000000000100000 RSI: ffff8802782554c0 RDI: 0000000000000000
Aug 11 16:52:41 cambria kernel: [21352.688903] RBP: ffff8807eff27af0 R08: ffff8802782553f8 R09: 0000000000000018
Aug 11 16:52:41 cambria kernel: [21352.688937] R10: ffffffff81829780 R11: 0000000000000000 R12: 0000000000137296
Aug 11 16:52:41 cambria kernel: [21352.688970] R13: 0000000000137296 R14: 000000000102005a R15: 0000000000000050
Aug 11 16:52:41 cambria kernel: [21352.689005] FS:  00007faa91261740(0000) GS:ffff88081f200000(0000) knlGS:0000000000000000
Aug 11 16:52:41 cambria kernel: [21352.689043] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 11 16:52:41 cambria kernel: [21352.689071] CR2: 000000000010001c CR3: 00000007efe95000 CR4: 00000000001407f0
Aug 11 16:52:41 cambria kernel: [21352.689105] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Aug 11 16:52:41 cambria kernel: [21352.689139] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Aug 11 16:52:41 cambria kernel: [21352.689173] Process rsync (pid: 2215, threadinfo ffff8807eff26000, task ffff8807f0882e80)
Aug 11 16:52:41 cambria kernel: [21352.689211] Stack:
Aug 11 16:52:41 cambria kernel: [21352.689223]  0000000000000004 ffff880683c25778 ffff8807eff27b18 ffffffff8112fb6a
Aug 11 16:52:41 cambria kernel: [21352.689267]  0000000000000004 ffff880683c25778 0000000000137296 ffff8807eff27b58
Aug 11 16:52:41 cambria kernel: [21352.689311]  ffffffff8112ff8c ffff8807eff27b58 0000000000000004 ffff880683c25630
Aug 11 16:52:41 cambria kernel: [21352.689354] Call Trace:
Aug 11 16:52:41 cambria kernel: [21352.689371]  [<ffffffff8112fb6a>] find_lock_page+0x2a/0x80
Aug 11 16:52:41 cambria kernel: [21352.689400]  [<ffffffff8112ff8c>] grab_cache_page_write_begin+0x6c/0xf0
Aug 11 16:52:41 cambria kernel: [21352.689436]  [<ffffffff812344a1>] ext4_da_write_begin+0xb1/0x250
Aug 11 16:52:41 cambria kernel: [21352.689467]  [<ffffffff8112edc3>] generic_file_buffered_write+0x113/0x270
Aug 11 16:52:41 cambria kernel: [21352.689502]  [<ffffffff81130a84>] __generic_file_aio_write+0x1b4/0x3d0
Aug 11 16:52:41 cambria kernel: [21352.689537]  [<ffffffff81196174>] ? __sb_start_write+0x54/0x110
Aug 11 16:52:41 cambria kernel: [21352.689568]  [<ffffffff81130d1f>] generic_file_aio_write+0x7f/0x100
Aug 11 16:52:41 cambria kernel: [21352.689600]  [<ffffffff8122da49>] ext4_file_write+0xa9/0x420
Aug 11 16:52:41 cambria kernel: [21352.689630]  [<ffffffff811a6924>] ? set_fd_set+0x44/0x60
Aug 11 16:52:41 cambria kernel: [21352.689658]  [<ffffffff811939e7>] do_sync_write+0xa7/0xe0
Aug 11 16:52:41 cambria kernel: [21352.689687]  [<ffffffff811940cc>] vfs_write+0xac/0x180
Aug 11 16:52:41 cambria kernel: [21352.689714]  [<ffffffff81194412>] sys_write+0x52/0xa0
Aug 11 16:52:41 cambria kernel: [21352.689742]  [<ffffffff816d379d>] system_call_fastpath+0x1a/0x1f
Aug 11 16:52:41 cambria kernel: [21352.691133] Code: e5 41 54 49 89 f4 53 48 8d 5f 08 4c 89 e6 48 89 df e8 b2 c2 21 00 48 85 c0 48 89 c6 74
 3a 48 8b 10 48 85 d2 74 26 f6 c2 03 75 4c <8b> 4a 1c 85 c9 74 d9 8d 79 01 4c 8d 4a 1c 89 c8 f0 0f b1 7a 1c 
Aug 11 16:52:41 cambria kernel: [21352.694262] RIP  [<ffffffff8112f733>] find_get_page+0x33/0xa0
Aug 11 16:52:41 cambria kernel: [21352.695800]  RSP <ffff8807eff27ae0>
Aug 11 16:52:41 cambria kernel: [21352.697272] CR2: 000000000010001c
Aug 11 16:52:41 cambria kernel: [21352.703295] ---[ end trace f2e38340029b4322 ]---

OS入れ替え前のログもこんな感じでした。rsyncじゃなくてcpを使っても同じ。
カーネルのバグなのか？
コールスタックを見ても出力されるたびに様々で、原因はよくわからず。

むむ〜っ、これは困った。

Free BSD を試してみる

RAIDがおかしいのかなと思いRAIDをやめることも考えたが、それでは耐障害性がなくなってしまうので何か別の対策を用意する必要がある。
そこで前から気になっていた Free BSD RELEASE 9.1 で ZFS を試して見ることにした。

この辺*1を参考に（というかまるごと同じ手順で）インストール。
無事にインストールは出来たが、Virtual Boxをportsから入れようとして32bitライブラリがないと言われ、先にそちらを入れることに。
するとmakeが途中でエラーになってしまう。portsを最新化したり make clean したり config を変えてみたり色々やってると、いつの間にかインストールできた。この時の挙動もちょっと怪しい。（汗
さていよいよ Virtual Box を入れようとすると、やはり make でエラー。clean して何回もチャレンジしてみるも、どうやっても通らない。
もう何がおかしいのかよくわからなくなってしまい、やはり使い慣れた Linux の方がトラブったときに手が早いな〜と実感。

というわけで Free BSD は断念。Ubuntu Server 13.04 を入れなおしました。

冷静に状況を分析

ここまでで復旧開始から1週間が経過。日々の開発業務終了後、連日深夜までサーバのおもり。
そろそろ行き当たりバッタリの対応を客観視し始め、情報を整理し、冷静に状況を分析してみることに。（最初からそうしなさい自分）

仮説：やっぱりSSDが不良を起こしているのかも。

smartを見ても異常は見られず。
hdparm -t を試してみると、初期構築時からパフォーマンスは若干低下しているが、異常なほどではない。

SSDについてググっていると Secure Eraze というものを知る。USBメモリからブートして hdparm を使って Secure Eraze を試みるが、どうやっても frozen が解除されず、断念。

第一、ディスク異常が起きた時のためのRAIDなのに、カーネルが落ちてしまっては意味がない。
Secure Eraze を行わなくても安定動作する方法を探すべきと判断。

discard オプションを付けてマウントしているので、Trimコマンドは発行できているはず。
と信じていたが、RedHatのマニュアルを見つけて驚愕。ガーン。どうやら md デバイスでは Trimコマンドをサポートしていない模様。Ubuntu 13.04でもそうなのか確かめるため、LVMで領域を切って mkfs.ext4 してみると、discarding と表示されてdiscardしていることがわかったが、mdデバイス上で mkfs.ext4 するとそれが行われない。mount -o discard した時の syslog に　

EXT4-fs (md1): mounting with "discard" option, but the device does not support discard
EXT4-fs (md1): mounted filesystem with ordered data mode. Opts: discard

と出る。

でもそれは障害原因とは関係ないはず。パフォーマンスは低下しても運用を継続できるはず。

仮説：ハードウェア異常

もうこれしかないのか。
せっかく気に入ったハードウェア構成だったのに、異常があるのならばもう使えないな〜（涙目

もう何回目かわからないくらいのUbuntu Serverのインストーラブート画面。ふと memtest86 が目に入ったので、実行してみた。

久しぶりに見たブルーのテスト画面。その数秒後、真っ赤なログが表示された。