postgresql で実行したSQLのシステムコールを眺めてみる
検索プラットフォーム事業部の澁谷です。
皆さん、システムコールって意識していますか？
昔からあるデバック方法の一つですが、最近の開発で「システムコール」を意識することも少なくなっている気がします。今回はシステムコールのデバックコマンド [strace ] の紹介がてら、postgresql で実行したSQLの挙動を眺めてみます。
システムコールとは？
システムコールとは、コンピュータ上で実行中のプログラムが、オペレーティングシステム（OS）のカーネルの特権的な機能を呼び出す仕組み。ネットワークを利用した通信、ファイルへの入出力、新しいプロセスの生成、プロセス間通信などは、システムコールを使用することで実現されます。
なお、CPU・メモリ上の計算であればシステムコールは発生しません。
どうやってトレースする？
linux (ubuntu ) の strace コマンドを使用し、トレースしたいプロセスのPIDを事前もしくは実行中に調べ、strace コマンド の [p]オプションへ指定すると確認することができます。
例えば、apache の親プロセスをトレースすると以下のようになります。
select,read.fstat,write,waitid などがシステムコールになります。
$ sudo strace -p 1339
strace: Process 1339 attached
select(48, [3 5 6 7 8 9 11 12 13 15 18 19 20 22 23 26 27 29 32 34 35 37 39 41 43 44 45 47], [], [7 8 9 11 12 15 19], NULL) = 1 (in [23])
read(23, "[20194:20194:1128/134821.397022:"..., 8192) = 117
read(23, 0x55e2ab413285, 8075) = -1 EAGAIN (Resource temporarily unavailable)
fstat(14, {st_mode=S_IFREG|0640, st_size=5046, ...}) = 0
write(14, "[20194:20194:1128/134821.397022:"..., 117) = 117
read(3, 0x7ffc0e3bf577, 1) = -1 EAGAIN (Resource temporarily unavailable)
waitid(P_ALL, 0, {}, WNOHANG|WEXITED|WSTOPPED|WCONTINUED, NULL) = 0
select(48, [3 5 6 7 8 9 11 12 13 15 18 19 20 22 23 26 27 29 32 34 35 37 39 41 43 44 45 47], [], [7 8 9 11 12 15 19], NULL^Cstrace: Process 1339 detached
<detached ...>
事前準備
検証用データの作成
検索用情報を持つテーブル foo と検索情報に紐づくテキスト情報を持つ bar テーブルを作成。内部結合を行った際の処理と、select句内でサブクエリを記述し取得した際の処理をそれぞれトレースします。
用意するデータのイメージは以下の通り
検索用情報テーブル (foo)
| ID1 | ID2 | ID3 | bit1 | bit2 | bit3 |
|---|---|---|---|---|---|
| 1 | 3 | 100 | true | true | true |
| 2 | 5 | 300 | true | true | false |
| ... | ... | ... | ... | ... | ... |
| 10000 | 17 | 500 | false | false | true |
テキスト情報テーブル (bar)
| ID1 | text1 |
|---|---|
| 1 | ふなっしー |
| 2 | くまもん |
| ... | ... |
| 10000 | 素敵坊主 |
今回の検証用SQLで得られる結果（id2 - bit3 は返却対象から外しています）
| ID1 | ID2 | ID3 | bit1 | bit2 | bit3 | text1 |
|---|---|---|---|---|---|---|
| 1 | 3 | 100 | true | true | true | ふなっしー |
| 2 | 5 | 300 | true | true | false | くまもん |
| ... | ... | ... | ... | ... | ... | ... |
| 10000 | 17 | 500 | false | false | true | 素敵坊主 |
-- 検索用情報テーブル CREATE TABLE foo ( id1 int4, id2 int4, id3 int4, id4 int4, bit1 bit(1), bit2 bit(1), bit3 bit(1), bit4 bit(1) ); insert into foo select n as id1, n as id2, n as id3, n as id4, '1'::bit as bit1, '1'::bit as bit2, '1'::bit as bit3, '1'::bit as bit4 from ( SELECT GENERATE_SERIES(1, 10000) as n )x; -- テキスト情報テーブル CREATE TABLE bar ( id1 int4, text1 text ); insert into bar select n as id1, 'hoge'::text as text1 from ( SELECT GENERATE_SERIES(1, 10000) as n )x
strace で プロセスをトレースする準備
straceコマンドでSQL実行中のプロセスをトレースするため、SQLを実行するアプリケーションpgadmin からSQLを実行しPIDを確認します。
$ ps -ax | grep postgres | grep SELECT 28495 ? Rs 10:34 postgres: forcia forcia 10.0.2.2(64164) SELECT
ここでは PID 28495が得られたので、そのプロセスを追跡していくこととします。
同一の処理結果となる ２つのSQLを比較
SQL1.内部結合で取得
select
b.text1
from foo a
inner join bar b using(id1);
-- explain analyze
"Hash Join (cost=319.00..506.12 rows=5184 width=32) (actual time=4.277..9.833 rows=10000 loops=1)"
" Hash Cond: (b.id1 = a.id1)"
" -> Seq Scan on bar b (cost=0.00..115.84 rows=5184 width=36) (actual time=0.013..1.626 rows=10000 loops=1)"
" -> Hash (cost=194.00..194.00 rows=10000 width=4) (actual time=4.253..4.253 rows=10000 loops=1)"
" Buckets: 16384 Batches: 1 Memory Usage: 480kB"
" -> Seq Scan on foo a (cost=0.00..194.00 rows=10000 width=4) (actual time=0.005..2.116 rows=10000 loops=1)"
"Planning time: 0.086 ms"
"Execution time: 10.485 ms"
SQL2.セレクト句にサブクエリを記述
select
(select text1 from bar b where b.id1 = a.id1) as text1
from foo a;
-- explain analyze
"Seq Scan on foo a (cost=0.00..1890194.00 rows=10000 width=32) (actual time=1.801..19942.947 rows=10000 loops=1)"
" SubPlan 1"
" -> Seq Scan on bar b (cost=0.00..189.00 rows=1 width=5) (actual time=1.015..1.990 rows=1 loops=10000)"
" Filter: (id1 = a.id1)"
" Rows Removed by Filter: 9999"
"Planning time: 0.078 ms"
"Execution time: 19946.171 ms"
SQL1,SQL2それぞれの処理速度(Execution time)を見ると、SQL1の10.485ms に対して、SQL2は19946.171 msで、SQL2はSQL1よりも約2000倍遅い。
SQL1、SQL2の実行プランを比較すると、bar テーブル の処理はどちらもシーケンシャルスキャンですが、rows/loops の処理方法に違いがあることがわかります。
SQL1: Seq Scan on bar b (cost=0.00..115.84 rows=5184 width=36) (actual time=0.013..1.626 rows=10000 loops=1)
SQL2: Seq Scan on bar b (cost=0.00..189.00 rows=1 width=5) (actual time=1.015..1.990 rows=1 loops=10000)
この時のSQL1,SQL2のシステムコールを眺めてみよう
SQL1 のシステムコールの統計情報
$ strace -p 28495 -c % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 3 write 0.00 0.000000 0 10 lseek 0.00 0.000000 0 7 brk 0.00 0.000000 0 4 sendto 0.00 0.000000 0 6 3 recvfrom 0.00 0.000000 0 3 epoll_wait ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 33 3 total
SQL2 のシステムコールの統計情報
$ strace -p 28495 -c % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 3 write 0.00 0.000000 0 10009 lseek 0.00 0.000000 0 4 sendto 0.00 0.000000 0 6 3 recvfrom 0.00 0.000000 0 3 epoll_wait ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 10025 3 total
上記より、SQL1のlseekが10回呼ばれているのに対して、SQL2の lseek は10009回呼ばれていることがわかります。
lseek はファイルの読み書きを行うためにポインタを移動する際に呼ばれるシステムコール。
先のexplain analyzeの結果を合わせてみると、SQL1 SQL2で実行したシーケンシャルスキャンの処理の違いは以下のように推測することができます。
- SQL1: foo テーブルに対し、bar テーブルを１回のHDDアクセスで10000レコード取得。それを1回のループで処理。
- SQL2:foo テーブルに対し、bar テーブルを１レコードずつHDDへアクセスしてデータを取得。それを10000回繰り返し処理。
つまり、SQL2の様に select 句でサブクエリを記述するとそのレコード毎に評価されることがシステムコールからも読み取れることがわかりました。
SQL2のシステムコールを減らしてみる
冒頭のシステムコールの説明で「CPU・メモリ上の計算であればシステムコールは発生しない」と書きました。
先のSQL2では、10000レコードの処理を行う際に1レコードずつファイルディスクリプタへアクセスをしていたが、メモリに乗っていればシステムコールは発生しないはず。検索情報テーブル(foo)とテキスト情報テーブル(bar)が結合するカラムにそれぞれインデックスを作成し試してみます。
create index _idx_foo on foo (id1); create index _idx_bar on bar (id1);
SQL3 (SQL1 with index)
"Hash Join (cost=289.00..620.50 rows=10000 width=5) (actual time=5.295..10.963 rows=10000 loops=1)" " Hash Cond: (a.id1 = b.id1)" " -> Seq Scan on foo a (cost=0.00..194.00 rows=10000 width=4) (actual time=0.008..1.429 rows=10000 loops=1)" " -> Hash (cost=164.00..164.00 rows=10000 width=9) (actual time=5.272..5.272 rows=10000 loops=1)" " Buckets: 16384 Batches: 1 Memory Usage: 558kB" " -> Seq Scan on bar b (cost=0.00..164.00 rows=10000 width=9) (actual time=0.007..2.447 rows=10000 loops=1)" "Planning time: 0.196 ms" "Execution time: 11.648 ms"
SQL4 (SQL2 with index)
"Seq Scan on foo a (cost=0.00..83219.00 rows=10000 width=32) (actual time=0.022..61.605 rows=10000 loops=1)" " SubPlan 1" " -> Index Scan using _idx_bar on bar b (cost=0.29..8.30 rows=1 width=5) (actual time=0.004..0.005 rows=1 loops=10000)" " Index Cond: (id1 = a.id1)" "Planning time: 0.068 ms" "Execution time: 63.099 ms"
実行プランを Explain analze で SQL4(SQL2 with index) の処理速度を確認すると 63.099 ms と、SQL2の 19946.171 ms から大幅に改善したのがわかります。では、この時のシステムコールを確認してみましょう。
SQL3 (SQL1 with index)のシステムコールの統計情報
$ strace -p 28495 -c % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 3 write 0.00 0.000000 0 12 lseek 0.00 0.000000 0 4 sendto 0.00 0.000000 0 6 3 recvfrom 0.00 0.000000 0 3 epoll_wait ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 28 3 total
SQL4 (SQL2 with index)のシステムコールの統計情報
$ strace -p 28495 -c % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 3 write 0.00 0.000000 0 11 lseek 0.00 0.000000 0 4 sendto 0.00 0.000000 0 6 3 recvfrom 0.00 0.000000 0 3 epoll_wait ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 27 3 total
SQL4のシステムコールがSQL1と同等レベルまで改善しているのがわかります。
SQL2が遅かった原因 is 何？
処理速度が遅かったSQL2にインデックスを張ったら性能が改善しました。ある意味当然の結果ではありますが、ここではシステムコールの発生が抑えられていることが確認できています。
SQL2のボトルネックを考えた時、シーケンシャルスキャンのロジックがそもそも遅いのか、それとも、ファイルディスクリプタへのアクセスが頻発することによるI/Oのオーバーヘッドが遅いのか、どちらなのでしょうか。
例えば、後者がボトルネックであれば、HDDをSSDに変えればアプリケーションの修正ではなくH/Wのレイヤーで性能を改善することができる、という検討もできます。
これを切り分けるために、SQL2の実行プランかつシステムコールの発生を抑えるSQLを組み立てて確認してみます。
SQLの準備
ここでは with句を使用して試してみます。with句で作成したデータは同一セッション内でメモリ内保存され後続処理で再利用する特性があり、この特性を生かして、予めメモリ内で展開したデータを元にSQL2と同等の処理が実行するSQL5を作成してみます。
SQL5 (with句使用)
with baz as ( select id1, text1 from bar ) ,fug as ( select id1 from foo ) select (select text1 from baz b where b.id1 = a.id1) as text1 from fug a; -- explain analyze "CTE Scan on fug a (cost=339.00..2250539.00 rows=10000 width=32) (actual time=4.304..36537.863 rows=10000 loops=1)" " CTE baz" " -> Seq Scan on bar (cost=0.00..155.00 rows=10000 width=9) (actual time=0.015..1.356 rows=10000 loops=1)" " CTE fug" " -> Seq Scan on foo (cost=0.00..184.00 rows=10000 width=4) (actual time=0.020..13.423 rows=10000 loops=1)" " SubPlan 3" " -> CTE Scan on baz b (cost=0.00..225.00 rows=50 width=32) (actual time=1.833..3.648 rows=1 loops=10000)" " Filter: (id1 = a.id1)" " Rows Removed by Filter: 9999" "Planning time: 0.078 ms" "Execution time: 36543.400 ms"
SQL5 のシステムコールの統計情報
strace -p 28495 -c % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 3 write 0.00 0.000000 0 10 lseek 0.00 0.000000 0 3 brk 0.00 0.000000 0 4 sendto 0.00 0.000000 0 6 3 recvfrom 0.00 0.000000 0 3 epoll_wait ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 29 3 total
システムコールの回数だけ見ると、SQL1、SQL3、SQL4と遜色ないレベルにありますが、SQL2のexplain analyzeの結果と比較すると処理速度が悪化しています。
このことから、このSQLにおけるボトルネックはファイルディスクリプタへのアクセスが頻発していることではなく、実行プランがシーケンシャルスキャンになっており、CPUの演算処理で時間がかかっていることだと判断できます。
例えば、SQL2がボトルネックになった場合、SSDを導入しても改善効果は乏しい、ということが推測できると思います。
- CTE Scan on fug a (cost=339.00..2250539.00 rows=10000 width=32) (**actual time=4.304..36537.863** rows=10000 loops=1)
さいごに
SQLを通してシステムトレースを眺めてみましが、ファイル・ネットソケットのopen/closeが適切に行われていない、ブラックボックス化されたライブラリ動作が遅かった、などを調査する手法としてシステムコールをトレースするのは有効だったりします。
触ったことが無い方、調査等で困った時にふと思い出して頂ければ幸いです。
澁谷 亮
2012年に中途でフォルシアに入社。
