2011年8月アーカイブ

完全に文化祭疲れで昼寝3時間ぐらいしてしまいましたが、懇親会で聞かせて頂いた話やblogやtwitterをみる限り好評だったようで、うれしく思っています。ISUCONに参加して頂いた方、社内で協力して頂いた方ありがとうございました

いくつか至らぬ点がありますが、明日以降に公式にフォローさせて頂きたいと思っています。

さて、既に公開されているので見た方は多いと思いますが、今回ISUCONで使ったベンチマークツールは大きく分けて次の3つのツールに分かれています。

• (1) 1post/secでコメントを投稿し、1秒後にコメントをしたページと、インデックスおよび適当な記事のDOMチェックを行う node.js
• (2) http_load + patch
• (3) css/js/imageのMD5値を検証する perl script

最終的な順位はhttp_loadが行ったリクエスト数で決まるのでもし(1)と(3)だけまじめに処理をして、(2)に対しては適当なコンテンツを返答すれば最速になる、はずです(多分この思考ができるのは根が悪い人だけです)。tagomoris氏が最初に作ったベンチマークツールを見ながら、このようなチートを如何に防ぐかというのをかなり開催日ぎりぎりまで考えていました。

以下はデフォルト状態でのnode.jsのHTTPクライアントがリクエストの際に発行する HTTP のヘッダです

GET / HTTP/1.1
Host: 192.168.1.1
Connection: close

User-Agentは指定しないとでません。User-Agentを指定すると、

GET / HTTP/1.1
User-Agent: Isucon1
Host: 192.168.1.1
Connection: close

とGET行の次に追加されます。http_laodはどうなのかと調べると

GET / HTTP/1.0
Host: 192.168.1.1
User-Agent: http_load 12mar2006

となります。User-Agentヘッダの場所、Connectionヘッダの有無、そしてHTTP/1.1プロトコルのバージョンの違うことが分かると思います。もし参加者がこのあたりに気付けばチートが簡単にできてしまいます。そのためまず node.jsのDOMチェックツールにUser-Agentを追加し、http_loadにはパッチをあてました。

--- http_load-12mar2006.orig/http_load.c        2006-03-13 04:17:03.000000000 +0900
+++ http_load-12mar2006/http_load.c     2011-08-29 00:50:53.000000000 +0900
@@ -1019,13 +1019,15 @@
        }
     else
        bytes = snprintf(
-           buf, sizeof(buf), "GET %.500s HTTP/1.0\r\n",
+           buf, sizeof(buf), "GET %.500s HTTP/1.1\r\n",
            urls[url_num].filename );
     bytes += snprintf(
+       &buf[bytes], sizeof(buf) - bytes, "User-Agent: %s\r\n", VERSION );
+    bytes += snprintf(
        &buf[bytes], sizeof(buf) - bytes, "Host: %s\r\n",
        urls[url_num].hostname );
     bytes += snprintf(
-       &buf[bytes], sizeof(buf) - bytes, "User-Agent: %s\r\n", VERSION );
+       &buf[bytes], sizeof(buf) - bytes, "Connection: close\r\n" );
     bytes += snprintf( &buf[bytes], sizeof(buf) - bytes, "\r\n" );

これがまず、プロトコルを合わせ、ヘッダの順をあわせるだけのパッチです。そしてこのとき1つ機能を追加しました

+    if (  (unsigned long) random() % 100 > 30 ) {
+        bytes += snprintf(
+           &buf[bytes], sizeof(buf) - bytes, "Accept-Encoding: gzip, deflate\r\n" );
+    }

それがこの一定の割合でのgzipヘッダの追加です。コメントの数が増えることでトラフィックも増え、HTTP圧縮が有効に活用できるんじゃないかと思ったんですが、、、、実際はproxyのCPUを使ってしまうためあまり効果がなかったようですne。

この変更により、http_loadが行っていたコンテンツのサイズのチェックは意味がなるなる可能性があったので、コメントアウトしました。

