【Redshift】パフォーマンス計測時にはコードコンパイルとリザルトキャッシュに注意

春田拓海 | Takumi

2019.08.13

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

こんにちは。DA事業本部の春田です。

表題の通り、Redshiftには コードコンパイル と リザルトキャッシュ という概念があり、これらを知らずして正確なクエリパフォーマンスの測定はできません。基礎的な内容ですが、簡単にまとめていきたいと思います。

「コードコンパイル」「リザルトキャッシュ」とは？

コードコンパイルとは、あるクエリを 最初に実行した時 にデフォルトで行われるコンパイル処理で、初回実行時のみオーバーヘッドコストが少しかかりますが、2回目以降は高速に実行されるというメリットがあります。コンパイルされたクエリはキャッシュされ、同じクラスタのすべてのセッションへ共有されるため、異なるクライアントでもその恩恵を受けることができます。また、構造が同じでパラメータが異なるクエリでも高速に実行することができます。なお、今現在はコードコンパイルを無効化することはできません。

一方、リザルトキャッシュは、特定の種類のクエリ結果をリーダーノード上のメモリにキャッシュしておき、再実行時にはキャッシュから返すことで、リソースの節約とクエリ実行時間の短縮が可能となる機能です。この機能はデフォルトで有効になっていますが、Redshiftの enable_result_cache_for_session というパラメータでON/OFFの指定ができます。

どちらもクエリの実行時間に大きな影響を与えている機能です。パフォーマンス計測の際には必ず、以下の2点を念頭に置いておきましょう。

1. 事前に SET enable_result_cache_for_session = off; を流してリザルトキャッシュをオフにする 2. 初回実行はコンパイルが走っているため使用しない。2回目以降の結果でパフォーマンスを診断する

参照：

クエリ実行結果のキャッシュ・コンパイル状況を確認してみる

キャッシュとコンパイルの状況を実際に確認してみます。サンプルは、Redshiftチュートリアルのデータを拝借しています。

ステップ 6: Amazon S3 のサンプルデータをロードする - Amazon Redshift

create table sales(
	salesid integer not null,
	listid integer not null distkey,
	sellerid integer not null,
	buyerid integer not null,
	eventid integer not null,
	dateid smallint not null sortkey,
	qtysold smallint not null,
	pricepaid decimal(8,2),
	commission decimal(8,2),
	saletime timestamp
);

copy sales from 's3://awssampledbuswest2/tickit/sales_tab.txt'
credentials 'aws_iam_role=<iam-role-arn>'
delimiter '\t' timeformat 'MM/DD/YYYY HH:MI:SS' region 'us-west-2';

リザルトキャッシュONのクラスターAとOFFのクラスターBに対してクエリを4回流し、クエリ結果がどのキャッシュやコンパイルから出力されたのか確認してみます。

SVL_QLOG: データベースに対して実行されたすべてのクエリログ
SVL_COMPILE: クエリの各クエリセグメントのコンパイル時間と位置

SET enable_result_cache_for_session = on;
-- もしくは
SET enable_result_cache_for_session = off;

SHOW enable_result_cache_for_session;
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01'; -- A: 40ms B: 49ms
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01'; -- A: 10ms B: 23ms
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01'; -- A: 10ms B: 21ms
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01' AND pricepaid > 100; -- A: 2.1s B: 42ms

SELECT
  SVL_QLOG.pid,          -- ステートメントに関連付けられるプロセスID
  SVL_QLOG.query,        -- クエリ ID。他の各種システムテーブルおよびビューを結合するために使用できる
  SVL_QLOG.starttime,    -- ステートメントの実行が開始された正確な時刻
  SVL_QLOG.elapsed,      -- クエリの実行にかかった時間の長さ (マイクロ秒)
  SVL_QLOG.source_query, -- クエリで結果のキャッシュが使用された場合、キャッシュされた結果のソースとなったクエリのクエリID。結果のキャッシュが使用されていない場合、このフィールドの値はNULL
  SVL_COMPILE.segment,   -- コンパイルするクエリセグメント
  SVL_COMPILE.locus,     -- セグメントを実行する場所。コンピューティングノード上にある場合は 1、リーダーノード上にある場合は 2
  SVL_COMPILE.compile    -- コンパイルが再利用された場合は 0、セグメントがコンパイルされた場合は 1
