2012年4月アーカイブ

とある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 というディレクティブ処理関数登録マクロは引数を無限に受け取り、それらを１つずつ処理するディレクティブを登録します。

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でもログにホスト名が記録される場合