@@ -1682,6 +1688,7 @@
        ++http_status_counts[connections[cnum].http_status];

     url_num = connections[cnum].url_num;
+/*
     if ( do_checksum )
        {
        if ( ! urls[url_num].got_checksum )
@@ -1716,9 +1723,9 @@
                }
            }
        }
+*/
     }

その代わり追加したのが、(3)のperlによるcss/js/imageのMD5チェックサム確認ツールです。チェックサム確認ツールは単純に取得して確認するだけはなく、Accept-Encodingを追加したリクエストと、追加していないリクエストの両方を行っています。もちろん、Accept-Encodingが付いているリクエストはhttp_loadだと想定してのチートを防ぐためです。ただし、css/js/image以外のインデックスや記事ページにたいしてはなんのチェックもしていないので実はここが穴でした^^。本当は記事が3000件あるかどうかのチェックとあわせてやろうかと思っていたんですが時間切れで間に合いませんでした。

と、このパッチをあてている最中に、例の鬼とか悪魔とか言われたリクエストパターンを思いつきます。

もともとtagomorisと性能がでない罠を作ろうと言っていてまるまる2日ぐらい悩んでいたのですが、サーバ側の設定を変更してバックログや使えるリソースの制限をしてもあまり効果（逆効果）がないか、エラーがアプリケーションのログやサーバのログにすぐにでるのである意味分かりやすいという理由で、罠パラメータやめようかと相談していのですが、ちょうどその時、別案件でnginxに対してこのパッチをあてるという作業をし、罠の天使（悪魔）が舞い降りてきた訳です。原因はすべてnginx-1.0系に上のパッチをあてれるようにしてくれたthi■■■o氏だった!!（ちがう)

それが

+    if (  (unsigned long) random() % 100 >= 97 ) {
+        bytes += snprintf(
+           &buf[bytes], sizeof(buf) - bytes, "Connection: keep-alive\r\n" );
+    }
+    else {
+        bytes += snprintf(
+           &buf[bytes], sizeof(buf) - bytes, "Connection: close\r\n" );
+    }

このhttp_loadへの変更。

http_loadはそもそも、HTTP/1.1やKeepAliveをサポートしていないツールで、Content-Lengthがない場合サーバから切断されるまでコンテンツを読み取ろうとします。上の変更により少ない確率ですが、HTTP/1.1、Connection: keep-aliveでのサーバにリクエストを行い、サーバ側がHTTP/1.1をサポートし、KeepAliveが有効になっていて、コンテンツがLengthが付かないchunked転送で送られると、http_loadとrevser_proxy間の接続がコンテンツの転送後もしばらくの間(KeepAliveTimeout)切断されなくなり、http_loadはコンテンツ読み取りが完了していないと思い込み、半ストール状態に陥り次のリクエストに移れず、ベンチマークの結果が悪くなります。

デフォルトで用意していたApacheはKeepAliveの設定がOffでしたが、Nginxなどイベントベースな軽量なWebサーバを使うとKeepAliveがデフォルト有効で、Timeoutも長い(Nginxのデフォルトは65秒!)ので、ApacheからNginxに変更したとたんベンチマークの値が劇落ちします。わりと多くのチームがはまり、そしてApacheに戻したりしたようです。中にはApacheの時にKeepAliveを有効にして遅くなったのを確認したチームもあるようです。

時間がもうすこしあればtcpdumpでみたり、http_loadの中身を確認するチームが出てきたのかもしれませんね

今回、こんな感じでチート対策と罠をしかけましたが、ソースコード一式も公開されているのでまだまだこんな穴があるとか、こういう嫌がらせはどうかとかありましたらblogなどなどで書いてもらえるとうれしいです。本当に参加頂きありがとうございました。

Software Design 2011年9月号にて『運用エンジニア「攻め」の仕事術」という特集の最初の章を担当させて頂きました。
運用エンジニアとはどんな職業で、何をすべきなのかを10年ぐらい前の昔話や前職の経験、今の職場で感じることなど自分の経歴を含めて書かせて頂きました。

