[pgsql-jp: 42006] Re: SELECT時のWALの大量出力について

[Masahiko Sawada]

澤田と申します。

2019年2月19日(火) 21:14 板山 <itayama-k ＠ evoltech.co.jp>:
>
> 喜田様
> ご連絡ありがとうございます、板山です。
>
>  > wal_log_hints有効時は、SELECTでもWALを吐きます。
>  > チェックポイント後は、初回アクセスされたページの..
>
> はい、存じております。
>
>
> 以下の場合、472,945件分のページが、「初回アクセスされた」に
> 該当することになるように思うのですが..
>
> ・1/16：181,135,541件有り、2回フルスキャン(seq_tup_read)
> ・1/22 12:00：181,608,486件分をWAL出力
>
>
> WALの出力量は、1億8千万件分あるように見受けられますが、
> 全件出力することもあるのでしょうか。

slaveの状態によってはあると思います。
1/17にslaveからmasterを構築しているので、例えば、その時にslave側のテーブルに
hint bitsが立っていない状態であれば、その後のmasterのフルスキャンで
初めてhint bitが立ちテーブル全体分のWALが出力されます。

1/16の 2回フルスキャンはmasterでの実行でしょうか？
また、1/16時点のmasterでもwal_log_hintsはonになっていたでしょうか？
hint bitsの更新は、full page write以外でslaveに反映されなかったと思うので、
slaveでのフルスキャンであったり、1/16時点でmasterがwal_log_hints = offの場合は、
slaveのhint bitは立っていない状態だと思います。

以上です。

>
>
>
> On 2019/02/19 20:36, 喜田 紘介 wrote:
> > 喜田と申します。
> >
> > メール冒頭にある「出力されないはずのWAL」とは、
> > この期間において「データの増／減／更新はありません。」だからでしょうか？
> >
> >
> > ★印で強調いただいていますので気になられているのだと思いますが、
> > wal_log_hints有効時は、SELECTでもWALを吐きます。
> > チェックポイント後は、、初回アクセスされたページの
> > イメージを丸ごとWALに吐く（full_page_writes）ので、
> > 何度か実施されたというフルスキャンでWALを吐いたのだと思います。
> >
> >
> > なにか見直すとすれば以下でしょうか。
> >
> > ・WALはそれだけ生成されるものとしてWAL領域を増やす（併せてチェックポイントを頻発させないためにmax_wal_sizeも増やす）
> >
> > ・pg_rewindのためのwal_log_hintsだと思うが、いざという時に原因不明で失敗するならwal_log_hintsを無効にする
> >
> > ・wal_compressionを有効にしてWALサイズを小さくする（微々たる効果かもしれませんが）
> >
> > 以上です。
> >
> >
> > 2019/02/19 19:10、板山 <itayama-k ＠ evoltech.co.jp>のメール:
> >
> >> 板山と申します。
> >>
> >> PostgreSQL9.6.9を利用しており、
> >> ストリーミングレプリケーションでクラスタを構成しております。
> >>
> >> 出力されない筈のWALが大量に出力され、アーカイブ領域がパンクしました。
> >> 原因不明のため、対策が分からず、困っております。
> >>
> >>
> >> 状況は以下になります。
> >>
> >> [参考]富士通 Systemwalker Service Quality Coordinator（SQC）という製品
> >>　 を導入しており、5分毎にPG_STAT_USER_TABLESとPG_STATIO_USER_TABLES等
> >>　 の情報を取得し、出力は10分毎に集計されます。
> >>　 時刻はUTCです。
> >>
> >> history_901テーブルが有り、履歴テーブルでパーティション化しております。
> >> 2019年1月に他テーブルで登録したデータを履歴として登録します。
> >> 5年保持し、5年経つまでは insert/selectしか行いません。
> >>
> >> 1/16に181,135,541件有り、indexが無いため 2回フルスキャン(seq_tup_read)
> >> しています。
> >> 1/17に非機能テストを実施し、1号機から2号機にPrimaryがswitchしました。
> >> この後、1号機をPrimaryに戻すため、2号機からpg_rewindを実行しましたが
> >> エラーになり、pg_basebackupで全コピーしました。
> >>
> >> 1/17 6:00に181,144,152件あり、1/18 5:10～7:30のみ、
> >> SQCで情報を取得できていませんが、上記2h20mの後、
> >> データの増／減／更新はありません。
> >>
> >> 1/22 12:00に「explain analyze select ～ from history_901」を実施し、
> >> 181,608,486件をseq_tup_readしました。
> >> PG_STATIO_USER_TABLESは、以下になっています。(約28.3GB)
> >> heap_blks_read：3,707,458
> >> heap_blks_hit ：　　　 35
> >>
> >> PostgreSQLのログには「checkpoint complete」が68行出力され、
> >> 以下の数値を合計すると、28.3GBになります。
> >> removed ：　754
> >> recycled：1,059
> >> 合計　　：1,813　→28.3GB
> >>
> >> これは、1億8千万件 全件をWALに出力していると思います。
> >> 全件WALに出力するのは、仕様通りだと あり得ないと思っております。
> >>
> >> 全件UPDATEしていれば可能性があると思いますが、
> >> PG_STAT_USER_TABLESは、以下になっています。
> >> last_autovacuum ：現在まで全てNULL
> >> last_autoanalyze：2019/1/15 6:33 [*1]
> >> [*1]1/17に2号機からコピーしたため、1/17以降は全てNULL
> >>
> >>
> >> postgresql.confの主なパラメータは、以下になります。
> >> wal_level = replica
> >> #fsync = on
> >> #synchronous_commit = on
> >> #wal_sync_method = fsync
> >> #full_page_writes = on
> >> wal_log_hints = on　　　　　★
> >> checkpoint_timeout = 30min
> >> #max_wal_size = 1GB
> >> #min_wal_size = 80MB
> >> checkpoint_completion_target = 0.9
> >> synchronous_standby_names = '相手サーバ名'
> >> log_min_duration_statement = 15s
> >> #autovacuum = on
> >> #autovacuum_vacuum_threshold = 50
> >> #autovacuum_analyze_threshold = 50
> >> #autovacuum_vacuum_scale_factor = 0.2
> >> #autovacuum_analyze_scale_factor = 0.1
> >>
> >>
> >> なぜ 28GB（全件）もWALに出力されたのでしょうか。
> >> よろしくお願い致します。


Masahiko Sawada