Amazon Aurora メトリクス `SELECTレイテンシー` の数値に納得いかなかったので軽く確認した

8008 ワード
Aurora Aurora テキストリンク

これの話です

経緯（というほどでもないけど）

今までこのメトリクスをなんとなく
「SELECTクエリの実行にかかった時間の合計 / 実行したSELECTクエリの数」
のようなものを表すメトリクスだと思っていたのですが

なんとなく使ってる感覚より数値が小さいような…気がする…

latencyってもしかしてSELECTクエリの命令から実行されるまでの遅延のことを言ってたりする？（そんな遅延の存在はさておき）

とりあえずサポートに聞いてみました

ありがたき回答を頂きました

内部情報に関わりますため、ドキュメント等の公開情報以上の具体的なメトリクスの集計方法などについては、回答いたしかねます

とのこと、闇ですね

ちなみにそのドキュメントによると
https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/monitoring/rds-metricscollected.html

SELECT クエリのレイテンシー (ミリ秒)。

とのこと、実質空欄ですね

自分で確かめるしかない

時間がかかるSELECTをひとつだけ実行してみた

mysql> SELECT SLEEP(10);

10sつまり10000ms、さてさて

10000を期待したけど100も行ってなかったです

というか

何もしてないはずなのに結構な数のSELECTが実行されているようです

ログを見ると

2018-08-17 04:02:13 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:14 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:15 rdsadmin[rdsadmin] @ localhost []   SELECT @@aurora_version
2018-08-17 04:02:15 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:15 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:15 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:16 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:17 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:17 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:18 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:19 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:19 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:20 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:21 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:21 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:22 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:23 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:23 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:24 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:25 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:25 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:26 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:27 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:27 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:28 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:29 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:29 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:30 rdsadmin[rdsadmin] @ localhost []   SELECT @@aurora_version
2018-08-17 04:02:30 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:30 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:31 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:31 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:32 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:33 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:33 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:34 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:35 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:35 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:36 rdsadmin[rdsadmin] @ localhost []   SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2018-08-17 04:02:37 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only
2018-08-17 04:02:37 rdsadmin[rdsadmin] @ localhost []   select @@session.tx_read_only

これらのrdsadminが発行してる保守用（？）クエリも全部合わせてSELECTレイテンシーの値に出てるのだろうか
1分間の数は

mysql> SELECT count(*) from mysql.general_log WHERE `argument` LIKE 'SELECT%' AND `event_time` BETWEEN '2018-08-17 04:02:00' AND '2018-08-17 04:02:59';
109

上のrdsadmin発行クエリのdurationを乱暴にも勝手に0としてしまうと（slow query logで0秒表示だったので許してください）
10000 / 109 = 91.743...

なんか大体合ってる感じがする！（偶然かも？）
根拠にするにはちょっと検証が少ないですが今回はここで終了にします

おそらくの結論

AuroraのメトリクスSELECTレイテンシー今までなんとなく思っていた通り
「SELECTクエリの実行にかかった時間の合計 / 実行したSELECTクエリの数」
で合ってるようですが、システムが発行しているクエリのレイテンシも含まれるようです
しかしプロダクションで使ってるような環境なら1分に100くらい分母が増えたところでほとんど影響ないかと思います
もしかしたらしっかり使っている環境にはまた別の見えない動きがあるかもしれませんが…
結果的に全く大したことはなかったですが確認ということで
というかこのくらいの情報は開示してくれてもいいのでは

ちなみに
※RDS全般に当てはまるかもしれませんが今回はAuroraしか使ってないので他のことはわかりません
※他のレイテンシ系メトリクスにも当てはまるかもしれませんが今回は見てないのでわかりません

（余談1）
経緯にあるぼくの「なんとなく」は全然別なところ（アプリケーション側）に原因がありました
（余談2）
Auroraは他にもエラーログのサイズ表示が大きいのに開いたらなにも表示されなかったり（こっち側用のログだから見せてあげないけど問題ないよbyサポート）と闇がちょいちょい見られるので使っていてもやもやすることがあります
でも超強力なプロダクトなので我々は闇に怯えながら使わせていただくしかないみたいですね