Redisをサービスで利用するというので、CloudForecastで監視するプラグインを作ってみました。

監視項目は Percona の Monitoring Plugins を参考にしてます

cf_redis.png



Redis の統計情報は info コマンドを実行すると得られます。telnet でも実行可能です。

info
$1020
redis_version:2.4.11
redis_git_sha1:00000000
redis_git_dirty:0
arch_bits:64
multiplexing_api:epoll
gcc_version:4.1.2
process_id:18078
uptime_in_seconds:781399
uptime_in_days:9
lru_clock:1553555
used_cpu_sys:1.90
used_cpu_user:0.82
used_cpu_sys_children:0.00
used_cpu_user_children:0.00
connected_clients:185
connected_slaves:1
client_longest_output_list:0
client_biggest_input_buf:0
blocked_clients:0
used_memory:2357504
used_memory_human:2.25M
used_memory_rss:4677632
used_memory_peak:3999144
used_memory_peak_human:3.81M
mem_fragmentation_ratio:1.98
mem_allocator:jemalloc-2.2.5
loading:0
aof_enabled:0
changes_since_last_save:0
bgsave_in_progress:0
last_save_time:1336737589
bgrewriteaof_in_progress:0
total_connections_received:29998
total_commands_processed:303740 
expired_keys:0
evicted_keys:0
keyspace_hits:251
keyspace_misses:65
pubsub_channels:41
pubsub_patterns:0
latest_fork_usec:1997
vm_enabled:0
role:master
slave0:10.x.x.x,34080,online
db0:keys=8,expires=1

どれが重要な数字なのかまだわからない

とあるMySQLのslowlogに残っていたところから見つけたクエリの書き換え。

サービスのどこで使われているものかまで詳しくみていないんだけど

CREATE TABLE `category2item` (
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `category_id` int(10) unsigned NOT NULL,
  `subcategory_id` int(10) unsigned NOT NULL,
  `item_id` int(10) unsigned NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `subcategory_id` (`subcategory_id`,`item_id`),
  KEY `picture_id` (`item_id`),
  KEY `category_id` (`category_id`,`item_id`)
) ENGINE=InnoDB AUTO_INCREMENT=42651972 DEFAULT CHARSET=utf8

カテゴリーとアイテムを結びつけるテーブルがあって、そこに対して、ユニークなアイテム数をカウントするクエリを実行する。

mysql> SELECT COUNT(DISTINCT item_id) FROM category2item WHERE category_id = '2';
+----------------------------+
| COUNT(DISTINCT picture_id) |
+----------------------------+
|                    2388652 |
+----------------------------+
1 row in set (3.02 sec)

件数がそれなり多いので、3秒以上掛かる。

slowlogにも多く残っていたので書き換えをしてみた。それがこれ。

mysql> SELECT COUNT(*) FROM (SELECT item_id FROM category2item WHERE category_id = '2' GROUP BY item_id) AS t;
+-------------------------+
| COUNT(DISTINCT item_id) |
+-------------------------+
|                 2388652 |
+-------------------------+
1 row in set (1.26 sec)

大体1/2の時間になった。このクエリではユニークな件数取得のために DISTINCT ではなく、GROUP BY してユニークなIDリストを取得して、その結果を COUNT(*) している。

なんでこれが速くなるのかよくわからなかったんだけど、EXPLAIN をしてみたところ

mysql> EXPLAIN SELECT COUNT(*) FROM (SELECT item_id FROM category2item WHERE category_id = '2' GROUP BY item_id) AS t;
+----+-------------+---------------+------+---------------+-------------+---------+------+---------+------------------------------+
| id | select_type | table         | type | possible_keys | key         | key_len | ref  | rows    | Extra                        |
+----+-------------+---------------+------+---------------+-------------+---------+------+---------+------------------------------+
|  1 | PRIMARY     | NULL          | NULL | NULL          | NULL        | NULL    | NULL |    NULL | Select tables optimized away |
|  2 | DERIVED     | category2item | ref  | category_id   | category_id | 4       |      | 4409520 | Using where; Using index     |
+----+-------------+---------------+------+---------------+-------------+---------+------+---------+------------------------------+
2 rows in set (1.25 sec)

Extra に 「Select tables optimized away」が付いていたので、 MyISAM のクエリ最適化が行われたと予想。

そこでプロファイリングを有効にしてクエリを実行。プロファイリングについてはnippondanjiさんのblogを参考にした

漢(オトコ)のコンピュータ道: プロファイリングで快適MySQLチューニング生活