今回の特集は、自分の他に@riywoさんや馬場さん(@netmarkjp)などの方々も記事を書いています。Mobageの半年で10億PV以上増えた話やアツい運用話、馬場さんの専業ならではの監視運用の話も非常に参考になりました。

中でも、馬場さんの記事中の、「障害対応のときに冷静でいる為のポイント」が参考になったので引用します

• 否が応でも心拍が早くなるので、心拍が早くなっていることを確認して自覚する
• 「冷静に」を心がける。心がけても冷静でいられないから、余計に心がける
• 呼吸、口調、タイプスピードを意図的にスピードダウンする。深呼吸気味に。少し目を瞑る。ただし、寝落ちないように。その後は少し大きめに開く（クワッ
• 基本に忠実に対応し、勘に頼らない。状況を必ず確認する（動作は正常で、システムメッセージだけ間違いなどのケースもある）
• ロジックで自分を固めすぎない。自分の無知（ロジックにおける前提知識の足りなさ）を自覚する。再起動してみるで解決することは意外と多い。
• 自分を過信しない。切り替えを早くし、誰かに聞いた方が早ければ聞く。GoogleでもTwitterでも先輩でも後輩でも、問題解決のためには何でも誰でも使う

障害対応していると、つい寡黙になったり、キータッチが強くなったり、椅子をなげてしまいそうになるので、上のポイントを常にデスクトップに表示して、対応の際は目を通したいぐらいです。

あと、今回のSoftware Designの第二特集で「トップエンジニアのお勧めの本55」という記事があります。弾さんやはてなのstanakaさん、弊社の伊勢さん、nipotanさんなどなど蒼々たる方々が様々なお勧め本を紹介しています。

そこでトップエンジニアでもなんでもないけど、勝手に3冊ほど自分のお勧め本をあげておこうと思います

毎度好例。MySQLにおけるインデックスのチューニング、OSやハードウェアの知識も身に付きます。運用エンジニアに限らず普段からMySQL(や他のDB)を使っていてこの本を読んでいないエンジニアは今すぐポチるか、近く本屋に行って買いましょう。アプリケーションエンジニアの方は7章からあとを中心に読むのがお勧めです

今回記事を執筆することになったきっかけでもあった書籍。運用の様々な側面が実例とともにエッセイ形式でまとめられています。運用エンジニアにとっては涙なしでは読めない部分も。

好きな漫画といったら間違いなくパトレイバーをあげます。レイバー(+システム)とそれを動かす人と組織。運用エンジニア的視点で読むと違う発見があるかもしれません。あーるも好きです

某サービスのクエリチューニングのお話。

ブログとか日記とかそういうサービス系で次のようなテーブルがあったとします。

CREATE TABLE entries (
  id INT UNSIGNED NOT NULL PRIMARY KEY AUTO_INCREMENT,
  user_id INT UNSIGNED NOT NULL,
  posted_by TINYINT UNSIGNED NOT NULL,  --#PC、mobileなどどこから投稿されたかのフラグ
  title VARCHAR(512) NOT NULL,
  body TEXT NOT NULL,
  created_at DATETIME NOT NULL,
  updated_at TIMESTAMP NOT NULL,
  status TINYINT UNSIGNED NOT NULL,
  INDEX (user_id,created_at,status)
) ENGINE=InnoDB

まぁ、わりとありがちです。順調にサービスが使われ記事数が百万件ぐらいあったとしましょう。ある日

「サービスの改善のため、1日に携帯から登録された件数をレポートとして出して欲しいんだけど」

とディレクターからカジュアルに頼まれました。いろいろ言いたいことはさておき、あなたならどうしますか？

最近上と同じような場面において、元々あったクエリを以下のように変更しました。

