[前][次][番号順一覧][スレッド一覧]

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 を使った時点でエラーにすべきだと思うの
ですが、どうでしょうか?

以上、この現象(バグ?)に関する情報などあればお教えください。
よろしくお願い致します。

[前][次][番号順一覧][スレッド一覧]