mysql:13376
From: "YOSHINO. Satoki" <"YOSHINO. Satoki" <yoshino@xxxxxxxxxx>>
Date: Thu, 21 Sep 2006 12:00:49 +0900
Subject: [mysql 13376] InnoDB でサブクエリを使った update 実行中に書き込みブロック
はじめまして、吉野仁規と申します。 MySQL5.0 でバグかも知れない現象が確認できたので、投稿させて いただきました。 【概要】 フロー制御関数とgroup by句を使ったselect文をupdateの set句で使うと、from句で指定したテーブルへの書き込みが できなくなります。 【環境】 OSは、CentOS 4.3です。 以下はmysqlbugの出力からの抜粋です。 Release: mysql-5.0.24a-standard (MySQL Community Edition - Standard (GPL)) Server: /usr/bin/mysqladmin Ver 8.41 Distrib 5.0.24a, for pc-linux-gnu on i686 Server version 5.0.24a-standard-log System: Linux log 2.6.9-22.EL #1 Sat Oct 8 17:48:27 CDT 2005 i686 i686 i386 GNU/Linux Architecture: i686 【my.cnf】 my.cnf の内容です。 [client] port=3306 default-character-set=sjis [mysql] default-character-set=sjis [mysqld] old_passwords port=3306 default-character-set=sjis default-storage-engine=InnoDB sql-mode="STRICT_TRANS_TABLES,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION" max_connections=500 log_slow_queries query_cache_size=12M table_cache=1000 tmp_table_size=16M thread_cache_size=23 myisam_max_sort_file_size=100G myisam_max_extra_sort_file_size=100G myisam_sort_buffer_size=8M key_buffer_size=18M read_buffer_size=64K read_rnd_buffer_size=256K sort_buffer_size=208K innodb_additional_mem_pool_size=2M innodb_flush_log_at_trx_commit=1 innodb_log_buffer_size=1M innodb_buffer_pool_size=32M innodb_log_file_size=10M innodb_thread_concurrency=8 【テーブル構造】 mysql> desc summary; +---------------------+----------+------+-----+---------+----------------+ | Field | Type | Null | Key | Default | Extra | +---------------------+----------+------+-----+---------+----------------+ | id | int(10) | NO | PRI | NULL | auto_increment | | month | datetime | YES | UNI | NULL | | | sum | int(10) | YES | | NULL | | +---------------------+----------+------+-----+---------+----------------+ mysql> desc log; +-----------------+--------------+------+-----+-------------------+----------------+ | Field | Type | Null | Key | Default | Extra | +-----------------+--------------+------+-----+-------------------+----------------+ | id | bigint(19) | NO | PRI | NULL | auto_increment | | create_on | timestamp | YES | | CURRENT_TIMESTAMP | | | user_id | bigint(19) | YES | MUL | NULL | | +-----------------+--------------+------+-----+-------------------+----------------+ mysql> desc user; +------------+---------------------+------+-----+---------+----------------+ | Field | Type | Null | Key | Default | Extra | +------------+---------------------+------+-----+---------+----------------+ | id | bigint(20) unsigned | NO | PRI | NULL | auto_increment | | kind | int(10) | NO | | 0 | | +------------+---------------------+------+-----+---------+----------------+ summary には10レコード、log には約1300万レコード、user には約2800件の データが入っています。 【現象の詳細】 log テーブルから条件に合致するデータを件数を抜き出し summary テーブルのデータを毎日更新するプログラムを定期 実行していました。 しかし、処理事態に異常に時間が掛かり、また、logへの 書き込みを行うアプリケーションが使えないという報告が あったので調査を行いました。 set句のselect中で間違って必要の無いgroup by を使っていたことが 原因だったのですが、それでもエラーを返さずにクエリが実行され、 テーブルのデータが更新されます。 以下、調査でわかったことを書き出しています。 下記のSQLを実行中に、テーブル log へのinsert/update/delete が ブロックされます。 update summary set sum = (select count(distinct if (user.kind = 0, log.user_id, 1)) - 1 from log inner join user on user.id = log.user_id where log.create_on >= '2006-09-01 00:00:00' and log.create_on < '2006-10-01 00:00:00' group by month(log.create_on)) where month = '2006-09-01 00:00:00'; mysql> insert log set kind = '0'; ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction 以下は /var/lib/mysql/データベース名-slow.log の出力結果です。 # User@Host: root[root] @ localhost [] # Query_time: 51 Lock_time: 0 Rows_sent: 0 Rows_examined: 0 SET insert_id=0,timestamp=1158725869; insert log set kind = '0'; # User@Host: root[root] @ localhost [] # Query_time: 1293 Lock_time: 0 Rows_sent: 0 Rows_examined: 14612378 update log set sum = (select count(distinct if (user.kind = 0, log.user_id, 1)) - 1 from log inner join user on user.id = log.user_id where log.create_on >= '2006-09-01 00:00:00' and log.create_on < '2006-10-01 00:00:00' group by month(log.create_on)) where month = '2006-09-01 00:00:00'; # User@Host: root[root] @ localhost [] # Query_time: 116 Lock_time: 0 Rows_sent: 1 Rows_examined: 14612378 select count(distinct if (kind = 0, user_id, 1)) - 1 from log inner join user on user.id = log.user_id where create_on >= '2006-09-01 00:00:00' and create_on < '2006-10-01 00:00:00' group by month(create_on); エラーログ(サーバー名.err)には何も出力されません。 log テーブルへのupdateを実行中に、mysql> show processlist を 何回か実行することで、Stateの状態が「Sorting result」から 「Sending data」に遷移していることが確認できました。 Stateが「Sending data」の状態の時に書き込みブロックが 発生します。 select を単独で実行すると「Sorting result」が終わった段階で 結果を返し、「Sending data」には遷移しません。 selectでifを使っている箇所をcaseにして書き換えても、同じ 現象が発生します。 selectからフロー制御関数もしくは group by を除くと、 update実行中の書き込みブロックは発生しません。 今回はselect中のgroup by を省いても、結果が一緒(0件の時以外。 結果が0件の時にgroup by を使っていないと「-1」になる。 group by を使うと「0」)なので、group by を使う必然性が 無いのですが、必要な場合もあるかと思います。 (今は例が思いつかなくて申し訳ないのですが) また、もしgroup by をset句のselect内で使う必要が絶対に 無ければ、group by を使った時点でエラーにすべきだと思うの ですが、どうでしょうか? 以上、この現象(バグ?)に関する情報などあればお教えください。 よろしくお願い致します。