2014年11月26日
Mac + emacs + PlantUML でさくさく UML 職人
例えば ./uml/ に uml ファイルを置いておいて ./img/ に UML の画像ファイルを書き出すような環境の場合。
JAVA_TOOL_OPTIONS="-Djava.awt.headless=true" watcher --dir ./uml/ -- 'java -jar /foo/bar/plantuml.jar ./uml/*.uml && open -g -a Preview ./img/*.png'のようなコマンドをバックグラウンドで起動しとくと、編集作業の邪魔されずに .uml ファイルが保存されるたびに全自動で画像を生成して Preview.app で開いといてくれる。
開いといてくれるけど Preview.app にフォーカスが移動しないと window 中の画像は反映されないので注意。
そしてwatcher コマンドはみなさんが嫌いな Perl でできていて CPANから入手できます。
2014年09月29日
#isucon 2014 に参加して暫定圏外になってきました
ISUCON4 の予選やってきました、最終スコアは37000位だったけど本戦足切りラインは45000くらいだと思うので残念でした。
チームメイトは、前回組んだ kamipo さんに加え新メンバー ar_tama さんと共に望みました。
役割としては
kamipo: 司令塔権 middleware 以下全部担当
ar_tama: アプリ担当
yappo: アプリ担当
リポジトリはこちら https://github.com/kamipo/isucon4qualifier
開始前
大体の凡ミスはレギュレーション読まない事に起因するのが、過去の ISUCON の教訓だからひたすらレギュレーション読む。
お陰でリーダの遅刻を見逃した。
10:00-12:00
開始とともにトイレ。この間に kamipo さんが必要なインスタンスあげてログイン出来るようになってた。
うちのチームは1人/1インスタンスという構成で始めた。理由としては去年1インスタンスでやったせいで、気づかない間に環境壊されてたり各人が施した成果のベンチマークを回すのに待ち行列が発生して無駄だったから。
インスタンスを別ける事で他人に影響する事無くひたすら開発を進められた。
ちなみに基本的にサーバのコードは触らずに yappo/master branch に commit してくスタイルだった。
最初に isucon user で直接ログインしようとしたけど、鍵置いても直接はどうしても無理だったから2分くらいで諦めた。ログインし続ければいいだけだし。
そして、標準の ruby でベンチマークを回す。
10:27 < Yappo> 01:26:52 type:score success:6090 fail:0 score:1316だった。
その後に ruby を止めて perl を有効にしようとしたら、まさかの forman が死なないトラブルがあったので kill してから plackupしてベンチを取った。
10:37 < Yappo> 01:35:55 type:score success:7530 fail:0 score:1627Perlにするだけでスコアが上がった。
workload 4とかにするだけで
10:50 < ar_tama> score 3335いったでした。
ベンチのスコアを確認した後は、ブラウザで見たときの見た目重視っていうゆるふわルールあったのでちゃんとアプリを使ってみようとしたんだけど、ログインしてから何も出来ない！銀行なのにローン組むリンクすらマトモにうごかない！！！
っていう挙動に不安になったので「いすこん銀行さん Safari でログインするとローン申し込めないんですが、それおっけーですか?」って質問したら問題ないって回答きてひと安心。
ISUCON4 予選で一番心に残った不具合報告は「住宅ローンの申し込みができないのですが」
— Issei Naruta (@mirakui) 2014, 9月 28
その後は benchmarker がどうなってるのかを一通り調べてて
//*[@id='last-logined-at']って書いてあるのを見つけた。たぶん「DOM を崩さない=このXPathで処理出来る事」だと理解した。
//*[@id='last-logined-ip']
//*[@id='notice-message']
もちろん input 要素や submit 周りの XPath も書いてあったので、ベンチマーク用の UA の時に表示する専用の HTML 返したら良いんだと思ったけど、そんなんおもろくないのでチームメンバーには黙ってた。
その後はテンプレートファイルを見る。
11:06 < Yappo> <span class="hikaru-mozi">偽画面にご注意ください！</span>いいセンスしてたので余計な所で時間くってた。。
11:06 < Yappo> これに釘付けだった
11:06 < ar_tama> ｗ
11:06 < Yappo> hiraku-mozi
11:06 < ar_tama> hikaru-mozi!!
11:06 < ar_tama> かわいい
11:08 < Yappo> [isucon@ip-10-127-131-242 ~]$ sudo zcat /var/log/nginx/access.log-20140926.gz | less
11:08 < Yappo> censored - - [26/Sep/2014:09:35:39 +0000] "GET /tmUnblock.cgi HTTP/1.1" 400 172 "-" "-"
11:08 < Yappo> censored - - [26/Sep/2014:10:27:58 +0000] "GET / HTTP/1.1" 200 2228 "-" "() { :;}; /bin/bash -c \x22echo testing9123123\x22; /bin/uname -a"ヒント探したつもりが全然品とじゃなかった案件もあった。。
その後はベンチ走らせた時のログを集計して top page -> login -> エラーだったら top page に戻る/成功だったら mypage を表示 という固定的なアクセスしかない事を把握した。
top page を開いた時に、必要な static file のリンク先を全部辿ってアクセスしにいく感じだった。
css を gz 化して見たものの当たり前だけどスコア落ちた。これは CPU 食ってて逆効果だったのか md5 checksum が一致してないのかわからんかったけど、余計な事なのですぐにやめた。
12:00-13:00
ここらで作戦タイムしながらアプリのコードを読んでく。
トラフィック的には / へのアクセスが支配的。 /login はクエリが重いので最後のボトルネックは /login 。そして /mypage の内容は実質 /login 時に取得したデータを使い回せる事を把握した。
/ に関しては、ログイン失敗時のエラーメッセージを動的に埋め込んでいるが、実際は5パターンのエラーしかないので、何かしらの状態をクライアント側に保持させて nginx 側で振り分けすれば application が処理しなくても良いはず。
/mypage に関しても /login 時に必要なデータを保持して nginx 側でレンダリングした方が早そう。
という結果を踏まえて、 benchmarker が任意の Set-Cookit を受け取って Cookie ヘッダで送ってくるかを調べ、それが可能である事を把握してから
1. 何も cookie が無い時に / へのアクセスがあったら nginx 側で静的コンテンツを返す
2. ログイン失敗時には error=nanntara という cookie を送信するので、その cookie がついた / へのアクセスは cookie の内容を考慮して適切な静的コンテンツを返す
3. ログイン成功したときは、最終ログイン情報を cookie に入れておくので、 nginx は cookie を元に ssi を使って /mypage のレンダリングをする
という、方針で動く事にした。
kamipo さんが nginx 周りの作業を全面的に行うあいだ、僕は暇になるので、自分は /login の重い処理を片付ける ar_tama さんは逆から攻めてく感じで /report 周りをやる感じになった。
本来は /report はカリカリにチューニングする意味ないんだけど、高スコアが叩けるようになった時に /report の負荷が高過ぎてベンチマーク成立しないリスクもあるので、先回りで。
13:00-15:00
このアプリはログイン時に失敗すると失敗カウントが増えていって、閾値を越えるとそのアカウントがロックされる。または ip address が ban リストに入って、どのアカウントにもログイン出来ない。
という仕組みが入っていたのですが、このログイン時に lock / ban をチェックする為のクエリが面倒いサブクエリで書かれていて index 使われてないので遅い。
これをまずどうにかする為に
CREATE TABLE IF NOT EXISTS `login_log` (という感じで index つけたら、これだけで score:1668 -> score:10027 に上がっていた。
`id` bigint NOT NULL AUTO_INCREMENT PRIMARY KEY,
`created_at` datetime NOT NULL,
`user_id` int,
`login` varchar(255) NOT NULL,
`ip` varchar(255) NOT NULL,
`succeeded` tinyint NOT NULL,KEY (user_id),
KEY (ip),
KEY (succeeded, user_id),
KEY (succeeded, ip)
) DEFAULT CHARSET=utf8;
でも index を貼る前に考えてた戦略があったので、一旦この案は取り消しました。
index 貼ってもログイン処理で lock/ban されたかどうか調べるクエリが複雑になるので、それらのクエリが簡単になるように予め失敗回数をカウントするだけのテーブルを用意しました。
CREATE TABLE IF NOT EXISTS `last_login_failure_count_user_id` (そうすると、ログイン時に login_log テーブルと追加したテーブルに対して3回も insert クエリが走ってしまうので trigger を使ってクエリ数を減らしました。
`user_id` int NOT NULL UNIQUE,
`count` int
) DEFAULT CHARSET=utf8;CREATE TABLE IF NOT EXISTS `last_login_failure_count_ip` (
`ip` varchar(255) NOT NULL UNIQUE,
`count` int
) DEFAULT CHARSET=utf8;
DELIMITER //また、 SELECT クエリが複数飛ぶのも点数下げるだけなので UNION でおまとめしてます。
CREATE TRIGGER login_log_insert AFTER INSERT ON login_log
FOR EACH ROW
BEGIN
IF NEW.succeeded = 1 THEN
DELETE FROM last_login_failure_count_user_id WHERE user_id=NEW.user_id;
DELETE FROM last_login_failure_count_ip WHERE ip=NEW.ip;
ELSE
INSERT INTO last_login_failure_count_user_id SET user_id=NEW.user_id, count=1 ON DUPLICATE KEY UPDATE count=count+1;
INSERT INTO last_login_failure_count_ip SET ip=NEW.ip, count=1 ON DUPLICATE KEY UPDATE count=count+1;
END IF;
END//
DELIMITER ;
(違うテーブルを UNION にまとめて結果を取り出すと、どの行が何のデータだかわからなくなるので1カラム目にラベルを入れておいて、それをプログラム側で成形してりようします。
SELECT 'user_id' AS name, count AS count FROM last_login_failure_count_user_id WHERE user_id = ?
) UNION (
SELECT 'ip', count FROM last_login_failure_count_ip WHERE ip = ?
)
ここら辺ずっと1並列でベンチ取ってたので、基本的にスコアが1万から変わらなくて辛かったけど次なる施策が控えてるので、このまま進んでた。
15:00-16:00
login 周りが一旦落ち着いたので、今度は /mypage で表示させるべきデータを /login で生成する作業に取りかかる。
/mypage で出しているのは前回ログインした時の ip address とログイン日時。という事で /login 叩かれた時点の user_id の最近の成功したログインのテーブルからデータを取れば良いという事になる。
ログイン履歴のテーブル(login_log)は、該当の user_id/ip address がいつログインしたか、それは成功したか失敗したか(succeededカラム)。という情報を入れてるので SELECT * FROM login_log WHERE succeeded=1 AND user_id=? ORDER BY id DESC みたいなクエリになるわけだけど、実は先ほど trigger の仕組みを作った時に
CREATE TABLE IF NOT EXISTS `last_login_success_user_id` (というテーブルを作ってて
`user_id` int NOT NULL UNIQUE,
`login_log_id` bigint NOT NULL
) DEFAULT CHARSET=utf8;CREATE TABLE IF NOT EXISTS `last_login_success_ip` (
`ip` varchar(255) NOT NULL UNIQUE,
`login_log_id` bigint NOT NULL
) DEFAULT CHARSET=utf8;
DELIMITER //という定義を作っていたので、それを利用して
CREATE TRIGGER login_log_insert AFTER INSERT ON login_log
FOR EACH ROW
BEGIN
IF NEW.succeeded = 1 THEN
INSERT INTO last_login_success_user_id SET user_id=NEW.user_id, login_log_id=NEW.id ON DUPLICATE KEY UPDATE login_log_id=NEW.id;
INSERT INTO last_login_success_ip SET ip=NEW.ip, login_log_id=NEW.id ON DUPLICATE KEY UPDATE login_log_id=NEW.id;
DELETE FROM last_login_failure_count_user_id WHERE user_id=NEW.user_id;
DELETE FROM last_login_failure_count_ip WHERE ip=NEW.ip;
ELSE
INSERT INTO last_login_failure_count_user_id SET user_id=NEW.user_id, count=1 ON DUPLICATE KEY UPDATE count=count+1;
INSERT INTO last_login_failure_count_ip SET ip=NEW.ip, count=1 ON DUPLICATE KEY UPDATE count=count+1;
END IF;
END//
DELIMITER ;
FROM last_login_success_user_id JOIN login_log ON last_login_success_user_id.login_log_id=login_log.id WHERE last_login_success_user_id.user_id = ?のようなクエリを作っていた。
もちろんこれも UNION でむりやり1クエリにまとめてたので
(みたいにして取ってた。
SELECT 'user_id' AS name, count AS count, NULL AS ip, NULL AS created_at FROM last_login_failure_count_user_id WHERE user_id = ?
) UNION (
SELECT 'ip', count, NULL, NULL FROM last_login_failure_count_ip WHERE ip = ?
) UNION (
SELECT 'last', NULL, ip, created_at FROM last_login_success_user_id JOIN login_log ON last_login_success_user_id.login_log_id=login_log.id WHERE last_login_success_user_id.user_id = ?
)
そして、そろそろ素の file に session data を書いてるのも良く無さそうなので。 /dev/shm 以下に書くようにしてメモリの上に session data を置くようにした。
ここで memcached 入れなかったのは、いきなり新規の daemon 突っ込もうとしてハマったら面倒、今まで1個のプロセスの中だけで session data の読み書きしてたのに突然別のプロセスに tcp socket 経由で処理するのは危険だしコンテキストスイッチやばそう。みたいな素人判断で安全にメモリ上に移行する方法を選びました。
この辺りまでは、ささいな typo でベンチマークがこける事はあったけど、それ以外の大きなトラブルは無く進んでた感じ。
ここで衝撃の事実
15:42 < Yappo> flash まわり kamipo 先生がやってたけど、どうなんだろうwflash まわりってのは / とか /mypage を nginx でどうにかするって言ってたやつなんだけど、結局 ssi がうまく動かせなくて諦めてしまったっぽい。
15:42 < ar_tama> ｗ
15:42 <@kamipo> それは挫折しましたｗ
15:42 <@kamipo> si
15:42 < Yappo> w
15:42 <@kamipo> し、使ってる / がめっちゃ速いから
16:00-17:00
という事で /mypage を nignx で処理する事は諦めたけど / は静的に返そうという話になった。
僕は事前の準備でベンチマークは path が不一致だと加点しないが、 query string が url に付与されてても加点対象となる事実をしってたので、 /login でエラーになったら /?error=xxx にリダイレクトして nginx で query string を処理して、全ての / へのレスポンスを静的に返そう！という話になった。
16:30 すぎた辺りから、まだ nginx の設定出来ない感じだったので全員で nginx の設定調べだすことになった。
ここからが真のデスマーチが始まって、だれも / を静的に返す nginx.conf が書けないまま1時間がすぎてしまい。途中経過に名前出てこないまま終わるのだけは嫌だ！というリーダの叫びもあって17時前に3万ちょい越えのスコアを送信してギリギリ名前を刻む事だけは出来たけど暫く進まず。。
17:00-17:40
全員でnginxを調べだして30分がすぎて、このままだともうダメだ！ってなってた頃に、ようやく僕が nginx で動く設定が解ったので、設定を試してベンチを回す事ができた。
まだ / だけ静的化しただけだったけど、すぐに error page を静的にする設定を入れて何とかベンチ通るようになった。
17:39 < Yappo> 08:37:49 type:score success:68790 fail:0 score:14859上が1並列で下が5並列くらいだとおもう。
17:39 < Yappo> 08:39:27 type:score success:159410 fail:0 score:34434
このくらいになると、まったく原因解らないけど僕のインスタンスだけが正しく動く環境になってました。
去年の本戦も同じくらいの時刻にもあったのですが、今回も「
もう最後の頼みの綱はやっぽさんだけや。。」って発言を頂いてしんみり。
結局、静的ファイル大作戦でスコアが1-2割上がったくらいでまだまだ足りんかった。
17:40-18:00
この後は悪あがきで Starman だったのを Starlet に入れ替えて workload を色々変えて試してみて、だいたい37000くらいのスコアで収束しそうだったので、天にも祈る気持ちでベンチマーク連打を他のメンバーにお願いして僕はトイレに行ってきました。
そして帰ってきた頃に終了です。
やり残した事
みなさんお分かりでしょうが trigger 周りが無駄すぎるので、そこはもっと効率よくする予定で進んでたのですが、さすがは本番でトラブル多発で時間足りなくなって、まともな感じにする前に撃沈でした。
最終的には MySQL の接続は /login のみで 1 write, 2 read クエリのみになってたけど、やはり /login での mysql 処理が支配的になってくるので users テーブルを全部 perl のコードに変換してクエリ数を減らす事もやりたかったです。
最後の手段で、ベンチマークの User-Agent の時だけ必要最小限な HTML を返すという事をやって終了させる目標があったけど、それもやりきれず残念。
スタート時に使ってる midllware を使い続けてキャッシュ戦略も取らなかった割には良いスコアだったのでは？？？
kamipo さんとか ar_tama さんとか、なんもバリュー出せてない言ってたけど細かい所直したり バグ見つけてくれたり kernel 設定したり middleware の調整したり ami 提出の調整するのとかバリューでまくってたよ！！
最初の戦略がちゃんと当たってれば、それこそすっごいバリューになってたし、今回は惜しい感じだっただけ！！
僕最初と最後に別のバリューだしてたけど。。。
反省点
スタートダッシュをゆっくりしない。最初と最後くらいトイレに行かない。
最後の静的ファイル返す時に Varnish 入れた方が良いと思ってたけど、普段やらない事を本番でやっちゃだめだという学びがありました。
こちらからは以上です。
#isucon で、やらんかった事
書いてる人
ISUCON が始まる直前のエンジニアチューニングコンテストで、レギュレーションで「特定のディレクトリ以下のファイルを弄ったら失格。それ以外は自由」って競技があったので、特定のディレクトリ以外の htppd.conf をいじって documentroot を変更して、ぶっちぎりのスコアをたたき出したら、ぶっちぎりすぎたと言う理由で失格になってマジイラっと来た人間。
最初やった事
- レギュレーションを良く読む
- テンプレートファイルを良く読む
- ベンチマーク実行する
- ベンチマークの User-Agent を見る
- 任意の Set-Cookie を返してもちゃんと処理するかどうか見る
- ログを awk ... | sort | unic -c |sort -r | more
- static file を.gz してファイル圧縮対応してる client かどうか試して無理なの確認する
- ベンチマークのバイナリを vim で開く
- strings ベンチマークのバイナリ
- ベンチマークで定義してる XPath に対して、 fail する条件を確定させる
やらなかったこと
- in memory storage(FAQみたらこれアウトなの確定してた)
- 公開されてる予選レギュレーション「レスポンス(HTML)のDOM構造」と「ブラウザで表示した際の見た目(問題ない範囲で)」と、実際のベンチマークバイナリから得た加点対象に最適な DOM 出力、そして実際の見た目で使用しうる User-Agent とベンチマークの User-Agent の差異を考慮した最短解
- 実際正しくレスポンス返しても誤差にしかならないもののレスポンスを捨てる行為
- IS NOT NULL なレコード作らんだろ！っていって、それ省く事
やったことの一部
- url の ? 以下が付与されてても加点に影響しない事を利用