Amazon Aurora 지표`SELECT 대기 시간`의 수치에 납득하지 못했기 때문에 가볍게 확인했다

이 이야기입니다.

경위(그렇지 않을 텐데)

지금까지이 메트릭을 어쨌든
SELECT 쿼리를 실행하는 데 걸린 총 시간/실행한 SELECT 쿼리 수
같은 것을 나타내는 지표라고 생각했습니다.

왠지 사용하고 있는 감각보다 수치가 작은 것 같은…

latency 하지만 어쩌면 SELECT 쿼리 명령에서 실행되기까지 지연을 말하는거야? (그런 지연의 존재는 제쳐두고)

우선 지원에 물어 보았습니다.

고맙게 대답했습니다.

내부 정보에 관련되기 때문에, 문서 등의 공개 정보 이상의 구체적인 메트릭스의 집계 방법등에 대해서는, 회답하기 어렵습니다

그건 어둠입니다.

그건 그렇고, 문서에 따르면
htps : // / cs. 아 ws. 아마존. 이 m / 그럼 _ jp / 아마 존 C ぉ 우도 ぁ ch / ぁ st / 모토 린 g / rds - 메 치 cs 여기 c d. 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 지원) 너무 좋을 수 있습니다.
하지만 초강력한 제품이므로 우리는 어둠에 겁을 먹으면서 사용할 수밖에 없는 것 같습니다.