mysql> SET profiling=1;
mysql> SELECT COUNT(*) ..
mysql> SHOW PROFILE SOURCE;
+---------------------------+----------+---------+---------------+-------------+
| Status                    | Duration | Source  | Source_file   | Source_line |
+---------------------------+----------+---------+---------------+-------------+
| starting                  | 0.000041 | NULL    | NULL          |        NULL |
| Opening tables            | 0.000007 | unknown | sql_base.cc   |        4519 |
| System lock               | 0.000002 | unknown | lock.cc       |         258 |
| Table lock                | 0.000031 | unknown | lock.cc       |         269 |
| optimizing                | 0.000007 | unknown | sql_select.cc |         833 |
| statistics                | 0.000041 | unknown | sql_select.cc |        1024 |
| preparing                 | 0.000014 | unknown | sql_select.cc |        1046 |
| executing                 | 0.000004 | unknown | sql_select.cc |        1780 |
| Sorting result            | 0.000002 | unknown | sql_select.cc |        2205 |
| Sending data              | 0.510723 | unknown | sql_select.cc |        2338 |
| converting HEAP to MyISAM | 0.106450 | unknown | sql_select.cc |       10984 |
| Sending data              | 0.641679 | unknown | sql_select.cc |       11049 |
| init                      | 0.000011 | unknown | sql_select.cc |        2528 |
| optimizing                | 0.000005 | unknown | sql_select.cc |         833 |
| executing                 | 0.000011 | unknown | sql_select.cc |        1780 |
| end                       | 0.000002 | unknown | sql_select.cc |        2574 |
| query end                 | 0.000001 | unknown | sql_parse.cc  |        5082 |
| freeing items             | 0.000014 | unknown | sql_parse.cc  |        6106 |
| removing tmp table        | 0.003672 | unknown | sql_select.cc |       10916 |
| closing tables            | 0.000003 | unknown | sql_select.cc |       10941 |
| logging slow query        | 0.000002 | unknown | sql_parse.cc  |        1723 |
| cleaning up               | 0.000002 | unknown | sql_parse.cc  |        1691 |
+---------------------------+----------+---------+---------------+-------------+

22 rows in set (0.00 sec)

「converting HEAP to MyISAM」が入っているのでやはり MyISAM が使われた模様。

試しに元の COUNT(DISTINCT item_id) のプロファイルをとってみると

mysql> SHOW PROFILE SOURCE;
+--------------------+----------+------------------+---------------+-------------+
| Status             | Duration | Source_function  | Source_file   | Source_line |
+--------------------+----------+------------------+---------------+-------------+
| starting           | 0.000032 | NULL             | NULL          |        NULL |
| Opening tables     | 0.000006 | unknown function | sql_base.cc   |        4519 |
| System lock        | 0.000003 | unknown function | lock.cc       |         258 |
| Table lock         | 0.000003 | unknown function | lock.cc       |         269 |
| init               | 0.000010 | unknown function | sql_select.cc |        2528 |
| optimizing         | 0.000006 | unknown function | sql_select.cc |         833 |
| statistics         | 0.000038 | unknown function | sql_select.cc |        1024 |
| preparing          | 0.000009 | unknown function | sql_select.cc |        1046 |
| executing          | 0.000022 | unknown function | sql_select.cc |        1780 |
| Sending data       | 3.018044 | unknown function | sql_select.cc |        2338 |
| end                | 0.001905 | unknown function | sql_select.cc |        2574 |
| removing tmp table | 0.000006 | unknown function | sql_select.cc |       10916 |
| end                | 0.000003 | unknown function | sql_select.cc |       10941 |
| query end          | 0.000002 | unknown function | sql_parse.cc  |        5082 |
| freeing items      | 0.000017 | unknown function | sql_parse.cc  |        6106 |
| logging slow query | 0.000002 | unknown function | sql_parse.cc  |        1723 |
| logging slow query | 0.000030 | unknown function | sql_parse.cc  |        1733 |
| cleaning up        | 0.000003 | unknown function | sql_parse.cc  |        1691 |
+--------------------+----------+------------------+---------------+-------------+
18 rows in set (0.00 sec)

こんな感じ。「Sending data」の時間が大きくなっているところから、ユニークなIDを割り出す為のデータ走査に時間が取られたのかなと予想。

では、MyISAMに変換されなかったらどうなるかと思って、tmp_table_size を 64MB (元16MB) まであげてみると、

mysql> SELECT COUNT(*) FROM (SELECT picture_id FROM category2picture WHERE category_id = '2' GROUP BY picture_id) AS t;
+----------+
| COUNT(*) |
+----------+
|  2388710 |
+----------+
1 row in set (1.10 sec)
mysql> SHOW PROFILE SOURCE;
+--------------------+----------+------------------+---------------+-------------+
| Status             | Duration | Source_function  | Source_file   | Source_line |
+--------------------+----------+------------------+---------------+-------------+
| starting           | 0.000041 | NULL             | NULL          |        NULL |
| Opening tables     | 0.000006 | unknown function | sql_base.cc   |        4519 |
| System lock        | 0.000002 | unknown function | lock.cc       |         258 |
| Table lock         | 0.000029 | unknown function | lock.cc       |         269 |
| optimizing         | 0.000006 | unknown function | sql_select.cc |         833 |
| statistics         | 0.000037 | unknown function | sql_select.cc |        1024 |
| preparing          | 0.000014 | unknown function | sql_select.cc |        1046 |
| executing          | 0.000004 | unknown function | sql_select.cc |        1780 |
| Sorting result     | 0.000002 | unknown function | sql_select.cc |        2205 |
| Sending data       | 1.099120 | unknown function | sql_select.cc |        2338 |
| init               | 0.000012 | unknown function | sql_select.cc |        2528 |
| optimizing         | 0.000004 | unknown function | sql_select.cc |         833 |
| executing          | 0.000010 | unknown function | sql_select.cc |        1780 |
| end                | 0.000002 | unknown function | sql_select.cc |        2574 |
| query end          | 0.000002 | unknown function | sql_parse.cc  |        5082 |
| freeing items      | 0.000013 | unknown function | sql_parse.cc  |        6106 |
| removing tmp table | 0.000015 | unknown function | sql_select.cc |       10916 |
| closing tables     | 0.000002 | unknown function | sql_select.cc |       10941 |
| logging slow query | 0.000001 | unknown function | sql_parse.cc  |        1723 |
| cleaning up        | 0.001948 | unknown function | sql_parse.cc  |        1691 |
+--------------------+----------+------------------+---------------+-------------+
20 rows in set (0.00 sec)

