読者です 読者をやめる 読者になる 読者になる

Fluent::Logger(Perl)をFluentd 0.14のSub-second timeに対応した

Fluentd 0.14 がリリースされましたね。

Fluentd v0.14.0 has been released | Fluentd

新機能が盛りだくさんですが、そのうちの一つ Sub-second time (秒未満の解像度のtimestamp) に Fluent::Logger 0.18で対応しました。

<source>
  type forward
</source>

<match **>
  @type file
  path  ./test
  time_format %Y-%m-%dT%H:%M:%S.%N
</match>

このような fluentd.conf で fluentd 0.14 で起動して、以下のように event_time オプションを真にした Fluent::Logger から送信すると、

#!/usr/bin/env perl
use 5.12.0;
use Fluent::Logger;
use Time::HiRes;
my $logger = Fluent::Logger->new( event_time => 1 );
$logger->post(
    test => { foo => "bar" },
);
$logger->post_with_time(
    test => { foo => "baz" },
    1464845619.12345, # floatで指定
);

以下のように秒以下の精度を持った時刻でログを送信できます。

2016-06-02T14:40:52.251250982    test    {"foo":"bar"}
2016-06-02T14:33:39.123450040    test    {"foo":"baz"}

Perl側のinterfaceは浮動小数点数なので、正確にはnanosecond単位の精度はありません。もし精度が必要なら、floatではない値で指定できるような方法を検討するのでお知らせください。時刻指定なしの post() では内部で Time::HiRes::time() を呼び出してその時刻を送信しています。

ちなみに送信先が fluentd 0.12 の場合に event_time => 1 で送信するとエラーが発生しますのでご注意ください。(クラッシュはしないようですが)

[error]: forward error error=#<MessagePack::MalformedFormatError: invalid byte>
error_class=MessagePack::MalformedFormatError

Enjoy!

#shibuyago #2 で Stretcher の実装について話した

Shibuya.go#2 という勉強会で、自分が開発している Pull型デプロイツール Stretcher について発表してきました。 shibuyago.connpass.com

発表資料はこちらです。 speakerdeck.com

Goの勉強会なので、Stretcherの実装で使われているTips的なコードの紹介を多めにしてみました。

ちなみに資料中で紹介している copyAndCalcHash の実装は、既にPRをいただいて io.MultiWriter によってすっきりきれいになっています。

copyAndCalcHash is simplified by io.MultiWriter by shogo82148 · Pull Request #13 · fujiwara/stretcher · GitHub

会場とピザ、ビールを提供していただいた VOYAGE GROUP 様、主催の @suzu_v 様、ありがとうございました!

nginx実践入門

「nginx実践入門」 を著者の @cubicdaiya さんからいただきました。ありがとうございます。 簡単ですが感想など。

nginx実践入門 (WEB+DB PRESS plus)

nginx実践入門 (WEB+DB PRESS plus)

感想

一通り読んだ感想としては、本書は「『実践』入門」であっていわゆる入門書ではないのですね。 手取り足取りしてくれるわけではなく、リファレンスの詳解でもなく、あくまで実践的に運用する人へ向けての、実用的な使い方の入り口を紹介してくれる本でした。

特に最近重要性の高い TLS(SSL) での安全でハイパフォーマンスな設定、大規模コンテンツ配信サーバの構築を例とした多段 proxy 構成、実用的なログ出力と Fluentd によるメトリクスモニタリングなど、本番環境でサービスを運用するために役立つ情報が多く載っています。

今時は Web サーバの運用は単体で完結するものではなく、モニタリングや周辺システムとの連動が必須になってきているという事情を踏まえての構成だと感じました。

また、ngx_lua, OpenResty についての情報は、日本語書籍ではほぼ初めての登場になるかと思います。Lua はうまく使うと nginx 単体ではトリッキーな設定になるようなものも分かりやすくなるので、ありがたいですね。

気になったところ

6章でアプリケーションにクライアントの IP アドレスを伝達するために、

proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;

アプリケーションはX-Forwarded-Forヘッダの最も初めに存在するアドレスを使用することでユーザの送信元アドレスを把握できます。 (140ページ)

