RHEL(CentOS)6系でトラフィックをたくさん捌くサーバが死ぬ問題は6.5のkernel-2.6.32-431.el6以降で多分直る
タイトルで言いたいことはすべて言った。
経緯
うちの場合はLVS+keepalivedなロードバランサなんだけど、ちょくちょくkernel panicになる問題が発生してた。
そこでcrashコマンドで解析してみた。crashコマンドの使い方はこちらが参考になる。Linux crash dump 読み方入門
# crash /boot/System.map-2.6.32-279.14.1.el6.x86_64 /usr/lib/debug/lib/modules/2.6.32-279.14.1.el6.x86_64/vmlinux /var/crash/127.0.0.1-2013-09-27-16\:21\:01/vmcore
(snip)
SYSTEM MAP: /boot/System.map-2.6.32-279.14.1.el6.x86_64
DEBUG KERNEL: /usr/lib/debug/lib/modules/2.6.32-279.14.1.el6.x86_64/vmlinux (2.6.32-279.14.1.el6.x86_64)
DUMPFILE: /var/crash/127.0.0.1-2013-09-27-16:21:01/vmcore [PARTIAL DUMP]
CPUS: 8
DATE: Fri Sep 27 16:19:55 2013
UPTIME: 3 days, 15:03:51
LOAD AVERAGE: 0.01, 0.04, 0.00
TASKS: 283
NODENAME: XXXXXX(masked)
RELEASE: 2.6.32-279.14.1.el6.x86_64
VERSION: #1 SMP Tue Nov 6 23:43:09 UTC 2012
MACHINE: x86_64 (2128 Mhz)
MEMORY: 8 GB
PANIC: "kernel BUG at net/ipv4/tcp_ipv4.c:417!"
PID: 0
COMMAND: "swapper"
TASK: ffff88022a568aa0 (1 of 8) [THREAD_INFO: ffff88022a56c000]
CPU: 3
STATE: TASK_RUNNING (PANIC)ログ
crash> log (snip) kernel BUG at net/ipv4/tcp_ipv4.c:417! invalid opcode: 0000 [#1] SMP last sysfs file: /sys/devices/system/cpu/cpu7/cache/index2/shared_cpu_map CPU 3 Modules linked in: ip_vs_rr ip_vs_wlc ip_vs_wrr ipmi_si mpt2sas scsi_transport_sas raid_class mptctl mptbase ipmi_devintf ipmi_msghandler dell_rbu ip_vs libcrc32c 8021q garp stp llc ipv6 nf_nat_ftp nf_conntrack_ftp nf_connt rack_netbios_ns nf_conntrack_broadcast xt_limit ipt_REJECT xt_state xt_multiport iptable_filter ipt_LOG ipt_MASQUERADE xt_mark iptable_nat nf_nat nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 xt_MARK iptable_mangle iptable_ raw ip_tables power_meter ses enclosure sg bnx2 dcdbas microcode serio_raw iTCO_wdt iTCO_vendor_support i7core_edac edac_core ext4 mbcache jbd2 sr_mod cdrom sd_mod crc_t10dif pata_acpi ata_generic ata_piix megaraid_sas dm_m irror dm_region_hash dm_log dm_mod [last unloaded: ipmi_si] Pid: 0, comm: swapper Not tainted 2.6.32-279.14.1.el6.x86_64 #1 Dell Inc. PowerEdge R410/01V648 RIP: 0010:[<ffffffff81494c71>] [<ffffffff81494c71>] tcp_v4_err+0x5e1/0x5f0 RSP: 0018:ffff88002f863bd0 EFLAGS: 00010246 RAX: ffff8801bde90208 RBX: ffff880215d49c2c RCX: ffff8801bde90208 RDX: 00000000000007d0 RSI: 0000000000000002 RDI: ffff8801bde90188 RBP: ffff88002f863c50 R08: ffff8801bde90150 R09: ffff8801bde90188 R10: 0000000055d6096c R11: 0000000000000001 R12: ffff8801bde90140 R13: ffffffff8200cec0 R14: ffff880215d49c40 R15: 0000000000000071 FS: 0000000000000000(0000) GS:ffff88002f860000(0000) knlGS:0000000000000000 CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b CR2: 0000003da9613000 CR3: 0000000217c2f000 CR4: 00000000000006e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Process swapper (pid: 0, threadinfo ffff88022a56c000, task ffff88022a568aa0) Stack: ffff880000000001 ffffffffa01b3557 ffff880100000014 000000000000b0c6 <d> ffff8801bde90188 fd02a8c0fd02a8c0 0000c6b000000001 01ffffff00000000 <d> 0000000080000000 000000002f863cd8 0000000080000000 0000000000000006 Call Trace: <IRQ> [<ffffffffa01b3557>] ? ipv4_confirm+0x87/0x1d0 [nf_conntrack_ipv4] [<ffffffff8149f0d0>] icmp_unreach+0x140/0x2d0 [<ffffffff8149ee40>] icmp_rcv+0x290/0x330 [<ffffffff814718d0>] ? ip_local_deliver_finish+0x0/0x2d0 [<ffffffff814719ad>] ip_local_deliver_finish+0xdd/0x2d0 [<ffffffff81471c38>] ip_local_deliver+0x98/0xa0 [<ffffffffa0126813>] ? bnx2_poll_work+0x633/0x1270 [bnx2] [<ffffffff814710fd>] ip_rcv_finish+0x12d/0x440 [<ffffffff81471685>] ip_rcv+0x275/0x350 [<ffffffff81447390>] ? neigh_timer_handler+0x0/0x340 [<ffffffff8143adcb>] __netif_receive_skb+0x49b/0x6f0 [<ffffffff8143b0ba>] process_backlog+0x9a/0x100 [<ffffffff8143f7a3>] net_rx_action+0x103/0x2f0 [<ffffffff81073f61>] __do_softirq+0xc1/0x1e0 [<ffffffff81096d60>] ? hrtimer_interrupt+0x140/0x250 [<ffffffff8100c24c>] call_softirq+0x1c/0x30 [<ffffffff8100de85>] do_softirq+0x65/0xa0 [<ffffffff81073d45>] irq_exit+0x85/0x90 [<ffffffff81506450>] smp_apic_timer_interrupt+0x70/0x9b [<ffffffff8100bc13>] apic_timer_interrupt+0x13/0x20 <EOI> [<ffffffff81407a38>] ? poll_idle+0x38/0x80 [<ffffffff81407a13>] ? poll_idle+0x13/0x80 [<ffffffff81407c27>] cpuidle_idle_call+0xa7/0x140 [<ffffffff81009e06>] cpu_idle+0xb6/0x110 [<ffffffff814f754f>] start_secondary+0x22a/0x26d Code: 4c 8b 4d a0 e9 71 fc ff ff 89 d2 eb 8d be ca 01 00 00 48 c7 c7 6e 46 80 81 e8 8c 6b bd ff 44 8b 55 98 4c 8b 4d a0 e9 1e fd ff ff <0f> 0b eb fe 90 90 90 90 90 90 90 90 90 90 90 55 48 89 e5 48 83 RIP [<ffffffff81494c71>] tcp_v4_err+0x5e1/0x5f0 RSP <ffff88002f863bd0>
バックトレース
crash> bt
PID: 0 TASK: ffff88022a568aa0 CPU: 3 COMMAND: "swapper"
#0 [ffff88002f863890] machine_kexec at ffffffff8103284b
#1 [ffff88002f8638f0] crash_kexec at ffffffff810ba982
#2 [ffff88002f8639c0] oops_end at ffffffff81501b00
#3 [ffff88002f8639f0] die at ffffffff8100f26b
#4 [ffff88002f863a20] do_trap at ffffffff815013f4
#5 [ffff88002f863a80] do_invalid_op at ffffffff8100ce35
#6 [ffff88002f863b20] invalid_op at ffffffff8100bedb
[exception RIP: tcp_v4_err+1505]
RIP: ffffffff81494c71 RSP: ffff88002f863bd0 RFLAGS: 00010246
RAX: ffff8801bde90208 RBX: ffff880215d49c2c RCX: ffff8801bde90208
RDX: 00000000000007d0 RSI: 0000000000000002 RDI: ffff8801bde90188
RBP: ffff88002f863c50 R8: ffff8801bde90150 R9: ffff8801bde90188
R10: 0000000055d6096c R11: 0000000000000001 R12: ffff8801bde90140
R13: ffffffff8200cec0 R14: ffff880215d49c40 R15: 0000000000000071
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
#7 [ffff88002f863c58] icmp_unreach at ffffffff8149f0d0
#8 [ffff88002f863c98] icmp_rcv at ffffffff8149ee40
#9 [ffff88002f863ce8] ip_local_deliver_finish at ffffffff814719ad
#10 [ffff88002f863d18] ip_local_deliver at ffffffff81471c38
#11 [ffff88002f863d48] ip_rcv_finish at ffffffff814710fd
#12 [ffff88002f863d88] ip_rcv at ffffffff81471685
#13 [ffff88002f863dc8] __netif_receive_skb at ffffffff8143adcb
#14 [ffff88002f863e28] process_backlog at ffffffff8143b0ba
#15 [ffff88002f863e78] net_rx_action at ffffffff8143f7a3
#16 [ffff88002f863ed8] __do_softirq at ffffffff81073f61
#17 [ffff88002f863f48] call_softirq at ffffffff8100c24c
#18 [ffff88002f863f60] do_softirq at ffffffff8100de85
#19 [ffff88002f863f80] irq_exit at ffffffff81073d45
#20 [ffff88002f863f90] smp_apic_timer_interrupt at ffffffff81506450
#21 [ffff88002f863fb0] apic_timer_interrupt at ffffffff8100bc13
--- <IRQ stack> ---
#22 [ffff88022a56ddf8] apic_timer_interrupt at ffffffff8100bc13
[exception RIP: poll_idle+56]
RIP: ffffffff81407a38 RSP: ffff88022a56dea8 RFLAGS: 00000246
RAX: 0000000400000000 RBX: ffff88022a56ded8 RCX: 000000000000001f
RDX: ffff88022a56dfd8 RSI: ffff88002f87dcd0 RDI: ffffffff81a8fc40
RBP: ffffffff8100bc0e R8: 0000000000000004 R9: 0000000000000010
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000002 R15: 0000000000000050
ORIG_RAX: ffffffffffffff10 CS: 0010 SS: 0018
#23 [ffff88022a56dee0] cpuidle_idle_call at ffffffff81407c27
#24 [ffff88022a56df00] cpu_idle at ffffffff81009e06得られた情報からググってみたところ、これと全く同じ症状だった。
kernel panic in tcp_v4_err() on icmp unreachable
該当パッチは2011年1月にリリースされた2.6.37で取り込まれているのだが、2.6.32を採用したRHEL6にはバックポートされていなかった。ちなみにDebianには2012年9月にリリースされた2.6.32-46でバックポートされた模様。
Debian Bug report logs - #685087
そこでRedHatのbugzilla（一般非公開）に報告したものの待てど暮らせどと変化なし。
あとでRedHatの中の人に聞いたところによると、
RHELの開発者はどれだけ深刻な問題でもBugzillaから直接報告されたバグ報告は見てない。RHNのライセンスを介して報告しないと本家には伝わらない。
とのこと。あらーそうなのね。
でも運良くRedHatの人に拾ってもらえて、古いバグ報告（こちらも非公開）にmarked as duplicateされた後、RHEL6.5のリリースと共に修正が取り込まれた。
カーネルのリリースノートにはこのバグ修正に関する言及はないのだが、同じ問題で悩まれていた方は是非カーネルアップデートをご検討ください。
追記1
Bug #757658とBug #1014877が非公開になっているのは、セキュリティのリスクを考慮してだと思う。CVEとして報告されているわけでもないので。ちなみにBug #757658が登録されたのは2011年11月28日。約2年越しのバグ修正だった*1。
追記2
RedHatの中の人より
Red Hat BugzillaはRHELクローンのバグ報告をする先ではない。RHELのサブスクリプション契約には契約期間内の回数無制限の問い合わせ権がついているのでカスタマーポータルから問い合わせて欲しい。>> http://t.co/K9FAlnkFN0
— Hajime Taira (@htaira) December 3, 2013ちなみに昔はご丁寧に拾ってくれていたそうです。いつからそのような方針に変わったかは不明。
*1:ちなみに私が報告したBug #1014877の登録日は2013年10月2日
金に物を言わせてISUCONのプログラムをc3.8xlargeで動かしてみた
先日AWSから新しいEC2インスタンスタイプc3.8xlargeが発表されましたね。
【AWS発表】 新世代の数値計算向けEC2インスタンス
2013年11月時点の性能と価格は以下のとおり。ISUCON予選で使用したm3.xlargeと比較。
| インスタンスタイプ | vCPU | ECU | Memory(GiB) | Tokyoリージョンの1時間あたりのオンデマンド価格 |
|---|---|---|---|---|
| m3.xlarge | 4 | 13 | 15 | 0.684ドル |
| c3.8xlarge | 32 | 108 | 60 | 3.064ドル |
CPU性能約8倍、メモリ4倍。価格約4.5倍。c3.8xlargeお得。
さて、オンデマンドの価格は上のとおりですが、開始後すぐのためか需要が少なくスポットインスタンスが激安なんですね。
- Amazon(Web Services)が大セール！c3.8xlargeがなんと！$0.0001！！
- 新しいHPC向けAmazon EC2インスタンス"c3.8xlarge"が大セールしていたので簡単なベンチマークをとった
先ほど確認したところ、まだ0.005ドルだったのを確認。
ちなみにm3.xlargeは0.148ドル。
0.005ドルは安い！これは今試しておかないと損！そこでISUCONのプログラムをm3.xlargeとc3.8xlargeで試してみました。
本選プログラム
公式のAMIと構築手順を元に構築。ベンチマークコマンドは以下の通り。
$ carton exec perl bench.pl -d /home/isucon/image_source http://127.0.0.1/
プログラムには一切手を加えてません。
m3.xlarge
starting benchmark: concurrency: 6, time: 60 done benchmark: score 2139.77336684146, elapsed 60.681 sec = 35.263 / sec
スコアは2139.8。うんまぁそんなもん。
c3.8xlarge
starting benchmark: concurrency: 6, time: 60 done benchmark: score 3703.04509395234, elapsed 62.458 sec = 59.289 / sec
スコアは3703.0。うーむ、もっと爆速になるかと思いきや、そうでもなかった。
おそらくストレージ（EBS）にファイルを生成する部分がボトルネックになっているのではないかと思われます。
予選プログラム
予選プログラムについても同様に試してみました。公式AMIを使い、プログラムには一切手を加えてない。
# isucon3 benchmark
m3.xlarge
Result: SUCCESS RawScore: 1162.8 Fails: 0 Score: 1162.8
1162.8。うん、そんなもんでしたね。
c3.8xlarge
Result: SUCCESS RawScore: 836.6 Fails: 0 Score: 836.6
836.6。えっ。
何度かやってみたがほぼ同じ。成績下がった。なんでやねん。
おそらくCPUの並列性が上がったせいでMySQLで詰まった感じでしょうか。ちゃんと検証してません。
isucon3本選に└('-'└)└)└)＜HEARTBEATSとして参加した＆予選本選を通して得た知見
11月9日に開催されたisucon3本選にチーム「└('-'└)└)└)＜HEARTBEATS」*1として参加してきました。
結果は惨敗だったのですが、当日やったことと、予選本選を通して得た知見を書き留めておきます。
当日やったこと
画像のサムネイル作成をなんとかするためImager使ったら孔明の罠
ベンチマーク中にtopを眺めているとconvertコマンドがボトルネックになっていたのでここをなんとかしようと試みてみました。
convertを呼び出す代わりにImagerを使ってサムネイルを作成してみたのですが、Imagerだと差分検出でエラーになってしまいました。見事な孔明の罠ですね。やられた。
Image::Magickのインストールに手間取る
Imagerが差分検出で引っかかるので早々にあきらめてImage::Magickを使おうとしたのですが、cpanfileに
requires "Image::Magick";
を追記してcartonを実行してもインストールがエラーになって入らない。
includeするファイルが足りないのどうのと言われるので
yum install ImageMagick-devel
を実行してからインストールしてもダメ。なんだ。あ、もしかしてバージョンの問題か！幸いremiリポジトリが入ってたので、
yum remove ImageMagick ImageMagick-devel yum install ImageMagick-last ImageMagick-last-devel
とすることでcartonでImage::Magickのインストールはできた…のだが、何故かStarletが起動する際にはImage::Magickがないって怒られる。なんでや。local::lib環境でXSはあかんのん？
よくわからないままApp::cpanminusでImage::Magickをインストールしてみたら
cpanm Image::Magick
あれ、なんかいけたっぽい。
Image::Magickで再実装するもエラー解消できず
PerlMagickのドキュメントを見ながらImage::Magickを実装するも、何故かうまく実装できず。試行錯誤するも時間がもったいないので途中で断念しました。
413 Request Entity Too Largeが出てて時間を若干とられた
あるタイミングでベンチマーク実行時のエラーで413 Request Entity Too Largeが出ててなかなか解決せず。nginxからapacheに戻すと解消したことからclient_max_body_sizeを指定してなかったことに気づいたわけですが、上記Image::Magickでの再実装とタイミングが重なっていたので原因究明に時間がかかってしまいました。
/tmpをtmpfsでマウントしたが性能下がった
Image::Magickによる実装がうまくいかないのでconvertコマンドのまま実装を進めていたわけですが、convertコマンドはtempfile()を吐き出し先として使っていたため、/tmpをtmpfsでマウントすればちょっとは性能上がるんじゃね？と思いマウントしてみたのですが、逆に性能が下がってしまったので断念。キャッシュに割くメモリの領域を食ってしまったからですかね？よくわからず。
サムネイル作成時にファイル保存
サムネイルを作成するタイミングでしておき、ファイルが存在する場合はファイルを直接返すことで性能が改善しました。サムネイルを作成するタイミングを変更するといった処理変更は実施してません。
timeline表示のSLEEPを2秒から1秒に
timelineで値が取得できなかった場合に2秒間待機する処理が入っていましたが、これを1秒に変更、またtimelineで都度ユーザ情報を取得してた部分をPerl上でキャッシュ、UPDATEがかかったときはPerlのキャッシュを削除*2するなどいたところ、6100程度までスコアが伸びていました。が、このあたりが自分の限界でした。
スケールアウトの方法をきちんと考えておらず1台構成のままフィニッシュ
終盤に複数台を活用する方法を考えるも良い案が思いつかず、とりあえず
- 5台ともフロントにする
- 画像投稿の時だけ1台目にproxyして1台目で処理
- 投稿された画像はlsyncdで他4台に同期
- 投稿以外は5台それぞれで処理
なんてザックリ考えていて、その準備が終わらずフィニッシュ。ついでに試行錯誤してるうちにスコアもだだ下がりしてて散々な結果となりました。チーン。
予選本選を通して得た知見
Varnishはできる子
予選の復習をしてる際に思ったのが、Varnishはとてもできる子なんじゃないか説。
httpdとStarmanの間にvarnishを挟むだけで良しなにキャッシュしてくれてスコアが1100→2000と改善しました。
さらに予選のようにそのままではキャッシュしにくいパターンでもESIを駆使することで比較的簡単に部分キャッシュが可能なのでかなり使えるのではないかと感じました。
本選のようなパターンだと素直にキャッシュできないので簡単には使えませんけどね…。でもモジュールが豊富で
とかあるし結構いけるんじゃないかと思います。
apachetopとwtopは惜しい子
アクセスログからどのクエリが多いか、時間がかかっているかを調べるのにapachetopやwtopが便利でした。
単純にログを見るだけなので、Apacheと同じ形式でログ出力すればnginxと組み合わせても使えます。
wtopはクラスを定義すればログの種類をまとめることができるのでとても良いのですが、HTTPメソッド毎の分類ができないのがちょっと残念です。改善してpull requestを送りたい。そのうち。
今回もプロファイラのDevel::NYTProfを使いこなせなかった
isucon予選でDevel::NYTProfをうまく使いこなせなくて、そのことをツイートしたらmiyagawaさんから
— Tatsuhiko Miyagawa (@miyagawa) October 29, 2013とヒントを頂いたのですが、それでもうまく使いこなせず。Devel::NYTProfは今後の課題です。
追記：検証してみたところ、最新版のPlack::Middleware::Profiler::NYTProfを使うと Kossy::__ANON__が上位にくることもなく綺麗にプロファイリングできていい感じでした。
最後に
└('-'└)└('-'└)└('-'└)└('-'└)└('-'└)
"ISUCON 準備お疲れさまでした!!"
ありがとうございました!
来年もよろしくお願いいたします!
└('-'└)└('-'└)└('-'└)└('-'└)└('-'└)
2chの書き込み規制のしくみを調べてみた
スレを読み進めていくと、どうやら
206.223.144.0/20
207.29.224.0/19
からのTCPポート
443
995
1723
へのアクセスをフィルタすれば書き込めるらしい。
書き込むたびにTCPポートスキャンをしているの？と興味が湧いたので調べてみた。
ちなみに元記事には情報源スレッドのURLが記載されているが、読み方がわからなかったので読んでない。
Twitterに全部書いたので再掲
tcpdumpで確認したのだが、上記の443、995、1723以外は確認できなかった。2,3回しか試してないので実際には他のパターンもあるかもしれない。2ch側からTCPポートスキャンがされる件を検証してみた。「書き込む」のボタンを押したらすぐにポートスキャンきた。207.29.225.225からTCPポート443、995、1723にSYNきた。クッキーを持ってない場合に届く模様。クッキー削除したらまたきた。
— └('-'└)└)└)＜matsuu (@matsuu) November 2, 2013
クッキーを食わせた状態でもう一度書き込んだ場合はポートスキャンは来なかった。
書き込みテストは「2ch 書き込み テスト」でググって出てきたここに。
書き込みテスト 専用スレッド637
書き込みの作法を知らないのでよくわからなかったんだけども。
ポートの待ち受けはPerlでIO::Socket::INETを使ってテキトーに書いた。2chの続き、各ポートを待ち受けて書き込みしてみたところ、Request Time-outになった。TCPのハンドシェイクのあと即FIN-ACK送ってるのでポートが空いてるかのみ確認してる。443→995→1723の順でポートスキャンしてて、どれか1つでも空いてたら拒否してる模様
— └('-'└)└)└)＜matsuu (@matsuu) November 2, 2013
#!/usr/bin/perl use strict; use warnings; use IO::Socket::INET; my $s = IO::Socket::INET->new(Listen => 5, LocalPort => $ARGV[0], Proto => 'tcp', ReuseAddr => 1) or die $!; $s->listen; while(my $c = $s->accept) { while(my $q = $c->getline) { print $q; $c->print($q); } $c->close; } $s->close;
3ハンドシェイク後にFIN-ACKをすぐ投げてるので何も出力されなかった。
ISUCON3予選でチーム└('-'└)として参加した＆やったこと
ISUCON3の予選にチーム└('-'└)として参加してきました。スコアは10784.5で暫定15位、問題がなければ本戦に進める予定です。
以下、やったことをつらつらと。
チーム編成
今回は職場の同僚であるyamasakiさんとfujiwaraさんと私の3人で参戦しました。自分以外は初参加だったため、本戦を見越してOJTで進めました。残念ながらSELinuxはdisabledです。
ちなみに弊社からは学生枠暫定2位のチーム( (0) / (0)) ☆祝☆も参戦しています。
事前準備
前日の夕方、Amazon Management Consoleで、AMIの選択からログインするところまでシミュレーションをしておきました。
ちなみにその際にAmazon IAMで自分以外のアカウントも作り、3人のうち誰でもログインできるようにしておきました。もしAMIの作成も時間内に行う必要があるのであれば、作業分担ができるようにするためです。
当日序盤
前日にシミュレーションしておいたこともあって、AMI-idの公開から実際にインスタンスを起動するところまでスムーズに実行することができました。
開始から10分で最初のベンチマーク実行、この時点で暫定一位。
まず状況を確認、Apache、MySQL、supervisord経由で起動されたStarmanなどを確認、自分はPerlが慣れているのでPerlのまま進めることにしました。
負荷の確認はdstatとtopで
負荷の状況はdstatとtopで確認してました。topからmysqldの負荷が高いこと、dstatからI/Oが多いことを確認していました。
ちなみに、dstatのオプションは-tlampが好きです。
dstat -tlamp
/etc/my.cnfがなかったけど気にしない
MySQLのチューニングをするためにmy.cnfを探してみたものの簡単には見つからなかったのですが、そんなことはあまり気にせず、MySQLの設定を/usr/share/doc/MySQL-server-5.6.14/からもってきて、そこに一般的なチューニングパラメータを追加していきました。
cp /usr/share/doc/MySQL-server-5.6.14/my-default.cnf /etc/my.cnf
適当な設定を投入後、mysqldのrestartで設定が反映されていることを確認。
また、環境に合わせたパラメータチューニングは何度かベンチマークを回したあとに
MySQLTuner-perlを使いました。これ仕事でも愛用してます。
wget -O mysqltuner.pl mysqltuner.pl
perl mysqltuner.pl
Apacheからnginx変更
Apacheからnginxに変更して/css,/js,/img,favicon.icoのリソースはnginxから返すようにしました。
location / { proxy_pass http://localhost:5000; proxy_set_header Host $host; } root /home/isucon/webapp/public; location /css { access_log off; } location /js { access_log off; } location /img { access_log off; } location /favicon.ico { access_log off; }
またその際にアクセスログに$request_timeを追加して、どのリクエストの応答時間が遅いのかを出力するようにしました。
log_format main '$request_time $remote_addr - $remote_user [$time_local] "$request" ' '$status $body_bytes_sent "$http_referer" ' '"$http_user_agent" "$http_x_forwarded_for"';
あとで集計しやすいように頭に追加。
上記のtop、dstatと合わせてリクエストの応答時間もチューニングの指標にしています。
MySQLのテーブルにインデックスを張る
PerlのプログラムからSELECTのクエリをgrepして、必要なテーブルにインデックスを追加しました。
grep SELECT /home/isucon/webapp/perl/lib/Isucon3/Web.pm
ALTER TABLE memos ADD INDEX (is_private, created_at); ALTER TABLE memos ADD INDEX (user, created_at); ALTER TABLE memos ADD INDEX (user, is_private, created_at);
ただ、手動でインデックスを追加してもベンチマークを回すたびにインデックスがなくなり、/home/isucon/webapp/config/schema.sqlのCREATE TABLE文に追記しても反映されなかったため、インデックスを追加するシェルスクリプトを作成し、ベンチマーク実行時の--initオプションでスクリプトを実行するようにしました。
/home/isucon/init.sh
( echo 'ALTER TABLE memos ADD INDEX (is_private, created_at);' echo 'ALTER TABLE memos ADD INDEX (user, created_at);' echo 'ALTER TABLE memos ADD INDEX (user, is_private, created_at);' ) | mysql -u root -proot isucon 2>/dev/null
isucon3 benchmark --init=/home/isucon/init.sh
プログラムからの応答を1秒間キャッシュして返すようにしてみるがチェックに引っかかるので諦めた
1秒程度の短い時間ならキャッシュしても問題ないんじゃないかと考え、isucon_sessionのクッキー所有者ごとにキャッシュする実装に変えてみました。
proxy_cache_path /dev/shm/nginx_cache levels=1:2 keys_zone=default:512m inactive=1m max_size=512m;
proxy_temp_path /dev/shm/tmp;
(中略)
set $do_not_cache 0;
(中略)
proxy_no_cache $do_not_cache;
proxy_cache_bypass $do_not_cache;
proxy_cache default;
proxy_cache_methods GET HEAD;
proxy_cache_key "$scheme$proxy_host$request_uri$cookie_isucon_session";
proxy_cache_valid 200 1s;がしかし、どうやってもベンチマークプログラムのチェックがエラーになり解決できそうにないため、ここにこだわるのはやめてキャッシュすることを諦めています。
MySQLでクエリーキャッシュを部分的に有効にした
memosは何度も更新されるからクエリーキャッシュを効かせても逆効果と考えて、SQL_CACHE構文で特定のクエリに対してのみキャッシュを行うようにSQLを書き換えました。
my.cnf
query_cache_size = 128M
query_cache_limit = 64M
query_cache_type = 2
Web.pm変更例
-'SELECT * FROM users WHERE id=?', +'SELECT SQL_CACHE * FROM users WHERE id=?', -'SELECT username FROM users WHERE id=?', +'SELECT SQL_CACHE username FROM users WHERE id=?', -'SELECT id, username, password, salt FROM users WHERE username=?', +'SELECT SQL_CACHE id, username, password, salt FROM users WHERE username=?',
トップページや/recent/:pageなどで毎回ユーザ情報を取得していた部分をキャッシュするようにした
このあたりからプログラムのソースを本格的に見始めました。応答時間が遅いリクエストが/recent/:pageだったのでそのあたりを中心に確認したところ、無駄にSELECTしている部分があったのでPerlでキャッシュするようにしました。
変更前
for my $memo (@$memos) { $memo->{username} = $self->dbh->select_one( 'SELECT SQL_CACHE username FROM users WHERE id=?', $memo->{user}, ); } || 変更後 >|perl| my $cache = {}; for my $memo (@$memos) { my $user = $memo->{user}; unless (exists $cache->{$user}) { $cache->{$user} = $self->dbh->select_one( 'SELECT SQL_CACHE username FROM users WHERE id=?', $user, ); } $memo->{username} = $cache->{$user}; }
この部分ではJOINでの実装も試してみたのですが、圧倒的に遅くなったので元に戻して上のようなキャッシュ実装に変更しています。最終的にmy $cache = {};は一番外側に追い出してグローバル変数のように扱いました。
Plack::Middleware::Profiler::NYTProfでプロファイリングしてみたがよくわからなかった
こちらの記事を参考にしながらPlack::Middleware::Profiler::NYTProfを導入してみたのですが、うまく使いこなせませんでした。NYTProfを入れた状態でbenchmarkを走らせたために沢山プロファイル結果が生成されてしまい、どれを見ればいいのかわからなくなったんですね。今思えばブラウザなどでアクセスしてみて確認すればよかったんや…。
NYTProfの結果からuri_for()の処理に時間がかかっていた
NYTProfをうまく使いこなせなかったものの、確認すると$c.req.uri_for()の処理に時間がかかっていたことから、$c.req.uri_for()の部分は絶対URLを直書きにしてみました。
しかし絶対URL直書きだとなぜかベンチマークのチェックに引っかかってしまうため直書きを諦めて、以下のように毎回呼ばないようにしました。
変更前
: for $memos -> $memo {
<li>
<a href="<: $c.req.uri_for('/memo/') :><: $memo.id :>"><: $memo.content.split('\r?\n').first() :></a> by <: $memo.username :> (<: $memo.created_at :>)
</li>
: }変更後
: my $memourl = $c.req.uri_for('/memo/')
: for $memos -> $memo {
<li>
<a href="<: $memourl :><: $memo.id :>"><: $memo.content.split('\r?\n').first() :></a> by <: $memo.username :> (<: $memo.created_at :>)
</li>
: }
innodb_log_fileを/dev/shm/に移した
途中ディスクフルになる事態が発生したため容量の削減を図っていたのですが、その時にふとinnodb_log_fileをtmpfsに載せればいいんじゃないかと気づき、innodb_log_group_home_dirを/dev/shm/に移してみました。
innodb_log_file_size = 1G
innodb_log_files_in_group = 4
innodb_log_group_home_dir = /dev/shm/
innodb_log_fileは起動時に存在しなくても作成されること、レギュレーション的にも問題ないことから移したのですが、その結果ディスクI/Oがほとんどなくなりました。これ結構効いたかも。
/memo/:idのolder,newerが無駄だったのでなんとかした
/memo/:idも応答時間が遅いリクエストだったため、以下のように書き換えています。うおおお俺のSQL力が試されている！
変更前
my $memos = $self->dbh->select_all( "SELECT * FROM memos WHERE user=? $cond ORDER BY created_at", $memo->{user}, ); my ($newer, $older); for my $i ( 0 .. scalar @$memos - 1 ) { if ( $memos->[$i]->{id} eq $memo->{id} ) { $older = $memos->[ $i - 1 ] if $i > 0; $newer = $memos->[ $i + 1 ] if $i < @$memos; } }
変更後
my $newer = $self->dbh->select_row("SELECT SQL_CACHE id FROM memos WHERE user=? AND id > ? $cond ORDER BY id ASC LIMIT 1", $memo->{user}, $memo->{id}); my $older = $self->dbh->select_row("SELECT SQL_CACHE id FROM memos WHERE user=? AND id < ? $cond ORDER BY id DESC LIMIT 1", $memo->{user}, $memo->{id});
もっと効率のいいSQLがあったかもしれませんが、まぁこんな感じに。
外部プログラムのmarkdownを呼び出しているところをText::Markdownに書き換えた
プログラム内でMarkdown書式をhtmlに展開するためにmarkdownコマンドを呼び出している部分に気づいたため、ググって最初にでてきたText::Markdownに置き換えました。Text::Markdownに置き換えてもベンチマーク上は問題がなかったことから、それ以上は深く追求はしてません。
いらないカラムを取っ払ったりとか不要な書き換えUPDATEを削除とか
SELECT * FROM ...としている部分は、実際に使われているカラムを調べてカラムを直指定にしたり、usersテーブルのlast_accessカラムの更新はどこからも参照されてないので取っ払ったり、saltの生成に使用しているsha256_hex()を外したりしました。
禁断のtcp_rw_reuseを有効にした
副作用が大きいため普段仕事では使わないnet.ipv4.tcp_tw_reuseを1に設定しました。ベンチマークと対象サーバが同一で閉じたネットワークのためです。/etc/sysctl.confに追記したのはとりあえず以下の通り。
net.ipv4.tcp_tw_reuse = 1 net.ipv4.tcp_fin_timeout = 30 net.ipv4.tcp_tw_recycle = 1 net.ipv4.ip_local_port_range = 16384 65535
ベンチマークプログラムの--workerを1ずつ増やしていった
このあたりはもう終盤ですが、isucon3 benchmarkの--workerをデフォルトの1から2に変更したところスコアが上がったので、徐々に数字を増やしていき一番スコアが高くなるところを探りました。
だいたい7か8あたりがピークで一番いいスコアになり、それ以上はTimeoutが頻発する状況となりました。
全力で/etc/motdを作りこんだが失敗に終わった
終盤、運営の皆様へ愛のメッセージを伝えようと/etc/motdを作りこんだのですが、サーバが再起動すると/etc/motdがAmazon Linux側で上書きされてしまうらしく、我々のメッセージは残念ながら届けられませんでした。残念。
まとめ
本戦ではmotdをしっかりとキメたい。
運営の皆様ありがとうございます。お疲れ様でしたあああああ！
Hacker Newsなど英語のfeedを効率よく読む方法
2012年10月ごろから海外の技術ネタが集うHacker Newsを読んで、気になる記事をはてブに登録するだけの簡単なお仕事を続けている。
本家RSSをベースに、リンク先のコンテンツを可能な限りRSSに取り込んだものを生成してFeedlyで読んでいる*1のだが、このRSSは流量が多い。先ほど数えてみたところ過去1週間分で748件あった。
そこで私がどうやって読んでいるかについて紹介してみようと思う。
タイトルだけを見てふるいにかける仕組みづくり
記事数が多いと1つ1つの記事に目を通していては時間がいくらあっても足りない。特に母語でない記事はどうしても読むのに時間がかかってしまう。なので出来るだけタイトルから見ないものを判別できる仕組みをまず用意することが重要。
試行錯誤の結果、一番高速に読む方法はスマートフォンの活用だった。私の場合はAndroidのFeedlyアプリだが、以下のような設定を施している。
- Auto Mark as Read
- スワイプすると既読になる設定
- Long Press to Save
- 長押しで「後で読む」に入れる
- Transision = Stack
- 記事一覧で縦にスワイプすると一気に既読へ
- Default View = Title Only
- Title Onlyだが実際には本文の冒頭部分だけ表示される
これで気になる記事を長押しであとで読むマークをつけておき、どんどん既読にしていく。
画面イメージはこんな感じ。縦スワイプで次ページへどんどん移動。
別にフィードリーダーはFeedlyである必要はなく何でもいいのだが、同じように記事を高速に消化できる仕組みを用意することが重要だと思う。
ちなみにFeedlyを使う前はGoogle ReaderクライアントであるGoodNewsというAndroidアプリを愛用していた。今でもGoodNewsを超えるフィードリーダーは見つかっていないのだが、Google Readerのサービス終了とともにGoodNewsの更新も停止してしまった。
幸いソースコードはgithubで公開されており、先日FeedlyのAPIも公開されたのでGoodNewsに復帰したいところ。時間を見つけて取り組みたい。
自分にとってのNGワードを見つける
日本語のタイトルに慣れている身としては、英語のタイトルは大抵情報不足で中身が推測できないことが多い。最初のうちは後で読むもので溢れてしまうかもしれない。
が、数をこなしていくと特定の言葉が含まれている場合は興味がわかないことに気づくはずだ。興味を惹かれる記事は人それぞれだと思うが、参考までに私にとってのNGワードは以下のような感じ。
- 国名・地名
- お国事情をつらつらと説明してるのであまり興味ない
- startup、entrepreneur、launch、funding、CEO、acquireなど
- 成功するスタートアップとはどうのこうのとか、興し方とか、買収されたとか、まぁどうでもいい
- AskHN、Pollなど
- HackerNews読者に聞け！的なやつなのでまぁスルー
- ○○ is down
- どこそこのサービスが落ちてるとか、ああそうですか。しかも結構多い
- iOS7
- ここ最近はこればかりだったが、Android派なので興味なかった
逆に以下のような場合は積極的にあとで読むのマークをつけている。
- ShowHNなど
- サービス開発者がHackerNewsに自分のサービスを紹介する時につけるprefix。もちろん微妙なサービスもあるがShowHNは一応目を通してる。ShowHNの記事だけを集めたサイトもある。
- やたらタイトルが短い記事
- 経験的にそっけないタイトルの記事の方がアタリの場合が多い気がする。
あとで読むをしっかり回収
あとで読むに入れたものは、私はPCで確認するようにしている。英語の記事を読む場合はじっくり腰を据えないと私は読めないので。
PCで読むそのタイミングで良さそうな記事であればはてブに登録している次第。
pointsはアテにならない
HackerNewsは記事やコメントにを評価するポイント制度があって高ければ人気が高い記事のはずなのだが、江添さんもおっしゃるバカの流入が目立つせいなのか、私が求める記事はあまり評価されてないことが多い。ポイントが高い記事に絞ってフィードを生成しているサービスもあるが、pointsは高くないけど良いものが結構あるというのが私の印象である。
コメント(ディスカッション)が面白い
HackerNewsを同じように読んでた昔の同僚（母語は英語）曰く、「HackerNewsはコメントが盛り上がってる記事は面白い、コメントを見てから記事を読むか判断している」のだそうだ。
コメントで似たようなサービスが紹介されてたり、リンク先の間違いを指摘していたりするので覗いてみると良い。
matsuu.netのRSSにはコメントへのリンクをRSS本文の先頭と最後に追加している。
まとめ
フィードを消化するだけで一日が終わる日々がここ最近続いているのでもうちょっとなんとかしたい。またHackerNewsは最近（自分にとって）ノイズな投稿が多く正直ツラい。そろそろ誰かにバトンタッチしたい。誰かあとは任せた。
*1:読み始めたときはGoogle Readerだった
フルサービスリゾルバのIPアドレスを調べるサービス作ってみた
DNS問い合わせで再帰的に権威サーバに問い合わせを行うリゾルバのことをフルサービスリゾルバと言いますが、フルサービスリゾルバのIPアドレスを調べるサービスが見つからなかったので作ってみました。
q.matsuu.net
q.matsuu.netにAレコードを問い合わせるとフルサービスリゾルバのIPアドレスを返します。
例えばGoogle Public DNSのフルサービスリゾルバはこんな感じ。
$ dig @8.8.8.8 q.matsuu.net. a +short 74.125.16.211
8.8.8.8やないんやね。
$ dig @208.67.222.222 q.matsuu.net. a +short 208.67.219.14
これまた別アドレスなんやね。
@で指定しなければ、今ご自身が利用しているDNSキャッシュサーバのフルサービスリゾルバのIPアドレスが取れるでしょう。
$ dig q.matsuu.net. a +short
q.matsuu.netの権威サーバであるaws.matsuu.netに直接問い合わせた場合、digコマンドがフルサービスリゾルバになるので自分自身のグローバルアドレスがわかりますね。やったね！
$ dig @aws.matsuu.net q.matsuu.net. a +short
aws.matsuu.netサーバはAWSシンガポールリージョンのt1.microで動作させてます。あんまりイジメないで下さい。