「converting HEAP to MyISAM」がなくなって「Sending data」が1回にまとまった分、MyISAMが使われるより若干早い感じ。HEAP(MEMORY)の場合もCOUNT(*)が最適化されるんですね。8.3.1.2. WHERE Clause Optimizationにも書いてあった

まぁ、これでも1秒以上クエリに掛かるので、Webアプリケーションの中から使うのは躊躇われるところ。どこで使われているかアプリケーションのソースコード読むかー。

Software Design 2011年9月号に寄稿した『運用エンジニア「攻め」の仕事術」』の記事が4/11 に発売の『サーバ/インフラエンジニア養成読本 管理/監視編』に載りました。技術評論社様、献本ありがとうございます。



2008年から2011年にSoftware Design誌に載ったシステム監視やトラブルシューティングに関する記事が数多く採録されています。n0tsさんやwebooさんの記事は2008年に書かれたものですが今でも十分に参考になりますね。

監視ツールやトラブルシューティングにつかうコマンドの使い方だけではなく、どのようなマインドで運用に取り組むべきなのかまで、広く記事が集められているので、手に取って読んで頂けたらと思います。

Apacheのconfにコメントを書く際に、設定の後ろに書く事はできないのは知られているのかどうかよくわかりませんが、その通りです。例えば

MaxRequestsPerChild 200 #少なめに

これは syntax error になります

% ./local/httpd/bin/apachectl -t
Syntax error on line 12 of /Users/.../local/httpd/conf/httpd.conf:
MaxRequestsPerChild takes one argument, Maximum number of requests a particular child serves before dying.

よくやりがちなんですが、ドキュメントにも

Directives in the configuration files are case-insensitive, but arguments to directives are often case sensitive. Lines that begin with the hash character “#” are considered comments, and are ignored. Comments may not be included on a line after a configuration directive.

書いてありました。

ところで、最近とあるサービスの動いているApacheのhttpd.confで

Order Deny,Allow
Deny from All
Allow from 127.0.0.1
..
Allow from x.y.z.252 #nat
Allow from x.y.z.253 #office1
Allow from x.y.z.254 #office2

という設定がされているのを見ました。設定行にコメントがあるけど、どうやらシンタックスエラーにはなって居ない。では問題ないじゃん、で終わるかというとそうではありません。

実はこれだけで HostnameLookups の設定関係なしに逆引きが行われてしまい、知らないうちにサーバの負荷になってしまうのです。実際にコメント部分を消したところロードアベレージが半分ぐらいに下がりました。

なぜ、シンタックスエラーにもならず、逆引きが行われるのかというと、「Allow」というディレクティブが複数の値を受け入れて、コメントをホスト名として扱ってしまうためです。ソースコードでみると、まずmodauthzhost.c の 174行目

AP_INIT_ITERATE2("allow", allow_cmd, &its_an_allow, OR_LIMIT,
                "'from' followed by hostnames or IP-address wildcards"),
AP_INIT_ITERATE2("deny", allow_cmd, NULL, OR_LIMIT,
                "'from' followed by hostnames or IP-address wildcards"),

ここで「Allow」と「Deny」のディレクティブを定義しています。APINITITERATE2 というディレクティブ処理関数登録マクロは引数を無限に受け取り、それらを1つずつ処理するディレクティブを登録します。

APINITXXXのマクロについてはklabさんの記事が詳しい
DSAS開発者の部屋:[補足記事]ディレクティブ処理関数登録マクロ一覧 (apache module 開発事初め その3-2)

そして、設定を行う「allow_cmd」では

static const char *allow_cmd(cmd_parms *cmd, void *dv, const char *from,
                         const char *where_c)
{
    char *where = apr_pstrdup(cmd->pool, where_c);
    .. 省略 ..
    else if (!strcasecmp(where, "all")) {
        a->type = T_ALL;
    }
    else if ((s = ap_strchr(where, '/'))) {
        *s++ = '\0';
        a->type = T_IP;
    }
    else if (!APR_STATUS_IS_EINVAL(rv = apr_ipsubnet_create(&a->x.ip, where,
                                                        NULL, cmd->pool))) {
        if (rv != APR_SUCCESS) {
            apr_strerror(rv, msgbuf, sizeof msgbuf);
            return apr_pstrdup(cmd->pool, msgbuf);
        }
        a->type = T_IP;
    }
    else { /* no slash, didn't look like an IP address => must be a host */
        a->type = T_HOST;
    }
    return NULL;
}

where に httpd.confで指定した文字列がきます。「#nat」や「#office」はIPアドレスではありませんし、スラッシュも含まないのでホスト名として扱われます。

Host名として扱われると、ここ

Hosts whose names match, or end in, this string are allowed access. Only complete components are matched, so the above example will match foo.apache.org but it will not match fooapache.org. This configuration will cause Apache to perform a double reverse DNS lookup on the client IP address, regardless of the setting of the HostnameLookups directive. It will do a reverse DNS lookup on the IP address to find the associated hostname, and then do a forward lookup on the hostname to assure that it matches the original IP address. Only if the forward and reverse DNS are consistent and the hostname matches will access be allowed.

書いてある通り、HostnameLookupsの設定に関係なく、逆引きを行ってアクセス可否を決めます。なので、「Allow」や「Deny」にはコメントを書くのは危険が危ないです。書かないようにしましょう。



だ が し か し