という部分があるのですが、この設定では nginx はクライアントが X-Forwarded-For ヘッダを付けてリクエストした場合、クライアントの IP アドレスを「追加」してアプリケーションに渡す形になります。

$ curl http://127.0.0.1/
→ X-Forwarded-For: 127.0.0.1

$ curl -H 'X-Forwarded-For: 192.168.1.1' http://127.0.0.1/
→ X-Forwarded-For: 192.168.1.1, 127.0.0.1

そのため、アプリケーションが先頭のアドレスを見た場合、その値は信用できないため、アクセス制限を回避されてしまう可能性がありそうです。

realip_module を使用して nginx が $remote_addr を偽装できない形で識別した上でアプリケーションに渡すか、

real_ip_header X-Forwarded-For;
real_ip_from [信頼できる接続元(多段proxyの親、ELBなど)のアドレス範囲];
proxy_set_header X-Forwarded-For $remote_addr;

アプリケーション側では X-Forwarded-For ヘッダの先頭ではなく末尾 (N段構成の場合は末尾からN番目) のものを見る必要があるかと思います。(基本的には最後の値は直接通信しているnginxが付けているので安全)

最後に

出版記念のイベントで LT をさせていただくことになりました。カヤック(の Lobi というサービス) で nginx + Lua (openresty) をどう活用しているかをお話しする予定です。

eventdots.jp

Consul 0.4.x から 0.5.2 へのバージョンアップ

このエントリは HashiCorp Advent Calendar 2015 - Qiita 1日目の記事です。

Consul クラスタは一度稼働を始めたら基本的に落とせないため、いわゆるローリングアップグレードによってクラスタ全体を停止せずにバージョンを上げることが考慮されています。

consul.io

ということで基本的には上記のURLを参照して、順番にagentを新しいバイナリで起動し直すことによって新しいバージョンに切り替えられるわけですが、Consul 0.5.0, 0.5.1 についてはいくつか留意点がありますので記録しておきます。

consul.io

0.5.0 未満から 0.5.0 以上にする場合

  • acl 機能を使っている場合、あらかじめ acl_policy を設定してからアップグレードする必要があります
    • が、自分は使用していなかったのでスルー
  • Leader が Consul 0.5 の場合、followerもすべて 0.5 である必要があります
    • Followerをすべて 0.5 にして、最後に Leader を 0.5 に上げる
    • 任意の順番で上げてもよいが、その場合は15分以内にすべてを 0.5 にする

なぜ15分なのかよく分かっていませんが、厳しい時間制限があると心臓によろしくないので、Leaderを最後にする方法でやるのがよいでしょう。

バージョンアップの作業の順番を間違えなければ問題はありませんが、サーバが最小構成の3台しかない状態では、1台作業中に他のサーバに障害が発生すると危険なので、可能であれば一時的に5台構成にするのをおすすめします。

また、新しく起動したサーバがちゃんと 0.5 で、クラスタに正常に組み込まれているかはよくよくログなどで確認しましょう。もし新しいサーバが join できず、サーバが足りない状態で別のを作業開始してしまうとクラスタ崩壊コースです。

0.5.1 未満から 0.5.1 以上にする場合

Consul 内部で使用している DB が、LMDB から BoltDB に変更になっています。

0.5.x では起動時に自動で migration が行われますので、特に事前準備する必要はなくバイナリを入れ替えて起動し直すだけです。上記ページには以下のようなログがでたら完了だよ、と書いてあるので、

==> Successfully migrated raft data in 5.839642ms

つい「ふんふん数msでおわるのね」と思ってしまいますが……環境によってはもっと時間がかかるようです。 手元のEC2 (t2.medium, gp2 disk) のインスタンスで migrate すると、data_dir 内に100MBある状態で約45秒掛かりました。

migration が終わるまで consul agentは起動しないため、その間は名前解決などの機能も当然使用できません。consul serverのみで他の機能を提供していないホストであればともかく、そうでない場合はちょっとつらい。

ではどうすればいいのか。まず、自分の環境で migration にどれぐらいの時間が掛かるかを計測することができます。