SELECT COUNT(*) FROM entries a, entries b
 WHERE a.id = b.id
  AND a.created_at BETWEEN '2011-09-10 00:00:00' AND '2011-09-10 23:59:59'
  AND b.posted_by=2

ちょっと奇妙に見えそうですが、self-joinを使っています。なぜこんなクエリになったのか、順を追って説明します。

通常、1日に携帯から投稿されたエントリ件数をだすには

SELECT COUNT(*) FROM entries 
  WHERE created_at between '2011-09-10 00:00:00' AND '2011-09-10 23:59:59'
    AND posted_by=2;

このように書くでしょう。ただし、インデックスが使えないのでテーブルスキャンとなってしまいます。EXPLAINすると

+----+-------------+---------+------+---------------+------+---------+------+-------+-------------+
| id | select_type | table   | type | possible_keys | key  | key_len | ref  | rows  | Extra       |
+----+-------------+---------+------+---------------+------+---------+------+-------+-------------+
|  1 | SIMPLE      | entries | ALL  | NULL          | NULL | NULL    | NULL | 98326 | Using where |
+----+-------------+---------+------+---------------+------+---------+------+-------+-------------+
1 row in set (0.00 sec)

となります。これを高速に実行するためにはインデックスの追加が必要です。

ALTER TABLE entries ADD INDEX (posted_by,created_at);

こんな感じでしょうか。

ただし今回のテーブルは既に100万件が登録されており、(サーバがそもそも古いとかInnoDB Pluginとか全く存在しないMySQL4.0だったなどなど)ALTERも大変そうです。そこでなんとか既存のインデックスの中で解決する方法を探します。

MySQLではプライマリインデックス、セカンダリインデックスだけでクエリが解決できることをCovering Indexと呼びます。当然インデックスだけでクエリ処理ができるので、高速です。MySQLのオプティマイザはクエリがCovering Indexで解決できる場合、多少効率が悪くてもテーブルスキャンよりインデックスのフルスキャンを選択するようなので、次のクエリのように条件がcreated_atだけのカウントクエリの場合、

mysql> EXPLAIN SELECT COUNT(*) FROM entries 
        WHERE created_at between '2011-09-10 00:00:00' AND '2011-09-10 23:59:59';
+----+-------------+---------+-------+---------------+---------+---------+------+-------+--------------------------+
| id | select_type | table   | type  | possible_keys | key     | key_len | ref  | rows  | Extra                    |
+----+-------------+---------+-------+---------------+---------+---------+------+-------+--------------------------+
|  1 | SIMPLE      | entries | index | NULL          | user_id | 13      | NULL | 98326 | Using where; Using index |
+----+-------------+---------+-------+---------------+---------+---------+------+-------+--------------------------+
1 row in set (0.00 sec)

このように、type=indexでインデックスフルスキャン、ExtaにUsing indexが入っているのでCovering Indexで処理されます。created_atが先頭にきているインデックスでなくても、created_atが含まれていればそれを利用するようです。

この動作を使って、posted_by=2を探す範囲を制限かけるのが、最初のクエリ。

SELECT COUNT(*) FROM entries a, entries b
 WHERE a.id = b.id
  AND a.created_at BETWEEN '2011-09-10 00:00:00' AND '2011-09-10 23:59:59'
  AND b.posted_by=2

aとb、同じテーブルを用意し、まずCovering Indexにてa.created_atから.a.idを求めています。user_idインデックスにはプライマリキーが含まれていないように見えますが、全てのセカンダリーインデックスにはプライマリキーが暗黙的に付加されます。そして、a.id = b.id とプライマリキーでテーブル結合し、検索範囲が狭めれたところで b.posted_by=2 は1行1行読み込んで調べます。

実際、この方法で某サービスでは30分ぐらい掛かっていたクエリが数秒に短縮されました。

注意するのは、これが有効になるパターン

a.created_at BETWEEN '2011-09-10 00:00:00' AND '2011-09-10 23:59:59'