書きたいですよね。「Allow」行にコメント。なのでパッチ書いてみました。

--- httpd-2.2.22.orig/modules/aaa/mod_authz_host.c  2008-06-14 20:44:19.000000000 +0900
+++ httpd-2.2.22/modules/aaa/mod_authz_host.c   2012-04-04 16:01:10.000000000 +0900
@@ -117,9 +117,17 @@
     char msgbuf[120];
     apr_status_t rv;

+    if (cmd->info && !strncasecmp(cmd->info, "#",1))
+        return NULL;
+
     if (strcasecmp(from, "from"))
         return "allow and deny must be followed by 'from'";

+    if(!strncasecmp(where, "#", 1)) {
+        cmd->info = where;
+        return NULL;
+    }
+
     a = (allowdeny *) apr_array_push(cmd->info ? d->allows : d->denys);
     a->x.from = where;
     a->limited = cmd->limited;

かなり無理矢理ですが、このpatchをあてると、「Allow」と「Deny」の設定に限り「#」以降の文字を無視できます。

Order deny,allow
Deny from all
Allow from 192.168.67.1 #foobar hogehoge
Allow from 127.0.0.1

「#foobar」だけではなく、ちゃんと「hogehoge」もコメントとして扱います。

アクセス制御を細かくやる必要がある場合、コメントを後ろに追加するとわりとわかりやすい設定が書けると思うので、このpatchでhttpd.conf が捗る事間違いなし!…かな

【追記】
社内やIRCでちょっと話をして、コメントがあったらシンタックスエラーにしたほうがいいのではないかとの意見を頂きました。
patchがあたっているApacheとそうでないApache両方があった場合、設定コピペしてはまることがありそうなので、よくないと。
確かにそうなので、上のpatchを試してみようと思う方は、そのあたりを注意して頂けると幸いです。return NULLの代わりにエラーメッセージを返すとシンタックスエラー扱いになるはずです
【/追記】

同じ事を書いている方いた
M.C.P.C.: ApacheでHostnameLookups offでもログにホスト名が記録される場合

松信さんが作った Replication Booster for MySQL をデータサイズが大きいデータベースに対して使ってみました。

Yoshinori Matsunobu’s blog: Making slave pre-fetching work better with SSD
github - yoshinorim/replication-booster-for-mysql

Replication Booster for MySQL をものすごく簡単に説明すると、以下のようになるでしょうか。

replication_booster_mysql.png

MySQL でレプリケーションを設定した場合、マスターのバイナリログをIOスレッドが読み取り、relay-logへ記録します。そしてSQLスレッドがrelay-logから読み取ってテーブルを更新して行きます。Replication Booster を実行するとrelay-logを読み取り、更新クエリを参照クエリに書き換えてSQLスレッドよりも先にテーブルに対してアクセスします。これにより、InnoDBのbuffer_poolなどメモリ上にこれから更新されるデータを載せ、更新クエリの実行にかかる時間を減らそうというものです。

主なユースケースとしてはスレーブサーバの再起動した際に、バッファをより速く暖めレプリケーションの遅延の解消にかかる時間を短くすることが考えられます。

検証した環境など

今回試したのは再起動後の遅延解消ではなく、メモリに対してデータサイズがとても大きな某サービスのデータベースのバックアップスレーブの遅延対策としてReplication Boosterを動かしてみることです。ちなみにデータサイズは560GB、メモリは16GB(innodb_buffer_pool=10GB)です。毎秒10弱の更新クエリがあります。DiskはSATAをBBU付きRAID1という環境です

replication_backup_slave.png

レプリケーション遅延はバックアップスレーブだけではなく参照を行うスレーブサーバでも起きているのですが、参照を行う分だけバッファのヒット率が多少高いのか、バックアップスレーブほど遅延していません。そこでReplication Boosterを使い、バックアップスレーブでも参照クエリを発行してバッファの効率をあげてみるのが今回の狙い。

Replication Booster のインストール

2013年3月時点で、Replication Boosterも依存するBinlog APIもまだpre-alphaということで注意が必要です

今回インストールしたのはCentOS 5.xのサーバ。

まずcmake、bzrのインストールとboostのアップデート。bzrはepelを利用すると簡単。boostは atrpms を利用できます。

$ sudo yum install cmake bzr
$ sudo rpm -Uvh http://dl.atrpms.net/all/boost-1.39.0-9.el5.x86_64.rpm \
  http://dl.atrpms.net/all/boost-devel-1.39.0-9.el5.x86_64.rpm http://dl.atrpms.net/all/boost-wave-1.39.0-9.el5.x86_64.rpm \
  http://dl.atrpms.net/all/boost-thread-1.39.0-9.el5.x86_64.rpm http://dl.atrpms.net/all/boost-test-1.39.0-9.el5.x86_64.rpm \
  http://dl.atrpms.net/all/boost-system-1.39.0-9.el5.x86_64.rpm http://dl.atrpms.net/all/boost-static-1.39.0-9.el5.x86_64.rpm \
  http://dl.atrpms.net/all/boost-signals-1.39.0-9.el5.x86_64.rpm http://dl.atrpms.net/all/boost-serialization-1.39.0-9.el5.x86_64.rpm \
  http://dl.atrpms.net/all/boost-regex-1.39.0-9.el5.x86_64.rpm http://dl.atrpms.net/all/boost-python-1.39.0-9.el5.x86_64.rpm \
  http://dl.atrpms.net/all/boost-program-options-1.39.0-9.el5.x86_64.rpm http://dl.atrpms.net/all/boost-math-1.39.0-9.el5.x86_64.rpm \
  http://dl.atrpms.net/all/boost-iostreams-1.39.0-9.el5.x86_64.rpm http://dl.atrpms.net/all/boost-graph-1.39.0-9.el5.x86_64.rpm \
  http://dl.atrpms.net/all/boost-filesystem-1.39.0-9.el5.x86_64.rpm http://dl.atrpms.net/all/boost-date-time-1.39.0-9.el5.x86_64.rpm \
  http://dl.atrpms.net/all/boost-doc-1.39.0-9.el5.x86_64.rpm