hashicorp/consul-migrate · GitHub が手動での migration tool なので、これを使って、

  • consul agent を一旦止める
  • data_dir を rsync で別の場所に copy する
  • consul agent を起動する

として、copy された data_dir に対して consul-migrate コマンドを実行すれば Migration completed in x.xxxs と表示されて完了までの時間が分かります。

ちなみに consul-migrate 実行時の iostat -x は以下のようになっていました。大量の disk write が発生していますね。

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvda              0.00   455.30    0.00 1159.70     0.00 33680.80    29.04     1.24    1.07   0.81  93.60

これで計測した migration に要する時間が運用上耐えられない場合の対応ですが、tmpfs に置いて migration することで劇的に高速化しました。同環境で 2.3 秒程度です。

  • consul (0.4.1) agent 停止
  • rsync で tmpfs に data_dir をコピー
  • 旧 data_dir から symlink を張る
  • consul (0.5.2) agent 起動

この手順で、合計ダウンタイムは数秒に抑えることができました。普通の disk に戻したい場合は、もう一度 consul agent を停止して、symlink を削除して書き戻してから起動することになります。

ただ、自分の場合は Consul server のホストが落ちたらまっさらな状態から同期し直してもたいしたコストではない(なんなら別のインスタンスを立てる) と判断したのと、Server が 5台あるので耐障害性もそれなりにある、ということで tmpfs のまま運用しています。

皆さんはどうしてるんでしょうか。教えてください。

Norikraのクエリをテキストファイルで管理する

Norikra に登録されているクエリが大量にある場合、WebUIで登録、編集をしていると複数人での共同作業で管理しきれなくなるため、クエリをファイルにしておいてリポジトリで管理したくなります。

norikra-clientには query add, remove, suspend, resume などの機能が従来からありますが、add, removeは冪等でないため登録されているクエリに対して再度実行するとエラーになるので状態管理は難しい。

ということで、norikra-client に query dump query sync という機能を追加して 1.3.1 で取り込んでもらいました。これで JSON によってクエリを管理し、Norikraと同期することができます。

$ norikra-client query dump > dump.json
[
  {
    "name": "test",
    "group": "STDOUT()",
    "expression": "SELECT count(*)\nFROM test.win:time_batch(5 sec)",
    "targets": [
      "test"
    ],
    "suspended": false
  },
  {
    "name": "test2",
    "group": "STDOUT()",
    "expression": "SELECT count(*) FROM test.win:time_batch(10 sec)",
    "targets": [
      "test"
    ],
    "suspended": false
  }
]

JSONを編集後、query sync に食わせると Norikra に登録されているクエリとの差分を見つけて、変更があったものだけ削除、追加を行います。変更がないクエリは触らないので、1時間とか1日などのロングスパンなクエリがあっても(変更しなければ) 大丈夫です。

$ norikra-client query sync < dump.json
remove query {"name"=>"test2", "group"=>"STDOUT()", "expression"=>"SELECT count(*) FROM test.win:time_batch(10 sec)", "targets"=>["test"], "suspended"=>false}
add query {"name"=>"test2", "group"=>nil, "expression"=>"SELECT count(*) FROM test.win:time_batch(60 sec)", "targets"=>["test"], "suspended"=>false}

しかし、SQLのクエリは見やすくするために改行を入れたりインデントしたりしたいので、JSON手書きして管理するのは辛いですね。

ということで norikra-querydump-format という簡単なフィルタを書きました。query dumpJSONSQL のテキストファイルの相互変換ができます。

$ norikra-client query dump | norikra-querydump-format -i json > dump.txt
$ norikra-querydump-format -i text < dump.txt | norikra-client query sync
-- QUERY:{"name":"test","group":"STDOUT()","targets":["test"],"suspended":false}
SELECT count(*)
FROM test.win:time_batch(5 sec)

-- QUERY:{"name":"test2","group":"STDOUT()","targets":["test"],"suspended":false}
SELECT count(*) FROM test.win:time_batch(10 sec)

--QUERY: の部分が後続のクエリについてのメタデータ、それ以外の部分がクエリ本文になります。行頭が -- で始まっている行と空行は無視されるので、クエリについてのコメントなども記述できます。