FROM SVL_QLOG
LEFT JOIN SVL_COMPILE ON SVL_COMPILE.query = SVL_QLOG.query
WHERE SVL_QLOG.substring like 'SELECT count(*) FROM sales%'
ORDER BY SVL_QLOG.starttime DESC;

結果は以下のようになりました。（starttimeで降順）

クラスターA: リザルトキャッシュON

リザルトキャッシュONのクラスターAでは、最初の実行で4つのセグメントでコンパイルが行われ、2回目3回目の実行では source_query のカラムにある通り、クエリID = 21、すなわち一番最初のキャッシュされたクエリ結果が返されており、初回と比べて30msほど高速になりました。4つ目はWHERE句にもう一つ条件を加えたクエリですが、セグメント0で再度コンパイルが動いたため実行時間が2.1sと遅くなりました。

SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01'; -- A: 40ms
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01'; -- A: 10ms
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01'; -- A: 10ms
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01' AND pricepaid > 100; -- A: 2.1s

pid	query	starttime	elapsed	source_query	segment	locus	compile
9773	39	2019-08-13 10:47:48.155894	2045497		2	2	0
9773	39	2019-08-13 10:47:48.155894	2045497		0	1	1
9773	39	2019-08-13 10:47:48.155894	2045497		1	1	0
9773	39	2019-08-13 10:47:48.155894	2045497		3	2	0
9773	23	2019-08-13 10:47:04.636792	23	21
9773	22	2019-08-13 10:47:00.604891	31	21
9773	21	2019-08-13 10:46:52.322476	25990		0	1	0
9773	21	2019-08-13 10:46:52.322476	25990		2	2	0
9773	21	2019-08-13 10:46:52.322476	25990		3	2	0
9773	21	2019-08-13 10:46:52.322476	25990		1	1	0

クラスターB: リザルトキャッシュOFF

一方、リザルトキャッシュOFFのクラスターBでは、全てその都度クエリが実行されています。1回目はコンパイルのため49msと遅く、2回目3回目はコンパイルを再利用したため23msと21msと高速になりましたが、キャッシュを使っているクラスターAの2回目3回目の方が速い結果となっています。クラスターAの4回目の実行では、再コンパイルが走っていましたが、クラスターBの方では上手く使い回せたようです。この辺り、セグメントでコンパイルするかどうかの基準は気まぐれといったところでしょうか……？

SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01'; -- B: 49ms
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01'; -- B: 23ms
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01'; -- B: 21ms
SELECT count(*) FROM sales WHERE saletime BETWEEN '2008-01-01 00:00:00' AND '2008-09-01' AND pricepaid > 100; -- B: 42ms

pid	query	starttime	elapsed	segment	locus
10114	83	2019-08-13 10:53:58.670213	27340	0	1
10114	83	2019-08-13 10:53:58.670213	27340	3	2
10114	83	2019-08-13 10:53:58.670213	27340	2	2
10114	83	2019-08-13 10:53:58.670213	27340	1	1
10114	82	2019-08-13 10:53:49.308988	7272	0	1
10114	82	2019-08-13 10:53:49.308988	7272	2	2
10114	82	2019-08-13 10:53:49.308988	7272	3	2
10114	82	2019-08-13 10:53:49.308988	7272	1	1
10114	81	2019-08-13 10:53:46.013981	7191	0	1
10114	81	2019-08-13 10:53:46.013981	7191	3	2
10114	81	2019-08-13 10:53:46.013981	7191	2	2
10114	81	2019-08-13 10:53:46.013981	7191	1	1
10114	80	2019-08-13 10:53:41.198118	34298	2	2
10114	80	2019-08-13 10:53:41.198118	34298	0	1
10114	80	2019-08-13 10:53:41.198118	34298	3	2
10114	80	2019-08-13 10:53:41.198118	34298	1	1