ablog

不器用で落着きのない技術者のメモ

Amazon Redshift の SYS_QUERY_HISTORY の elapsed_time は lock_wait_time を含む

AWS Redshift

検証結果

  • elapsed_time = end_time - start_time
  • lock_wait_time は elapsed_time に含まれる

検証手順

  • テーブルを作成して、行を挿入
CREATE TABLE testtab1(id int primary key, name varchar(32));
INSERT INTO testtab1 (id, name) VALUES(1, 'foo');
INSERT INTO testtab1 (id, name) VALUES(2, 'bar');

dev awsuser 20230606_15:56:13 =# BEGIN;
UPDATE testtab1 SET name='fff' WHERE id=1;
BEGIN
Time: 261.403 ms
UPDATE 2
Time: 994.728 ms

（しばらくして commit）

dev awsuser 20230606_15:56:17 =# commit;
COMMIT
Time: 917.933 ms
dev awsuser 20230606_15:59:18 =#
  • 別セッションで UPDATE を実行（ロック待ちになる）
dev awsuser 20230606_15:56:27 =# UPDATE testtab1 SET name='bbb' WHERE id=2;
（別セッションを commit するとロックが解放され実行される）
UPDATE 2
Time: 170493.007 ms (02:50.493)
dev awsuser 20230606_15:59:20 =#
  • SYS_QUERY_HISTORY を確認（"UPDATE testtab1 SET name='bbb' WHERE id=2" のクエリを参照）
    • elapsed_time = end_time - start_time となる
    • elapsed_time と lock_wait_time + execution_time がほぼ近い値になり、elapsed_time は lock_wait_time を含む。
dev awsuser 20230606_16:01:17 =# select start_time, end_time, end_time-start_time end_minus_start, elapsed_time,  queue_time+execution_time+planning_time+lock_wait_time time_sum, queue_time, execution_time, compile_time, planning_time, lock_wait_time, substring(query_text,1,50) from sys_query_history where query_text like '%testtab1%' order by start_time;
         start_time         |          end_time          | end_minus_start | elapsed_time | time_sum  | queue_time | execution_time | compile_time | planning_time | lock_wait_time |                     substring
----------------------------+----------------------------+-----------------+--------------+-----------+------------+----------------+--------------+---------------+----------------+----------------------------------------------------
 2023-06-06 06:56:17.005435 | 2023-06-06 06:56:17.823341 | 817906          |       817906 |    805815 |          0 |         803375 |            0 |          2424 |             16 | UPDATE testtab1 SET name='fff' WHERE id=1;
 2023-06-06 06:56:29.727066 | 2023-06-06 06:59:19.201868 | 169474802       |    169474802 | 169463828 |          0 |         413926 |            0 |          2895 |      169047007 | UPDATE testtab1 SET name='bbb' WHERE id=2;

長時間WLMキュー待ちケースを実行して、キュー待ちが elapsed_time に含まれるか確認する。

compile_time、planning_time が長い複雑なクエリを実行して、compile_time、planning_time が execution_time に含まれるか確認する。

クエリログから start_time がクエリ受付時刻か、実行開始時刻か確認する。

参考