ただし、一度 Norikra に sync したあと dump すると、Norikra側にはコメントなどを保存することができないので失われてしまいます。なので運用の際には、

  1. 現在 Norikra に登録されているクエリを dump, format してテキストファイルにする
  2. リポジトリでファイルを管理
  3. クエリの変更はファイルで行い、JSON にして sync する一方通行

という手順で管理するのがよいでしょう。

norikra-listener-mackerel で Norikra のクエリ結果を直接 Mackerel に投げる

Norikra でクエリした結果を Mackerel に投げたい場合、これまでは fluent-plugin-norikra で取得して fluent-plugin-mackerel で送信する、という作りにしていたと思います。

Norikra 1.2以降では Listener plugin が使えるようになったので、クエリ結果を直接 Norikra 上で扱うことが可能になりました。

ということで、norikra-listener-mackerel (rubygems) を書きました。Norikra 単体で、クエリ結果を Mackerel のサービスメトリクスとして送信できます。

使い方

$ gem install norikra-listener-mackerel

norikra が動作する ruby でインストールすれば、norikra start 時に自動的に読み込まれます。

クエリを通常と同じように書き、group を MACKEREL(service_name,api_key) として登録します。

  • Mackerel のサービス名: nginx
  • metricsのprefix: status
  • API Key: bpzpdhjzmTnkp+ZkE3bFX2EcoWG+N1wqy2x5wVdAr7o=

の場合は以下のようになります。

MACKEREL(nginx.status,bpzpdhjzmTnkp+ZkE3bFX2EcoWG+N1wqy2x5wVdAr7o=)

API keyが未指定の場合は環境変数 MACKEREL_APIKEY から読むようになっています。

たとえば「アクセスログからステータスコードを1分ごとにカウントして、秒間のリクエスト数として送信する」というよくあるユースケースだとこんな感じですね。

SELECT
  COUNT(1, 200 <= status AND status <= 299) / 60.0 AS rate_2xx,
  COUNT(1, 300 <= status AND status <= 399) / 60.0 AS rate_3xx,
  COUNT(1, 400 <= status AND status <= 499) / 60.0 AS rate_4xx,
  COUNT(1, 500 <= status AND status <= 599) / 60.0 AS rate_5xx
FROM nginx_access.win:time_batch(1 min)
-- group: MACKEREL(nginx.status,bpzpdhjzmTnkp+ZkE3bFX2EcoWG+N1wqy2x5wVdAr7o=)

これで Norikra に fluentd からログを流し込んでやれば、Mackerel に自動的にサービスメトリクスが定義されてグラフができあがります。(サービスの定義だけは事前にしておく必要がありますが)

f:id:sfujiwara:20151109100328p:plain

Norikra から値を取得して送信する fluentd が不要になるので、よりお手軽になりますね。

どうぞご利用ください。

ISUCON5 で優勝しました

ISUCON5、予選を無事通過して10/31(土)に開催された本選に参加し、優勝しました。

チームは ISUCON 1 の時の初代「fujiwara組」再結成ということで、@songmu, @sugyan とのカヤックの元同僚メンバーです。

最初に、毎回素晴らしいイベントを開催、運営していただいている @941 さんをはじめとした運営チームの皆様、出題の @tagomoris さん、@kamipo さん、他すべての協力いただいた皆様に感謝を申し上げます。本当にありがとうございました!

競技開始からベンチ実行まで

ロゴがなかったので作った。

競技開始、まずは3台で相互にsshできるようにするのに一瞬戸惑う。port 22は開いていて、会場からは接続できるものの提供された3台間で接続しようとすると切断される挙動……最近の若い人は tcpwrapper とかなじみ薄いんじゃないかなあ、と思いつつおじさんなのでそこはすぐ /etc/hosts.allow にIPアドレスを追加して解決。

予選から使っていた初期設定用の Chef を流して初期設定はすんなり完了。isucon5/chef at master · fujiwara/isucon5 · GitHub

Chefの適用とアプリケーションのデプロイは、3台なので何でもいいんだけど…と思いつつせっかくなので手製の stretcher で構築。

雑に