これで見つかる範囲がテーブル全体に対して広い場合。セカンダリインデックス => プライマリキーで検索というランダムリードの回数が多くなり、テーブルスキャン（シーケンシャルリード)よりも速度が落ちますので注意してください。どっちが効率がいいのかはテーブルの構造やデータ容量にもよりますので、やってみて判断するのがいいかと思います。

突っ込みお待ちしています。

こちらとこちらのエントリーの続き

memcached 1.4.6でmixiの障害の原因となったaccept_new_connsがスレッドセーフじゃない件は修正されているはずだったのですが、検証したところ別のスレッド競合による不具合が発生し、Bugは全て解消されてはいませんでした。

この件についてmixiたんぽぽGの森本さんと調査していたところ、memcachedのcommiterにtwitter上で補足され、つたない英語で報告をあげていたら1.4.7-rc1で修正されたのでその報告。

memcached 1.4.6での不具合再現方法

まず、1.4.6で不具合を再現させる方法について。mixiのエンジニアブログと同じように、memcachedは次のオプションで起動し、

$ ./memcached -U 0 -u nobody -p 11222  -t 4 -m 16000 -C -c 1000 -v

malaさん作のテストスクリプトによって負荷をかけます。その際にスクリプトにこのpatchをあてています。再現させる環境としてOSにCentOS5.6、Xeon L3426(4core/8thread)を積んだサーバを使い、16並列でmemcachedにアクセスします

$ ./memcachedos.pl 127.0.0.1 11222 16
...
TIME:73176 PID:7292 Connect:47421822 QPS:835 Active:129 Success:18800016 Closed:18799887 Fail:28621806 Msg:Connection timed out
...

この環境にて、5分から2時間ぐらいので間で、dosツールがだすメッセージのQPSが0に限りなく近くなったら再現成功です。この状態でmemcachedos.plを止め、telnetでmemcachedにアクセスをしてみます

$ telnet 127.0.0.1 11222
..
stats

おそらく接続はできるけど、一切コマンドへの応答がないはずです。quitもできません。

memcached 1.4.6での修正内容と問題点

詳しくは、mixiのエンジニアブログを参照してもらうとよいですが、memcached 1.4.6ではスレッド間の競合をさけるため、accept_new_connsを各スレッドで変更するのではなく、timerを使いメインスレッドにて変更を行うようになりました。

mixiエンジニアblogから転載(一部追加)した、簡略化したコード

main thread : do_accept_new_conns {
  if(受付無理){
    allow_new_conns = false; // allow_new_connsを落とす
    maxconns_handler起動
  }
}

worker thread :  conn_close {
   allow_new_conns = true; // 接続に余裕ができた
}

main thread : maxconns_handler {
  if(not allow_new_conns){
    //  まだ接続に余裕がない
    10msにもう一度調べる
  }else{
    timer削除
    accept_new_conns(true); // 新規接続受付開始;
  }
}

// thread.c
void accept_new_conns(const bool do_accept) {
  pthread_mutex_lock(&conn_lock);
  do_accept_new_conns(do_accept);
  pthread_mutex_unlock(&conn_lock);
}

接続エラーが起きた際の処理は、

• (1) drive_machineからaccept_new_conns(false)が呼び出される
• (2) do_accept_new_connsでallow_new_connsをfalseにし、maxconns_handlerを呼び出す
• (3) maxconns_handlerはallow_new_connsをみて、falseの場合timerを使い10ms後に、自分自身を呼びだす
• (4) 他のクライアントからの接続が切れると、allow_new_connsをtrueにする
• (5) timerから呼び出されたmaxconns_handlerがallow_new_connsがtrueであればaccept_new_conns(true)する

となっています。

ここでものすごく稀なケースとして、(2)と(3)の間に(4)が入ると、(3) でtimer処理ではなく、いきなりaccept_new_conns(true)を呼び出してしまい、pthread_mutex_lock(&conn_lock) でdead lockする。これが今回の問題でした。

