プロシージャには複数のSELECTやINSERTが含まれています。
どのSQLが遅かったか突き止める方法はあるのでしょうか？
プロシージャに含まれている、各SQLはスロークエリログに落ちるんでしょうか？
試してみます。
テスト用に遅いプロシージャを作ります。
DELIMITER //
CREATE PROCEDURE sample()
BEGIN
SELECT SLEEP(10);
END
//
DELIMITER ;
mysql> SET GLOBAL slow_query_log = ON;
Query OK, 0 rows affected (0.00 sec)
mysql> SET GLOBAL long_query_time = 0;
Query OK, 0 rows affected (0.00 sec)
スロークエリログにはプロシージャの中身は表示されませんでた。。。
/usr/sbin/mysqld, Version: 8.0.15 (MySQL Community Server - GPL). started with:
Tcp port: 3306 Unix socket: /var/lib/mysql/mysql.sock
Time Id Command Argument
# Time: 2019-04-03T06:54:09.547179Z
# User@Host: root[root] @ localhost Id: 30
# Query_time: 10.001274 Lock_time: 0.000376 Rows_sent: 1 Rows_examined: 0
SET timestamp=1554274439;
call test.sample();
Rows_examinedの値はどうなるんだろうか？
DELIMITER //
CREATE PROCEDURE sample2()
BEGIN
SELECT * FROM mysql.user;
SELECT * FROM mysql.user;
END
//
DELIMITER ;
このSELECT文は一回あたり、5行スキャンする
# Time: 2019-04-03T07:02:03.693124Z
# User@Host: root[root] @ localhost Id: 32
# Query_time: 0.000284 Lock_time: 0.000127 Rows_sent: 5 Rows_examined: 5
SET timestamp=1554274923;
select * from mysql.user;
ログには二回分（合計１０）がちゃんと記録された。Row_examined の値は正しく合計を表していると。
# Time: 2019-04-03T07:04:31.383244Z
# User@Host: root[root] @ localhost [] Id: 36
# Query_time: 0.000693 Lock_time: 0.000000 Rows_sent: 10 Rows_examined: 10
SET timestamp=1554275071;
CALL samitani.sample2();
まとめ：
- プロシージャの中身のどこが遅いかはスロークエリログからわからない。
- 中のSQLを１つ１つ実行してみるしかなさそう
- Rows_examined は合計が記録される。
つづく。。。
