プロシージャの中身のクエリはスロークエリログに落ちない

とあるMySQLのデータベースで、性能劣化した疑いのあるプロシージャがありました。
プロシージャには複数の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 は合計が記録される。

つづく。。。