accept_new_conns => pthread_mutex_lock(&conn_lock) => do_accept_new_conns =>
=> maxconns_handler => accept_new_conns => pthread_mutex_lock(&conn_lock)
と処理がループしてしまっているわけですね

gdbでもそれが確認できます

(gdb) bt
#0  0x000000391c80d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x000000391c808e1a in _L_lock_1034 () from /lib64/libpthread.so.0
#2  0x000000391c808cdc in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x000000000040db6d in accept_new_conns (do_accept=true) at thread.c:183
#4  0x0000000000402924 in maxconns_handler (fd=<value optimized out>, which=<value optimized out>, arg=<value optimized out>) at memcached.c:140
#5  0x000000000040db75 in accept_new_conns (do_accept=false) at thread.c:184
...
省略
...
(gdb) p conn_lock
$1 = {__data = {__lock = 2, __count = 0, __owner = 19110, __nusers = 1, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, 
  __size = "\002\000\000\000\000\000\000\000\246J\000\000\001", '\000' <repeats 26 times>, __align = 2}
(gdb) p allow_new_conns
$2 = true

thread.cのmutex_lockで止まっていて、allow_new_connsにtrueが入っています。

修正patch

んで、次が今回の修正箇所。

diff --git a/memcached.c b/memcached.c
index 7905e6c..c82f5c5 100644
--- a/memcached.c
+++ b/memcached.c
@@ -130,7 +130,7 @@ static struct event maxconnsevent;
 static void maxconns_handler(const int fd, const short which, void *arg) {
     struct timeval t = {.tv_sec = 0, .tv_usec = 10000};

-    if (allow_new_conns == false) {
+    if (fd == -42 || allow_new_conns == false) {
         /* reschedule in 10ms if we need to keep polling */
         evtimer_set(&maxconnsevent, maxconns_handler, 0);
         event_base_set(main_base, &maxconnsevent);
@@ -3386,7 +3386,7 @@ void do_accept_new_conns(const bool do_accept) {
         stats.listen_disabled_num++;
         STATS_UNLOCK();
         allow_new_conns = false;
-        maxconns_handler(0, 0, 0);
+        maxconns_handler(-42, 0, 0);
     }
 }

maxconns_handlerの初回呼び出し時に特殊なfdとして「-42」与え、必ずtimerが起動するようになりました。-42がそのまま書いてあるところがいまいち感がありますがこれで問題がなくなりました。
今、同じ環境で1.4.7-rc1に対して、memcachedos.plを使い負荷をかけていますが、20時間以上は問題なく動作しています。

これでmixiの障害の原因となったmemcachedのバグは全て修正されたはずです。memcached-1.4.7の正式リリースが待ち遠しいです。

もう一年たったんですねぇ〜

MySQL 4.1未満を使っている人はいないとかDisられましたが、懇親会で3系がまだ動いているとか聞いて、私は元気です、

MySQL Casual Talks Vol.2で MySQL 4.0の LT をしてきました。

歴史的経緯とか開発のリソースうんぬんでMySQL 4.0をまだ使っているところはないこともないと思っています。

このLTでは、MySQL 4.0の運用やSQLチューニングを行う場合の注意点や数分から数時間はまった点などを、5つほどにまとめてみました。一応補足しておくと、数千qps、数百コネクションというような環境でもない限り、MySQL 4.0でも安定して動きます。これがMySQLのすばらしいところですが、運用を楽にして行く為にもいつかは4系を撲滅したいものですね。

もう一つおまけ的に、MySQL 4.0 の運用ネタ。

4.0 のmysqldumpで取得したダンプデータには外部キー制約のチェックを外す

FOREIGN_KEY_CHECKS=0

が含まれないので、restoreする際にそのままだとエラーが起きます。その際は

sh -c 'echo "set FOREIGN_KEY_CHECKS=0;" && cat dump.sql' | mysql

とかやるとよいです。昨日これで20分ぐらい失いました