epelのyum repository利用しにくい環境の場合は、

$ sudo yum install python-pycurl
$ sudo rpm -Uvh  http://dl.fedoraproject.org/pub/epel/5/x86_64/bzr-2.1.4-2.el5.x86_64.rpm \
  http://dl.fedoraproject.org/pub/epel/5/x86_64/python-paramiko-1.7.6-1.el5.noarch.rpm \
  http://dl.fedoraproject.org/pub/epel/5/x86_64/python-crypto-2.0.1-4.el5.2.x86_64.rpm

これでも大丈夫です。

次にBinlog APIのインストール。repositoryは https://code.launchpad.net/mysql-replication-listener にあります

$ bzr branch lp:mysql-replication-listener
$ cd mysql-replication-listener/
$ cmake .
$ make -j4
$ sudo make install

最後にreplication_boosterのビルド

$ git clone git://github.com/yoshinorim/replication-booster-for-mysql.git
$ cd replication-booster-for-mysql/
$ cmake .
$ make

検証したサーバではMySQLが通常とは異なるパスに入っていたので、CMakeLists.txtをごにょごにょしました。あと今回は検証目的なので、replication_boosterコマンドはmake installしていません。

コマンドのヘルプ

$ ./replication_booster --help
Usage: 
 replication_booster [OPTIONS]

Example: 
 replication_booster --user=mysql_select_user --password=mysql_select_pass --admin_user=mysql_root_user --admin_password=mysql_root_password --socket=/tmp/mysql.sock 

Options (short name):
 -t, --threads=N                :Number of worker threads. Each worker thread converts binlog events and executes SELECT statements. Default is 10 (threads).
 -o, --offset-events=N          :Number of binlog events that main thread (relay log reader thread) skips initially when reading relay logs. This number should be high when you have faster storage devices such as SSD. Default is 500 (events).
 -s, --seconds-prefetch=N       :Main thread stops reading relay log events when the event's timestamp is --seconds-prefetch seconds ahead of current SQL thread's timestamp. After that the main thread starts reading relay logs from SQL threads's position again. If this value is too high, worker threads will execute many more SELECT statements than necessary. Default value is 3 (seconds).
 -m, --millis-sleep=N           :If --seconds-prefetch condition is met, main thread sleeps --millis-sleep milliseconds before starting reading relay log. Default is 10 milliseconds.
 -u, --user=mysql_user          :MySQL slave user name. This user should have at least SELECT privilege on all application tables (default: root)
 -p, --password=mysql_pwd       :MySQL slave password (default: empty)
 -a, --admin_user=mysql_user    :MySQL administration user for the slave. This user should have at least SUPER and REPLICATION CLIENT (for SHOW SLAVE STATUS) privileges. (default: root)
 -b, --admin_password=mysql_pwd :MySQL password for the administration user. (default:empty)
 -h, --host=mysql_host          :MySQL slave hostname or IP address. This must be local address. (default: localhost)
 -P, --port=mysql_port          :MySQL slave port number (default:3306)
 -S, --socket=mysql_socket      :MySQL socket file path

Replication Booster の実行と結果

replication_boosterは以下のように実行しました

$ ./replication_booster  -t 8 -o 10 -u booster -p xxxxxxx -a booster -p xxxxxxx -h 127.0.0.1

スレッドは8個、relay-logはあまりskipせずに頻繁にクエリを実行させてみました。

結果は以下

replicationbooster.png

グラフは一つ前のエントリ「CloudForecastでMySQLのレプリケーション監視」によるもの。上が秒数、下がバイナリログのポジション。明らかな差はでてないですが、Seconds Behind Masterの平均を取ると、導入前が「0.5」、実行後は「0.2」と遅延幅は小さくなり、レプリケーション遅延のアラートの回数も減りました。

今後は別のサーバも含めてもうちょっと検証していくつもり

MySQLのレプリケーションの遅延状況を取得するプラグインをCloudForecast本体に追加しました。

host_configで

---
component_config:
resources:
  - traffic:eth0
  - traffic:eth1
  - basic
  - mysql
  - innodb
  - mysqlreplication

このように追加すれば使えます。

作られるグラフな下のような感じで、秒数による表示とバイナリログのポジションの2つが作成されます。

cloudforecast_mysqlreplication.png

グラフは某サービスの実際のレプリケーション遅延状況です。データが非常に多いので結構遅れてる事が多いですね。蛇足ですがMySQL4系の場合は「Seconds Behind Master」がないので秒数は常に0になります^^

大きくレプリケーションが遅延するタイミングがあれば、その際に発行されているクエリを見直してみる等の用途にこのグラフが使えるでしょうか。

「Webエンジニアのためのデータベース技術[実践]入門」を技術評論社様から献本頂きました。ありがとうございます。

mysql.jpg

このblogで張ってるAmazonのアフィリエイトリンクを通して一番売れている本は、写真奥に写っていますが、同じく松信さんによる「Linux-DB システム構築/運用入門 (DB Magazine SELECTION) 」です。

