gdb で MySQL 5.0.96 のスロークエリログを追ってみる

1つ前のエントリ Query_time - Lock_time > long_query_time - takatoshiono's blog で以下のように書いた。

ソースコード

MySQL 5.0.96 で Lock_time が 0 になるのが気になったのでソースをダウンロードしてきて追ってみた。Lock_time で grep すると以下のコードに辿り着くので変数名を頼りに少しさまよってみたのだが、力不足で追いきれなかった。無念。

Webエンジニアのための データベース技術[実践]入門 (Software Design plus) を読んで動的解析の方法を学習したので試してみる。

MySQL 5.0.96 をデバッグモードでインストール

kamipo/mysql-build · GitHub を使って 5.0.96 を —with-debug でインストールした。

最初 sed で illegal byte sequence とか出てエラーになったので brewgnu-sed をインストールして PATH を通してからもう一回やったらうまくいった。

デバッグモードで起動する

➜ 5.0.96 gdb ./libexec/mysqld
GNU gdb 6.3.50-20050815 (Apple version gdb-1820) (Sat Jun 16 02:40:11 UTC 2012)
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "x86_64-apple-darwin"...Reading symbols for shared libraries ... done

(gdb)

ブレークポイントを設定する。 目標は以下のソースコードなので、

sql/log.cc

2345     if (query_start_arg)
2346     {
2347       /* For slow query log */
2348       if (my_b_printf(&log_file,
2349                       "# Query_time: %lu  Lock_time: %lu  Rows_sent: %lu  Rows_examined: %lu\n",
2350                       (ulong) (current_time - query_start_arg),
2351                       (ulong) (thd->time_after_lock - query_start_arg),
2352                       (ulong) thd->sent_row_count,
2353                       (ulong) thd->examined_row_count) == (uint) -1)
2354         tmp_errno=errno;
2355     }

以下のようにした。

(gdb) br log.cc:2345
Breakpoint 1 at 0x10013ea5f: file log.cc, line 2345.

で、run する。 my.cnf にはスロークエリログが1秒で出力されるように設定した。

(gdb) run --defaults-file=/Users/usr0600268/opt/mysql/.my.cnf
Starting program: /Users/usr0600268/opt/mysql/5.0.96/libexec/mysqld --defaults-file=/Users/usr0600268/opt/mysql/.my.cnf
(省略)
Version: '5.0.96-debug-log' socket: '/tmp/mysql.sock' port: 3306 Source distribution
[Switching to process 8239 thread 0x1e03]

ロック待ちタイムアウトの実験

これで起動したので mysql コマンドでクライアント2つ起動して、update がロックするように試す。

クライアント1

mysql> desc entries ;
+------------+--------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+------------+--------------+------+-----+---------+----------------+
| id | int(11) | NO | PRI | NULL | auto_increment |
| name | varchar(255) | NO | | NULL | |
| count | int(11) | NO | | NULL | |
| created_at | datetime | NO | | NULL | |
| updated_at | datetime | NO | | NULL | |
+------------+--------------+------+-----+---------+----------------+
5 rows in set (0.01 sec)

mysql> insert into entries(name,count,created_at,updated_at) values('entry A',100,now(),now()) ;
Query OK, 1 row affected (0.00 sec)

mysql> insert into entries(name,count,created_at,updated_at) values('entry B',100,now(),now()) ;
Query OK, 1 row affected (0.01 sec)

mysql> select * from entries ;
+----+-----------+--------+---------------------+---------------------+
| id | name | count | created_at | updated_at |
+----+-----------+--------+---------------------+---------------------+
| 1 | entry A | 100 | 2015-02-10 00:58:50 | 2015-02-10 00:58:50 |
| 2 | entry B | 100 | 2015-02-10 00:59:00 | 2015-02-10 00:59:00 |
+----+-----------+--------+---------------------+---------------------+
2 rows in set (0.00 sec)

mysql> start transaction ;
Query OK, 0 rows affected (0.00 sec)

mysql> update entries set count = count + 1 where id = 1 ;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0

クライアント2

➜ ~ mysql -uroot -A
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.0.96-debug-log Source distribution

Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> use test
Database changed
mysql> start transaction ;
Query OK, 0 rows affected (0.00 sec)

mysql> update entries set count = count + 1 where id = 1 ;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
mysql>

そうすると Lock wait timeout のタイミングで以下のブレークポイントで止まった。

Breakpoint 1, MYSQL_LOG::write (this=0x1005ca068, thd=0x101063800, query_length=52, query_start_arg=1423497577) at log.cc:2345
2345 if (query_start_arg)
(gdb) s
2348 if (my_b_printf(&log_file,
(gdb) p current_time
$1 = 1423497628
(gdb) p query_start_arg
$2 = 1423497577
(gdb) p (ulong) (current_time - query_start_arg)
$3 = 51
(gdb) p thd->time_after_lock
$4 = 1423497577
(gdb) p (ulong) (thd->time_after_lock - query_start_arg)
$5 = 0

変数の中身を見ると (ulong) (thd->time_after_lock - query_start_arg) つまり Lock_time が 0 になっていることを確認できた。

で、プログラムを続行すると

(gdb) c
Continuing.

以下のようにスロークエリログに出力されていることを確認できた。

# Time: 150210 1:00:28
# User@Host: root[root] @ localhost []
# Query_time: 51 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
use test;
update entries set count = count + 1 where id = 1;

なるほど便利。