こんにちは。技術部の髙岡です。 前回のブログで、Zabbixのダッシュボードのeventsが遅くて表示されないことがあって、その原因は、実行されるクエリーが遅いためであることと、クエリーを早くする方法を結論だけ紹介しました。
遅いクエリー
SELECT DISTINCT e.eventid,e.clock,e.ns,e.objectid,e.acknowledged,er1.r_eventid
FROM events e LEFT JOIN event_recovery er1 ON er1.eventid=e.eventid
WHERE e.source='0' AND e.object='0' AND e.objectid='16821' AND e.eventid='4020491' AND e.value='1'
ORDER BY e.eventid DESC
LIMIT 20
;
今回は、その結論を導き出したプロセスを順を追って説明したいと思います。長々と説明する前に、これから説明するクエリーの課題と解決策のサマリーを書いておきます。
| 1. ２つのテーブルを結合する前のeventsテーブルの行絞り込みがインデックススキャン＋フィルタ処理で実行されていた →インデックスを追加して時間のかかるフィルタ処理を排除した 2. パラレルクエリーのワーカー毎の処理に時間がかかっていた →ワーカー数を増やしてワーカー当たりの処理時間を短縮した |
PostgreSQLのバージョンは11を使っています。
調査・分析結果
スロークエリーの出力
何はともあれ、クエリーが遅いと思った時は、実行計画の確認です。 そのための準備として、スロークエリーがログに出力されるように、PostgreSQLの設定を変更します。 以下は、postgresql.confのパラメータで、3秒以上かかるクエリーを出力する設定です。
| log_min_duration_statement = 3s |
ログファイルに出力されたスロークエリー
2019-07-24 20:04:42.981 JST [4086] LOG: 期間: 10003.652 ミリ秒 文: SELECT DISTINCT e.eventid,e.clock,e.ns,e.objectid,e.acknowledged,er1.r_eventid
FROM events e LEFT JOIN event_recovery er1 ON er1.eventid=e.eventid
WHERE e.source='0' AND e.object='0' AND e.objectid='16821' AND e.eventid='4020491' AND e.value='1'
ORDER BY e.eventid DESC
LIMIT 20
;
「期間: 10003.652 ミリ秒」と書いてあるので、10秒近くかかっていることがわかります。
テーブルとインデックスの確認
「events」テーブルと「event_recovery」テーブルの定義を確認してみます。どんなインデックスが張ってあるのかに注目します。
zabbix=# \d events;
テーブル "public.events"
列 | 型 | 照合順序 | Null 値を許容 | デフォルト
--------------+-------------------------+----------+---------------+-----------------------
eventid | bigint | | not null |
source | integer | | not null | 0
object | integer | | not null | 0
objectid | bigint | | not null | '0'::bigint
clock | integer | | not null | 0
value | integer | | not null | 0
acknowledged | integer | | not null | 0
ns | integer | | not null | 0
name | character varying(2048) | | not null | ''::character varying
severity | integer | | not null | 0
インデックス:
"events_pkey" PRIMARY KEY, btree (eventid)
"events_1" btree (source, object, objectid, clock)
"events_2" btree (source, object, clock)
～以下省略～
eventidへの主キー以外に、「events_1」と「events_2」のインデックスが張ってあることがわかります。
zabbix=# \d event_recovery
テーブル "public.event_recovery"
列 | 型 | 照合順序 | Null 値を許容 | デフォルト
---------------+--------+----------+---------------+------------
eventid | bigint | | not null |
r_eventid | bigint | | not null |
c_eventid | bigint | | |
correlationid | bigint | | |
userid | bigint | | |
インデックス:
"event_recovery_pkey" PRIMARY KEY, btree (eventid)
"event_recovery_1" btree (r_eventid)
"event_recovery_2" btree (c_eventid)
～以下省略～
eventidへの主キー以外に、「event_recovery_1」と「event_recovery_2」のインデックスが張ってあることがわかります。
スロークエリーの実行計画の確認
次に、explainコマンドをanalyzeオプション付きで実行し、このクエリーの実行計画を確認します。
zabbix=# explain analyze SELECT DISTINCT e.eventid,e.clock,e.ns,e.objectid,e.acknowledged,er1.r_eventid
FROM events e LEFT JOIN event_recovery er1 ON er1.eventid=e.eventid
WHERE e.source='0' AND e.object='0' AND e.objectid='16821' AND e.eventid='4020491' AND e.value='1'
ORDER BY e.eventid DESC
LIMIT 20
;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=19770.73..19771.03 rows=20 width=36) (actual time=9678.497..9682.089 rows=20 loops=1)
Unique (cost=19770.73..19801.12 rows=2026 width=36) (actual time=9678.492..9678.505 rows=20 loops=1)
Sort (cost=19770.73..19775.80 rows=2026 width=36) (actual time=9678.490..9678.492 rows=20 loops=1)
Sort Key: e.eventid DESC, e.clock, e.ns, e.acknowledged, er1.r_eventid
Sort Method: quicksort Memory: 206kB
Gather (cost=1000.99..19659.46 rows=2026 width=36) (actual time=38.914..9679.989 rows=2010 loops=1)
Workers Planned: 2
Workers Launched: 2
Nested Loop Left Join (cost=0.99..18456.86 rows=844 width=36) (actual time=33.883..9173.631 rows=670 loops=3)
Parallel Index Scan using events_1 on events e (cost=0.56..11832.07 rows=844 width=28) (actual time=23.447..6306.476 rows=670 loops=3)
Index Cond: ((source = 0) AND (object = 0) AND (objectid = '16821'::bigint))
Filter: ((eventid = '4020491'::bigint) AND (value = 1))
Rows Removed by Filter: 1599
Index Scan using event_recovery_pkey on event_recovery er1 (cost=0.43..7.85 rows=1 width=16) (actual time=4.276..4.276 rows=1 loops=2010)
Index Cond: (eventid = e.eventid)
Planning Time: 163.507 ms
Execution Time: 9682.342 ms
(17 行)
実行計画の見方は、以下の資料が参考になります。
「PostgreSQLクエリ実行の基礎知識 ～Explainを読み解こう～」
性能トラブル改善案
ボトルネックの特定と解決①
上記の実行計画の中で、どの処理が遅くなっているのかを確認するために注目する箇所は、「actual time」です。 実際の処理に要した時間がミリ秒単位で表示されています。実行計画がインデントのようになっている箇所を計画ノードと呼び、インデントの階層が下のノードから順番に処理されます。処理のフローを記載します。
下の階層のノードから順番に「actual time」を見て、処理に時間がかかっているノードを探します。 図では黄色く塗ったノードが遅い処理です。実行計画の18行目に、6秒近くかかっているノードが見つかりました。
| Parallel Index Scan using events_1 on events e (cost=0.56..11832.07 rows=844 width=28) (actual time=23.447..6306.476 rows=670 loops=3) |
実行計画の18行目~21行目にこのノードの処理の詳細が記載されています。
このクエリーは、「events」テーブルと「event_recovery」テーブルをネストループで結合する処理ですが、結合する前に「events」テーブルの中で結合候補となる行をWHERE句の条件で絞り込んでいます。
| WHERE e.source=’0′ AND e.object=’0′ AND e.objectid=’16821′ AND e.eventid=’4020491′ AND e.value=’1′ |
実行計画の該当するノードを見てみると、WHERE句の絞り込み処理は大きく２つの処理に分かれていることがわかります。
処理を簡略化して表現した図を記載します。
図中の②、③のフィルタ条件による除外処理はインデックススキャンだけの処理に比べて時間がかかるので、排除したい処理です。実行計画の中に書いてある「Rows Removed by Filter」の1599行をフィルタ条件によって除外しているのです。
そこで、「events_1」インデックスの定義を確認してみます。
| “events_1” btree (source, object, objectid, clock) |
「events_1」インデックスによるスキャンが対象とする列は、source列、object列、objectid列、clock列のみで、eventidとvalueは対象外です。
eventidとvalueがインデックスで定義されていないので、インデックススキャンの後でフィルタ条件による除外処理が実行されているのです。
フィルタ条件による除外処理「Filter」を排除するために、インデックススキャンだけで行を絞り込むことができるよう、eventidとvalueを含めたWHERE句の列が全て盛り込まれたIndexを作成してみます。
zabbix=# create index event_4_add on events (source,object,objectid,eventid,value);
CREATE INDEX
zabbix=# \d events;
テーブル "public.events"
列 | 型 | 照合順序 | Null 値を許容 | デフォルト
--------------+-------------------------+----------+---------------+-----------------------
eventid | bigint | | not null |
source | integer | | not null | 0
object | integer | | not null | 0
objectid | bigint | | not null | '0'::bigint
clock | integer | | not null | 0
value | integer | | not null | 0
acknowledged | integer | | not null | 0
ns | integer | | not null | 0
name | character varying(2048) | | not null | ''::character varying
severity | integer | | not null | 0
インデックス:
"events_pkey" PRIMARY KEY, btree (eventid)
"event_4_add" btree (source, object, objectid, eventid, value)
"events_1" btree (source, object, objectid, clock)
"events_2" btree (source, object, clock)
さて、同じクエリーを実行して早くなるかどうかを確認してみたいところですが、 その前にキャッシュの影響を排除するために、PostgreSQLの再起動とOSキャッシュのクリアを実行します。
$ pg_ctl restart # echo 1 > /proc/sys/vm/drop_caches
余談になりますが、PostgreSQLは、DB自体のキャッシュ領域だけでなく、OSのファイルキャッシュも 積極的に活用するDBなので、2行目のOSキャッシュをクリアするコマンドを実行しています。
同じクエリーを実行してみます。
zabbix=# explain analyze SELECT DISTINCT e.eventid,e.clock,e.ns,e.objectid,e.acknowledged,er1.r_eventid
FROM events e LEFT JOIN event_recovery er1 ON er1.eventid=e.eventid
WHERE e.source='0' AND e.object='0' AND e.objectid='16821' AND e.eventid='4020491' AND e.value='1'
ORDER BY e.eventid DESC
LIMIT 20
;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=11642.51..11642.81 rows=20 width=36) (actual time=9499.548..9499.715 rows=20 loops=1)
Unique (cost=11642.51..11672.90 rows=2026 width=36) (actual time=9499.543..9499.555 rows=20 loops=1)
Sort (cost=11642.51..11647.58 rows=2026 width=36) (actual time=9499.541..9499.543 rows=20 loops=1)
Sort Key: e.eventid DESC, e.clock, e.ns, e.acknowledged, er1.r_eventid
Sort Method: quicksort Memory: 206kB
Gather (cost=1000.99..11531.24 rows=2026 width=36) (actual time=51.282..9497.662 rows=2010 loops=1)
Workers Planned: 2
Workers Launched: 2
Nested Loop Left Join (cost=0.99..10328.64 rows=844 width=36) (actual time=36.832..9081.066 rows=670 loops=3)
Parallel Index Scan Backward using event_4_add on events e (cost=0.56..3703.85 rows=844 width=28) (actual time=20.426..3304.782 rows=670 loops=3)
Index Cond: ((source = 0) AND (object = 0) AND (objectid = '16821'::bigint) AND (eventid = '4020491'::bigint) AND (value = 1))
Index Scan using event_recovery_pkey on event_recovery er1 (cost=0.43..7.85 rows=1 width=16) (actual time=8.617..8.617 rows=1 loops=2010)
Index Cond: (eventid = e.eventid)
Planning Time: 149.209 ms
Execution Time: 9500.031 ms
(15 行)
インデックス追加前は6秒近くかかっていた「events」テーブルの絞り込み処理が、インデックススキャンだけで絞り込むことができるようになった結果、18行目に書いてある通り3秒まで縮まりました。フィルタ条件による絞り込み処理「Filter」も消えました。
ボトルネックの特定と解決②
しかし、後で処理されるノードの中に遅い処理があるため、全体の実行結果は9秒くらいで、残念なことにインデックス追加による対処前と大して変わっていません。
ボトルネックとなっているのは、17行目のNested Loop処理です。「Workers Launched」で指定された2つのワーカープロセスが分担して処理を実行しています。 処理内容をもっと詳しく見てみるために、analayzeコマンドをverbose付きで実行してみました。
zabbix=# explain (analyze,verbose) SELECT DISTINCT e.eventid,e.clock,e.ns,e.objectid,e.acknowledged,er1.r_eventid
FROM events e LEFT JOIN event_recovery er1 ON er1.eventid=e.eventid
WHERE e.source='0' AND e.object='0' AND e.objectid='16821' AND e.eventid='4020491' AND e.value='1'
ORDER BY e.eventid DESC
LIMIT 20
;
~中略~
Gather (cost=1000.99..11531.24 rows=2026 width=36) (actual time=51.868..9671.491 rows=2010 loops=1)
Output: e.eventid, e.clock, e.ns, e.objectid, e.acknowledged, er1.r_eventid
Workers Planned: 2
Workers Launched: 2
Nested Loop Left Join (cost=0.99..10328.64 rows=844 width=36) (actual time=34.739..9363.610 rows=670 loops=3)
Output: e.eventid, e.clock, e.ns, e.objectid, e.acknowledged, er1.r_eventid
Inner Unique: true
Worker 0: actual time=28.219..9192.748 rows=664 loops=1
Worker 1: actual time=25.002..9229.143 rows=664 loops=1
Parallel Index Scan Backward using event_4_add on public.events e (cost=0.56..3703.85 rows=844 width=28) (actual time=20.433..3460.525 rows=670 loops=3)
~以下略~
17、18行目に書いてある通り、各ワーカーの処理が9秒近くかかっているのです。 そうであるならば、もっとたくさんのワーカーに処理を分担してもらいましょう。
postgresql.confのパラメータを変更してワーカー数の上限を上げます。
| max_worker_processes = 20 # (change requires restart) max_parallel_workers_per_gather = 15 # taken from max_parallel_workers max_parallel_workers = 15 # maximum number of max_worker_processes that |
ワーカー毎に物理CPUが一つ必要なので、マシンのCPUの個数を20個に増やします。 次に、SELECT文の実行計画でパラレルクエリーが機能するようにevnetsテーブルとevent_recoveryテーブルのparallel workersの数を指定します。
zabbix=# alter table events set (parallel_workers=15) ; zabbix=# alter table event_recovery set (parallel_workers=15) ;
再び、explainコマンドをanalzyzeとverboseオプション付きで実行して、より詳細な実行計画を確認してみます。
zabbix=# explain (analyze,verbose) SELECT DISTINCT e.eventid,e.clock,e.ns,e.objectid,e.acknowledged,er1.r_eventid
FROM events e LEFT JOIN event_recovery er1 ON er1.eventid=e.eventid
WHERE e.source='0' AND e.object='0' AND e.objectid='16821' AND e.eventid='4020491' AND e.value='1'
ORDER BY e.eventid DESC
LIMIT 20
;
~中略~
Gather (cost=1000.99..5959.01 rows=2026 width=36) (actual time=49.910..3192.122 rows=2010 loops=1)
Output: e.eventid, e.clock, e.ns, e.objectid, e.acknowledged, er1.r_eventid
Workers Planned: 15
Workers Launched: 15
Nested Loop Left Join (cost=0.99..4756.41 rows=135 width=36) (actual time=63.530..2279.423 rows=126 loops=16)
Output: e.eventid, e.clock, e.ns, e.objectid, e.acknowledged, er1.r_eventid
Inner Unique: true
Worker 0: actual time=62.991..1527.919 rows=83 loops=1
Worker 1: actual time=74.020..3131.311 rows=166 loops=1
Worker 2: actual time=99.689..3003.324 rows=166 loops=1
Worker 3: actual time=66.579..2945.754 rows=166 loops=1
Worker 4: actual time=59.772..2482.030 rows=166 loops=1
Worker 5: actual time=30.028..1632.531 rows=83 loops=1
Worker 6: actual time=43.918..1701.187 rows=83 loops=1
Worker 7: actual time=96.524..2851.142 rows=163 loops=1
Worker 8: actual time=67.309..2976.407 rows=166 loops=1
Worker 9: actual time=43.191..1710.439 rows=83 loops=1
Worker 10: actual time=63.170..2956.958 rows=166 loops=1
Worker 11: actual time=99.215..2959.693 rows=166 loops=1
Worker 12: actual time=48.824..1677.165 rows=83 loops=1
Worker 13: actual time=26.310..1683.975 rows=83 loops=1
Worker 14: actual time=86.172..1525.894 rows=83 loops=1
Parallel Index Scan Backward using event_4_add on public.events e (cost=0.56..3696.76 rows=135 width=28) (actual time=47.051..816.172 rows=126 loops=16)
~以下略~
ワーカーが15個起動し、最も遅いワーカーでも3秒まで縮めることができました。以降のノードの処理時間はミリ秒レベルで遅い処理となっていませんので、クエリー全体の実行時間を3秒近くまで縮めることができました。
この間にvmstatを実行するとprocのb列の値が15、16となり、ディスクI/O待ちとなるワーカーが増えてしまいました。これ以上ワーカーを増やしても実行時間を縮める効果は少ないと思われます。
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 0 0 2568 1526316 0 183276 0 0 0 0 227 172 0 0 100 0 0 2 15 2568 1495312 0 194956 0 0 5512 168 2094 1409 0 1 89 10 0 0 16 2568 1450544 0 239740 0 0 22776 0 7451 5635 0 1 44 55 0 0 8 2568 1426444 0 270056 0 0 15280 0 6551 4724 0 0 59 41 0 0 0 2568 1416708 0 285988 0 0 9156 0 5095 3556 0 0 76 24 0
高性能のディスクに変更すれば、ディスクI/O待ちが減ってもっと早くなるのではないでしょうか。
所感
・パラレルクエリーは、PostgreSQLバージョン9.6以降で実装された機能です。個人的には、「困った時はパラレルクエリーで」と思うくらい、性能面では頼りになる機能だと思っています。諸事情によりRHEL7の同梱パッケージのPostgreSQL 9.2を使うことが多いのですが、このバージョンではパラレルクエリーが使えないのが残念です。
・Zabbix用のDBとして、特に理由がなければMariaDB、MySQLを選ぶことが多いと思いますが、監視データが増えてしまった時の性能トラブル時の対応策の選択肢を考慮すると、PostgreSQLの方が個人的には頼もしいと思っています。Zabbix監視用のDBに限らず、DBを使うシステム全般に言える話しですが。。例えば、MariaDB、MySQLは、テーブル毎に張ることができるインデックスは一つだけですし、パラレルクエリー機能も有りません。今回のような対策は、MariaDB、MySQLで実施することができないのです。