blog記事の中やWebアプリケーションエンジニアにお勧めの本を聞かれる度に紹介してきましたが、大体「前半の高可用性の所は呼び飛ばしてもいいよ」という若干残念な一言を加えていました。この「Webエンジニアのためのデータベース技術[実践]入門」ではその心配がなくなって一安心です

Webアプリケーションエンジニアがデータベースを使う上で押さえておいて欲しいポイントは以下の3つだと個人的に考えています

  • インデックスの構造についてビジュアライズして想像できること
  • データの量と性能に関する感覚
  • ハードウェアのトレンド、メモリ・SSD・CPU・クラウド

上述の「Linux-DB システム構築/運用入門」でもこれらの点が丁寧に紹介されていて、非常に参考となりました。

今回の「Webエンジニアのためのデータベース技術[実践]入門」の内容は、インデックス、テーブル設計、SQL、トランザクションといった基礎知識をおさえつつ、DeNAの現場で使われているだろう可用性、レプリケーション、ハードウェアのトレンド、性能改善手法といった実践的な事柄が網羅的に取り上げられています。

データベースの基礎と実践を押さえることができる良本として、これからオススメしていきます。

この機能欲しかったんだよねー。

CustomLogで、pipeしてrotatelogsを使ってログ分割を行う場合、

CustomLog "|/path/to/rotatelogs /path/to/log/access_log.%Y%m%d%H 7200 540"

ログファイルは、

$ ls -1
access_log.2012030116
access_log.2012030118

の様に最新のファイルが変更になります。tail -f で追いかけていた場合は、途中でファイルを手動で切り替えないとならないのでとても不便です。また、fluentdのtail pluginも利用できません。

Apache 2.4.1 のrotatelogsでは、最新のファイルに対してハードリンクを張る機能が追加されたので、とりあえず試してみました。

$ wget http://ftp.riken.jp/net/apache//httpd/httpd-2.4.1.tar.gz
$ tar zxf httpd-2.4.1.tar.gz
$ cd httpd-2.4.1

2.4.1のソースコード中にはapr,apr-utilが含まれていないのでこちらもダウンロード

$ cd srclib
$ wget http://ftp.kddilabs.jp/infosystems/apache//apr/apr-1.4.6.tar.gz \
    http://ftp.kddilabs.jp/infosystems/apache//apr/apr-util-1.4.1.tar.gz       
$ tar zxf apr-1.4.6.tar.gz
$ tar zxf apr-util-1.4.1.tar.gz  
$ mv apr-1.4.6 apr
$ mv apr-util-1.4.1 apr-util
$ cd ..

そしてbuild。

$ ./configure --prefix=/path/to/httpd24 --enable-static-rotatelogs --with-included-apr
$ make

enable-static-rotatelogs を使うと、依存の無い(コピーして使える) rotatelogs コマンドが作れるので便利です。今回は rotatelogs を試したいだけなので、make install はしません

ビルドできたらrotatelogsを試しに実行

./support/rotatelogs 
Incorrect number of arguments
Usage: ./support/rotatelogs [-v] [-l] [-L linkname] [-p prog] [-f] [-t] [-e] [-c] <logfile> {<rotation time in seconds>|<rotation size>(B|K|M|G)} [offset minutes from UTC]

Add this:

TransferLog "|./support/rotatelogs /some/where 86400"

or 

TransferLog "|./support/rotatelogs /some/where 5M"

to httpd.conf. By default, the generated name will be
<logfile>.nnnn where nnnn is the system time at which the log
nominally starts (N.B. if using a rotation time, the time will
always be a multiple of the rotation time, so you can synchronize
cron scripts with it). If <logfile> contains strftime conversion
specifications, those will be used instead. At the end of each
rotation time or when the file size is reached a new log is
started.

Options:
  -v       Verbose operation. Messages are written to stderr.
  -l       Base rotation on local time instead of UTC.
  -L path  Create hard link from current log to specified path.
  -p prog  Run specified program after opening a new log file. See below.
  -f       Force opening of log on program start.
  -t       Truncate logfile instead of rotating, tail friendly.
  -e       Echo log to stdout for further processing.
  -c       Create log even if it is empty.

The program is invoked as "[prog] <curfile> [<prevfile>]"
where <curfile> is the filename of the newly opened logfile, and
<prevfile>, if given, is the filename of the previously used logfile.

「-L」オプションがどうやらそれの様子。

次にログを rotatelogs にログを渡す perl スクリプトを作って実際に切り替わるか試してみます。

#!/usr/bin/perl

use strict;
use warnings;

open(my $fh, '|-:unix', './support/rotatelogs',
    '-L','./log/access_log.link',
    './log/access_log.%Y%m%d%H%M','60','540') or die $!;
while(1){
    print $fh "[".localtime()."] foo bar\n";
    sleep 1;
}

上記のスクリプトでは access_log.%Y%m%d%H%M がログファイルで、access_log.link をリンクとして、60秒ごとにログファイルを切り替えるようにrotatelogsを起動し、1秒ごとにログを出力します。

こいつをtest.plとして保存し実行して、

$ perl test.pl

ログを tail -F(大文字) で観察。