#!/bin/bash
tar czvf ~/webapp.tar.gz .
sum=$(sha1sum ~/webapp.tar.gz | awk '{ print $1 }')
cat <<END > ~/webapp.yml
src: http://isu01a:8000/webapp.tar.gz
dest: /home/isucon/webapp
checksum: $sum
commands:
  post:
    - sudo supervisorctl restart perl
    - sudo mv /var/log/nginx/access.log /var/log/nginx/access.log.`date +%Y%m%d-%H%M%S`
    - sudo service nginx reload
END
echo http://isu01a:8000/webapp.yml | nssh -i -t isu01a -t isu01b -t isu01c stretcher

isu01a (1台目) の port 8000 で nginx が /home/isucon 以下を配れるようにしておいて tarとmanifestを配信、nssh で各ホストでstretcherを並列実行。nsshというのはこれも自作の、複数のホストにsshしてコマンド実行して出力をまとめて流してくれる君。fujiwara/nssh · GitHub

この間にチームメンバーの二人にはアプリケーションを読み込んでもらい、手元で実行できるようにしてもらっていたんだけど、今回の題材は運営が用意している外部APIサーバに接続する必要があり、そこには会場から接続できずに動かせない、とのこと。

なので Squid を isu01a:3128 で動作させ、手元で動かす際には HTTP_PROXY=http://(isu01aのIPアドレス):3128/ を指定してもらうことで会場の手元のマシンから接続できるように構築。

最初のハマり

ここで、Squid で外部APIの結果をよしなに cache できたらそれだけでスコア上がったりするんじゃないか? と思いついたので cache させようとしたものの、うまくいかずにすべて MISS してしまう。最近、Squid は forward proxy としてたまに使うものの下手にcacheされると面倒なことのほうが多いので、cache させない設定の config は持ってたんだけど…

なんだかんだでここで1時間程度ロスした気がする。これが大失敗。

アプリケーションでの cache 実装

結局 Squid での cache はあきらめて、アプリケーションレイヤーで外部APIのレスポンスを memcached に cache してもらう。この実装が動いたのが14時すぎぐらいで、一発で通ってスコアは 37,000 ぐらい。一瞬2位になるものの、GoBoldは既に10万点近くまで駆け上がっていて背中が遠い。

最初の実装はすべてのAPIレスポンスを考えなしに (expireせず) cache していたので、たまたま通ればスコアは出るがチェッカーに引っかかるとfailするという状況。

API エンドポイントごとに expire を個別に設定できるいい感じの実装を @songmu につくってもらったので、それでまずは変わらなそうな ken (ken_all.CSV!!) などをベンチ走行中に切れないように長寿命に調整。

https の perfectsec_attacked, perfectsec はどうも cache するとまずそうだな、と判断して cache しないことに。 (これも実は判断ミス)

https のは実は http2 対応していたそうですが、全く気づいてなかったのと、仮に気づいてたとしてもまともな Perl の http2 クライアント実装を知らないのでスルーしていたことでしょう。

下回りの調整

この状態で、isu01a に nginx, PostgreSQL, memcached, webapp、他2台にwebappという構成で5万点前後?

isu01aでのネットワーク転送量がだいぶ大きかったのでログを見つつサイズの大きい静的ファイル(css, js)へのリクエストヘッダを観察したところ、Accept-Encoding: gzip が付いていたので gzip_static モジュールで gzip 済みのファイルを配信。一気に転送量が減ってスコアも7万点近くまで伸びた気がする。

Plack の worker 数は何も考えずに 10 (* 3台) にしていたんだけど、初期実装の5プロセスから10にしただけでスコアが倍近くになっていたので、ここをもう少し調整できていればもっと伸びたか。

迷走

16時近くまで膠着状態。 perfectsec API系は一番最初に何も考えず cache した状態でベンチを通過していたので、実はここも cache できるのでは? と思って expire 調整をしようかと提案。

が、@sugyanが「もっとアプリケーションでできることは…」と言うので、まあそれもそうだよな。cache 寿命調整はあとでもできるし、と思ってあるミドルウェアを書くことに。結果的には、16時から大改造に手を付けたのも大失敗。

