# mysql
mysql> show global variables like '%slow_query%';
+---------------------+-------------------------------+
| Variable_name | Value |
+---------------------+-------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /var/lib/mysql/mysql-slow.log |
+---------------------+-------------------------------+
2 rows in set (0.00 sec)
mysql> show global variables like '%long_query_time%';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.00 sec)
mysql> show global variables like '%log_output%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output | FILE |
+---------------+-------+
1 row in set (0.00 sec)
rootにて実行
long_query_timeを1から0.1に変更
vi /etc/my.cnf
long_query_time = 0.1
再起動
service mysql restart
2台ターミナルは開くこと
cd /var/lib/mysql
tail -f mysql-slow.log
グローバルIPを利用する場合は各自のIPを設定すること
curl http://localhost/exercise/part4
tailにてスローログが出力されていること
# Time: 150610 18:06:37
# User@Host: techtrain[techtrain] @ localhost [] Id: 89
# Query_time: 6.028402 Lock_time: 0.000047 Rows_sent: 0 Rows_examined: 1754073
SET timestamp=1433927197;
select * from message where title = 'チューニングバトル' order by created_at desc limit 10;
上記で出力されたSQLにて確認する
explain時に末尾を「;」から「\G」に変えること
mysql> explain select * from message where title = 'チューニングバトル' order by created_at desc limit 10\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: message
type: ALL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: 1522365
Extra: Using where; Using filesort
1 row in set (0.00 sec)
mysql> explain select u.name ,m.message from message m inner join user u on u.id = m.user_id where m.id = 100\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: m
type: const
possible_keys: PRIMARY
key: PRIMARY
key_len: 4
ref: const
rows: 1
Extra: NULL
*************************** 2. row ***************************
id: 1
select_type: SIMPLE
table: u
type: const
possible_keys: PRIMARY
key: PRIMARY
key_len: 4
ref: const
rows: 1
Extra: NULL
2 rows in set (0.01 sec)
MySQL5.6から実装
mysql> explain insert into user values (null,'A','A','A','A','A',now(),now())\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: NULL
type: NULL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: NULL
Extra: No tables used
1 row in set (0.00 sec)
messageにINDEXを追加
mysql> alter table message add index user_id(user_id);
Query OK, 0 rows affected (12.52 sec)
Records: 0 Duplicates: 0 Warnings: 0
mysql> select count(*) from message force index (primary);
+----------+
| count(*) |
+----------+
| 1754069 |
+----------+
1 row in set (6.04 sec)
mysql> select count(*) from message force index (user_id);
+----------+
| count(*) |
+----------+
| 1754069 |
+----------+
1 row in set (0.53 sec)
mysql> explain select id from message where user_id = 10 or id = 10\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: message
type: index_merge
possible_keys: PRIMARY,user_id
key: user_id,PRIMARY
key_len: 5,4
ref: NULL
rows: 12
Extra: Using union(user_id,PRIMARY); Using where
1 row in set (0.01 sec)
mysql> explain select id from message where user_id = 10 union select id from message where id = 10\G
*************************** 1. row ***************************
id: 1
select_type: PRIMARY
table: message
type: ref
possible_keys: user_id
key: user_id
key_len: 5
ref: const
rows: 11
Extra: Using index
*************************** 2. row ***************************
id: 2
select_type: UNION
table: message
type: const
possible_keys: PRIMARY
key: PRIMARY
key_len: 4
ref: const
rows: 1
Extra: Using index
*************************** 3. row ***************************
id: NULL
select_type: UNION RESULT
table: <union1,2>
type: ALL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: NULL
Extra: Using temporary
3 rows in set (0.00 sec)
mysql> select count(*) from message;
+----------+
| count(*) |
+----------+
| 1754069 |
+----------+
1 row in set (0.37 sec)
mysql> select count(*) from message;
+----------+
| count(*) |
+----------+
| 1754069 |
+----------+
1 row in set (0.35 sec)
mysql> select count(*) from message;
+----------+
| count(*) |
+----------+
| 1754069 |
+----------+
1 row in set (0.38 sec)
rootにて行うこと
[mysqld]の段落に追記すること
# vi /etc/my.cnf
query_cache_type = ON
# service mysql restart
2回目以降0.00 secであること
mysql> select count(*) from message;
+----------+
| count(*) |
+----------+
| 1754069 |
+----------+
1 row in set (0.46 sec)
mysql> select count(*) from message;
+----------+
| count(*) |
+----------+
| 1754069 |
+----------+
1 row in set (0.00 sec)
mysql> select count(*) from message;
+----------+
| count(*) |
+----------+
| 1754069 |
+----------+
1 row in set (0.00 sec)
2回目でQcache_hitsがインクリメントされていること
mysql> show status like 'Qcache%';
+-------------------------+---------+
| Variable_name | Value |
+-------------------------+---------+
| Qcache_free_blocks | 1 |
| Qcache_free_memory | 1029832 |
| Qcache_hits | 4 |
| Qcache_inserts | 1 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 4 |
| Qcache_queries_in_cache | 1 |
| Qcache_total_blocks | 4 |
+-------------------------+---------+
8 rows in set (0.00 sec)
mysql> select count(*) from message;
+----------+
| count(*) |
+----------+
| 1754069 |
+----------+
1 row in set (0.00 sec)
mysql> show status like 'Qcache%';
+-------------------------+---------+
| Variable_name | Value |
+-------------------------+---------+
| Qcache_free_blocks | 1 |
| Qcache_free_memory | 1029832 |
| Qcache_hits | 5 |
| Qcache_inserts | 1 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 4 |
| Qcache_queries_in_cache | 1 |
| Qcache_total_blocks | 4 |
+-------------------------+---------+
8 rows in set (0.00 sec)
2台のターミナルで実施
$ siege -c 10 http://localhost/exercise/part4
processlistに着目
mysql> show processlist;
+-----+----------+-----------+-----------+---------+------+---------------------+----------------------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+----------+-----------+-----------+---------+------+---------------------+----------------------------------------------------------------------------------------------------+
| 1 | root | localhost | groupwork | Sleep | 3934 | | NULL |
| 2 | root | localhost | groupwork | Query | 0 | init | show processlist |
| 387 | demouser | localhost | groupwork | Execute | 0 | Creating sort index | select title,message,created_at from message where user_id = '79679' order by created_at limit 100 |
+-----+----------+-----------+-----------+---------+------+---------------------+----------------------------------------------------------------------------------------------------+
3 rows in set (0.00 sec)
mysql> use test
mysql> create table test (id int,col1 varchar(10),primary key (id));
Query OK, 0 rows affected (0.05 sec)
mysql> insert into test values(1,'abc');
Query OK, 1 row affected (0.00 sec)
mysql> select * from test;
+----+------+
| id | col1 |
+----+------+
| 1 | abc |
+----+------+
1 row in set (0.00 sec)
mysql> insert into test values(2,'bbb'),(3,'ccc'),(4,'ddd');
Query OK, 3 rows affected (0.00 sec)
Records: 3 Duplicates: 0 Warnings: 0
mysql> select * from test;
+----+------+
| id | col1 |
+----+------+
| 1 | abc |
| 2 | bbb |
| 3 | ccc |
| 4 | ddd |
+----+------+
4 rows in set (0.00 sec)
2台のターミナルで実施
LATEST DETECTED DEADLOCKが無いこと
mysql> show engine innodb status\G
mysql> use test
mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into test values(5,'eee');
Query OK, 1 row affected (0.01 sec)
mysql> use test
mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into test values(6,'fff');
Query OK, 1 row affected (0.00 sec)
mysql> update test set col1 = 'zzz' where id = 6;
Query OK, 0 rows affected (27.83 sec)
Rows matched: 0 Changed: 0 Warnings: 0
mysql> update test set col1 = 'yyy' where id = 5;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
LATEST DETECTED DEADLOCKが表示されること
mysql> show engine innodb status\G
中略
------------------------
LATEST DETECTED DEADLOCK
------------------------
2014-01-14 22:51:00 7f5aa9bcd700
*** (1) TRANSACTION:
TRANSACTION 99676, ACTIVE 88 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 47819, OS thread handle 0x7f5aa9b4b700, query id 334756 localhost root updating
update test set col1 = 'zzz' where id = 6
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 8 page no 3 n bits 80 index `PRIMARY` of table `test`.`test` trx id 99676 lock_mode X locks rec but not gap waiting
Record lock, heap no 7 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000006; asc ;;
1: len 6; hex 00000001855d; asc ];;
2: len 7; hex 9a000001870110; asc ;;
3: len 3; hex 666666; asc fff;;
*** (2) TRANSACTION:
TRANSACTION 99677, ACTIVE 53 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 2, OS thread handle 0x7f5aa9bcd700, query id 334757 localhost root updating
update test set col1 = 'yyy' where id = 5
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 8 page no 3 n bits 80 index `PRIMARY` of table `test`.`test` trx id 99677 lock_mode X locks rec but not gap
Record lock, heap no 7 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000006; asc ;;
1: len 6; hex 00000001855d; asc ];;
2: len 7; hex 9a000001870110; asc ;;
3: len 3; hex 666666; asc fff;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 8 page no 3 n bits 80 index `PRIMARY` of table `test`.`test` trx id 99677 lock_mode X locks rec but not gap waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000005; asc ;;
1: len 6; hex 00000001855c; asc \;;
2: len 7; hex 99000001860110; asc ;;
3: len 3; hex 656565; asc eee;;
*** WE ROLL BACK TRANSACTION (2)