$ tail -F log/access_log.link
[Thu Mar  1 18:21:55 2012] foo bar
[Thu Mar  1 18:21:56 2012] foo bar
[Thu Mar  1 18:21:57 2012] foo bar
[Thu Mar  1 18:21:58 2012] foo bar
[Thu Mar  1 18:21:59 2012] foo bar
tail: `access_log.link' has been replaced;  following end of new file
[Thu Mar  1 18:22:00 2012] foo bar
[Thu Mar  1 18:22:01 2012] foo bar
[Thu Mar  1 18:22:02 2012] foo bar
[Thu Mar  1 18:22:03 2012] foo bar

59秒と00秒の間で切り替わりました。よさそう。

staticでビルドすれば、Apache 2.4系を使わなくても rotatelogsだけコピーして、2.2系のサーバに使ったりできるので、今すぐにでもrotatelogsでローカルのログを管理しつつ、fluentも使うことができるんじゃないでしょうか。

GrowthForecastというグラフ表示ツールで捗る話」で紹介したGrowthForecastですが、モリス氏のfluent meetupでの発表やriywo氏の発表で少し紹介されていたりするわけですが、社内でも少しずつメトリクスが増えて活用されています。

データが既に入っているので大きな変更はできないのですが、少し機能追加をしています。

ソースコード
https://github.com/kazeburo/GrowthForecast

1分更新グラフ

GrowthForecast はWebアプリケーションとWorkerの2つから構成されています。APIに対してPOSTされたデータは、一旦SQLiteのDBに格納され、Workerがそれを取得、RRDファイルを更新します。これまでは5分毎に動くworkerがいるだけでしたが、そこに1分毎動くworkerを追加しました。

growthforecast_two_workers.png

上の図のようにworkerが2つ動くようになりました。すぐに結果が知りたいとき、5分よりも高い解像度でデータがみたいときに利用できます。

画面では、とりあえず感が強いけどボタンが追加されています。

growthforecast-1min.png

デフォルトでこの機能が有効になっていますが、以下のように起動することで、これまでと同じ5分更新だけにできます

$ perl growthforecast.pl --disable-1min-metrics

JSONフォーマットでの出力機能追加

これまでGrowthForecastはデータを溜め込んでグラフとして表示するだけでしたが、これだけではせっかく貯めたデータの再利用ができず捗りません。そこでRRDファイルに保存されているデータをJSONにて出力できるAPIを作りました。

APIは2種類。1つ目はグラフの凡例にでているサマリー取得API

$ curl http://example.com/summary/path/to/graph
{"graph":["0.00000000","0.09241971","5.91815168","0.00000000"]}

レスポンスのデータは指定期間中の「現在」「平均」「最大」「最小」となります。

もう一つのAPIは、グラフデータのエクスポート。

$ curl http://gf.ops.dev.livedoor.net/xport/path/to/graph?t=d&gmode=subtract
{"column_names":["graph"],"step":600,"columns":1,"end_timestamp":1329790200,"start_timestamp":1329671400,"rows":[[0.499581818333333],[0],[0],[0],[0],[0],[0],[0],[0],...,[null]]}

このようにグラフを描く際に使う値が取得できます。2つのAPIは複合グラフでも利用可能です。

これらのAPIを使って、以下のような監視をすることを妄想中です。

fluent-growthforecast-monitoring.png

アクセスログからステータスコードごとにまとめて件数をGrowthForecastになげて、エラーの割合が一定を超えたらアラートを出すとか、ツールを連携させることで実現できそうですね

合わせて読みたい

fluent-plugin-flowcounter および fluent-plugin-growthforecast released! #fluentd - tagomorisのメモ置き場

slowloris対策として、Apacheの2.1.15から入ったモジュールにmod_reqtimeoutというのがあります。

RequestReadTimeout header=10 body=30

このように設定することで、headerの受信が10秒以内、bodyの受信が30秒以内に完了しない場合、「408」エラーとできます。簡単で便利そうですね

公式ドキュメント http://httpd.apache.org/docs/2.2/en/mod/mod_reqtimeout.html


ただし、

Apacheをreverse proxyとして使用している場合はTimeoutにならず、リクエストの一部がproxy先に送られるという問題があるので注意が必要というか、はまったのでその話。

ちなみに、すでにBugzillaには上がっているけど、2.2系ではまだ対応完了してない https://issues.apache.org/bugzilla/show_bug.cgi?id=51103




以下再現方法。

まず、reverse proxy側で RequestReadTimeout と ProxyPass を設定します

RequestReadTimeout header=10 body=5
ProxyPass /backend http://127.0.0.1:5000

そして、backendとなるStarletには以下のpatchをあてます。

diff --git a/lib/Starlet/Server.pm b/lib/Starlet/Server.pm
index ea5a34a..f99f360 100644
--- a/lib/Starlet/Server.pm
+++ b/lib/Starlet/Server.pm
@@ -17,6 +17,8 @@ use Socket qw(IPPROTO_TCP TCP_NODELAY);
 use Try::Tiny;
 use Time::HiRes qw(time);

+use Log::Minimal;
+
 use constant MAX_REQUEST_SIZE => 131072;
 use constant MSWin32          => $^O eq 'MSWin32';

@@ -155,6 +157,10 @@ sub handle_connection {
         undef $can_exit;
         my $reqlen = parse_http_request($buf, $env);
         if ($reqlen >= 0) {
+            {
+                local $Log::Minimal::AUTODUMP=1;
+                warnf $env;
+            }
             # handle request
             if ($use_keepalive) {
                 if (my $c = $env->{HTTP_CONNECTION}) {
@@ -177,6 +183,7 @@ sub handle_connection {
                             $conn, \$chunk, $cl, 0, $self->{timeout})
                             or return;
                     }
+warnf "chunk size: %d", length($chunk);
                     $buffer->print($chunk);
                     $cl -= length $chunk;
                 }

関係ないけどStarletはシンプルなのでこういう検証に便利ですね

そしてtest用のpsgiアプリケーションを書いて

use Plack::Request;

sub {
    my $env = shift;
    my $req = Plack::Request->new($env);
    my $content = $req->content();
    my $length = length($content);
    [200,['Content-Type'=>'text/plain','Content-Length'=>length($length)+1],["$length\n"]];
};

起動、

$ plackup -s Starlet test.psgi

今度は、Bodyを送るのに5秒以上掛かるように細工したクライアントを書きます

#!/usr/bin/perl

use strict;
use warnings;
use IO::Socket::INET;

my $sock = IO::Socket::INET->new(
    PeerAddr => '127.0.0.1',
    PeerPort => '8080',
);

my $header = <<EOF;
POST /backend/foo HTTP/1.1
Host: example.com
User-Agent: slowpost
Content-Length: 32768
EOF

$header =~ s/\n/\r\n/g;

$sock->syswrite("$header\r\n");

for (1..8) {
    $sock->syswrite("1"x4096);
    sleep 1;
}

my $res;
$sock->sysread( $res, 8192 );

print $res;

これを使って、Apacheに向けてリクエストを送ってみると、、

$ perl slowpost.pl
HTTP/1.1 400 Bad Request
Date: Thu, 16 Feb 2012 02:28:51 GMT
Content-Length: 226
Connection: close
Content-Type: text/html; charset=iso-8859-1

<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>400 Bad Request</title>
</head><body>
<h1>Bad Request</h1>
<p>Your browser sent a request that this server could not understand.<br />
</p>
</body></html>

Bodyの送信に5秒以上掛かっているので、期待としては「408」が返って来そうですが「400」となりました。

Apacheのエラーログには

[Thu Feb 16 11:28:56 2012] [error] proxy: pass request body failed to 127.0.0.1:5000 (127.0.0.1) from 127.0.0.1 ()

このように記録されています。

ふむふむ、bodyのproxyに失敗しただけかと思うのですが、実際にはbodyも一部だけがproxyされ途中で切れています。

以下がplackupを起動したターミナルの出力

2012-02-16T11:28:54 [WARN] {'psgi.multiprocess' => 1,'SCRIPT_NAME' => '','SERVER_NAME' => 0,'HTTP_CONNECTION' => 'close','HTTP_X_FORWARDED_SERVER' => 'kazeburomba.local','PATH_INFO' => '/foo','CONTENT_LENGTH' => '32768','REQUEST_METHOD' => 'POST','psgi.multithread' => '','HTTP_USER_AGENT' => 'slowpost','QUERY_STRING' => '','REMOTE_PORT' => 55700,'SERVER_PORT' => 5000,'psgix.input.buffered' => 1,'REMOTE_ADDR' => '127.0.0.1','HTTP_X_FORWARDED_HOST' => 'example.com','SERVER_PROTOCOL' => 'HTTP/1.1','HTTP_X_FORWARDED_FOR' => '127.0.0.1','psgi.streaming' => 1,'psgi.errors' => *::STDERR,'REQUEST_URI' => '/foo','psgi.version' => [1,1],'psgi.nonblocking' => '','psgix.io' => bless( \*Symbol::GEN1, 'IO::Socket::INET' ),'psgi.url_scheme' => 'http','psgi.run_once' => '','HTTP_HOST' => '127.0.0.1:5000'} at /Users/hoge/perl5/perlbrew/perls/perl-5.12.2/lib/site_perl/5.12.2/Starlet/Server.pm line 162
2012-02-16T11:28:54 [WARN] chunk size:16384 at /Users/hoge/perl5/perlbrew/perls/perl-5.12.2/lib/site_perl/5.12.2/Starlet/Server.pm line 184

ヘッダも送られてきて、Bodyも16384byte読み込んでいます。

実際、StarletではBody部分がContent-Lengthの長さにならなければリクエストの処理に移らないので、問題とはならないのですが、Content-Lengthと異なっていても正常に処理をしてしまった場合(libapreqを使うmod_perlがそうだった気がする)問題となる可能性があります。

こわいこわい

おそらく原因としては、mod_reqtimeoutもmod_proxyもfilterで動いていて、reqtimeoutがエラーと判断した時にはすでにmod_proxyがbackendにコンテンツを送ってしまっていて、mod_proxyでリクエストのBofyの続きが読めなくなって「400」エラーって事なんだろうなぁと思ってます。

対策としては、RequestReadTimeout を使わない、もしくは使う場所を限定する(アップロードなど通信時間長くなるところには使わない)、Content-LengthやChunked-Transferを正しく扱うサーバを使ってのが考えられます。

そういえば昔、同じような問題に、LimitRequestBodyでもあたったことがあって、ApacheのFilter機構は難しいなぁと思った次第。

最近のコンテンツはインデックスページで見られます。過去に書かれたものはアーカイブのページで見られます。

アイテム

  • cf_redis.png
  • replicationbooster.png
  • replication_backup_slave.png
  • replication_booster_mysql.png
  • cloudforecast_mysqlreplication.png
  • mysql.jpg
  • fluent-growthforecast-monitoring.png
  • growthforecast-1min.png
  • growthforecast_two_workers.png
  • nginx11keepalive.png

ウェブページ

OpenID対応しています OpenIDについて
Powered by Movable Type 4.27-ja