自分と @sugyan が飛び道具開発、@songmu にはその間に memcached へのリクエストを最適化するために get_multi, set_multi するように改修を進めてもらうことにした。

飛び道具不発

書きたかったものは以下のようなやつ。

  • Go で memcached protocol を喋る server
  • ["uri",{"param":"value"},{"header":"value"},expire] というkeyの形式で複数 get をリクエストすると、外部に並列HTTPリクエストした結果を返してくれる
    • このkey形式はアプリケーションでmemcachedを扱うときのものと同一
  • ついでにオンメモリcache もする

これができれば、memcached の代わりにこれを使うだけで Perl のアプリケーションは何も変わらず、しかも並列にAPIリクエストもできてレイテンシが隠蔽できるという飛び道具になるはずだった…

Go での memcached protocol server は kayac/go-katsubushi · GitHub という、Snowflake like な ID 発番をするサーバを書いていたのでこれを改造。

@sugyanとペアプロしながら外部のHTTP APIにリクエストを飛ばして結果を返すところまでは30分も掛からず書けて、あとは複数並列とオンメモリ cache、1時間半あるし行けるのでは!という感じだったものの、ここで memcached protocol の理解が浅くてドはまり。

gets で複数の値を取得するときは、gets a b c と key をリクエストされた順番でレスポンスを返す必要があったんですね。なぜかレスポンスが取れたり取れなかったりして、パケットキャプチャと睨めっこしながら1時間ハマって、キー順に sort して返す必要に気がついたのが 17:35 ごろ。

結局そこから直しても deploy して組み込む時間はない、ということで 17:40 に実装を断念。

ボトルネック開放

perfectsec 系 API、まず片方だけ10秒 cache したところ一気にスコアが上がって17:46ごろに10万点近く、両方 10 秒にして15万を17:50ごろ記録。

これは cache の寿命だけではなく、@songmu が進めていた memcached への複数 get, set、user をセッションデータ内部に持たせてログインセッション中は DB を引かないようにするという改善が、ボトルネックを開放したことで一気に伸びた要因に思われる。

再起動テスト

17:53ごろから再起動テスト。 順不同で再起動した場合、PostgreSQLに1回繋がっていたコネクションがあとから落ちると、次のリクエスト時にエラーになって500が返るのを17:57ごろ発見。

再起動後誰も一度もリクエストしなければ問題ないので、「全員開いてるタブを全部落として!」として XHR でのリクエストなども飛ばないようにして、あとは祈る感じで… (本来なら、接続が切れたら再接続するコードを入れるべきですね)

結果

結果、failすることもなく 151,509点 で優勝できました。

今回は反省点が本当に多くて、Squidでハマって1時間無駄にしたことで飛び道具実装も1時間遅くなり、そこでハマって動かせず。 負けるときはこういう感じなんだろうなあとだいぶ覚悟していました。

なお、飛び道具は後日修正したら+2分でちゃんと動かせたので、当日も1時間早く手を付けていたら投入できていた可能性は高いですね…大改造するなら14時か遅くても15時までに手を付けるべし、という経験則は正しかった。

自分がハマっていた時の作業ミスを確実にすべて見つけてくれた @sugyan、2人が1時間沈黙している間黙々と改善を進めて最後に炸裂させた @songmu、両名には本当に感謝です。

ISUCONで勝つためには、チームメンバーを心底信頼して任せることが本当に必要ですね。 自分は過去すべての大会でそういう戦いができていて、幸せだと思います。

来年?

ISUCON 6 が来年あるとして、出題は他の人にやってもらいたいなあという気持ちがあります。どうも自分と @tagomoris さんは妙にかみ合うというか、ISUCON における相性がよすぎる気がするので、交互に出題していてもあんまり広がりがないのではないか、と思うのがひとつ。

今年も事前解答によるフィードバックが足りないことが課題として見えているので、自分は出題の事前解答とレビューをやることで、さらなる品質向上に貢献できるのではないかと思ってます。

最後に、運営の皆様、スポンサーの皆様、そしてすべての参加者の皆様に感謝します。ISUCON楽しかったですね!

vimeo.com