ぱと隊長日誌

ブログ運用もエンジニアとしての生き方も模索中

pg_rman によるバックアップで、バックアップ対象ファイルのタイムスタンプがシステム時刻より進んでいるとエラーとなる

事象

pg_rman によるバックアップ中に、以下のエラーが表示されて、処理が中断される。

$ pg_rman backup --backup-mode=full --with-serverlog --progress
INFO: copying database files
Processed 1183 of 1183 files, skipped 0
INFO: copying archived WAL files
FATAL: cannot take a backupipped 0
DETAIL: There is a file with future timestamp from system time.
Current system time may be rewound.
HINT: The file is /mnt/data/pgsql/archivedir/000000020000000000000006.
If this is a database file, please retry with the full backup mode.
If this is a server log or archived WAL file, change the timestamp.

再現環境

CentOS 7(PostgreSQLサーバ、NFSサーバ共に)
PostgreSQL 9.6
pg_rman-1.3.4-pg96

NFSサーバをWALアーカイブ先に指定しています。

環境やコマンドによっては、先述のエラーメッセージが異なるかもしれません。

原因

pg_rman によるバックアップ実行時、pg_rman を実行したマシンのシステム時刻と、バックアップ対象ファイルのタイムスタンプを比較し、ファイルのタイムスタンプが進んでいる場合にエラーとなるためです。

pg_rman のバックアップ対象は以下のファイル群です。

  • データベース($PGDATA、データディレクトリ)
  • アーカイブWAL(archive_command 構成パラメータの指定先)
  • サーバログ(log_directory 構成パラメータの指定先)

このうち、アーカイブWALファイルは本エラーの対象となりやすいです。NFSサーバをWALアーカイブ先としている場合、DBサーバとNFSサーバの時刻ずれによって、本エラーの発生する可能性があるからです。

このことは pg_rman のマニュアルにも記載されています。

WALアーカイブ先が別サーバ上に存在する場合、DBサーバよりもシステム時刻が進んでいるとバックアップ/リカバリに失敗します。

pg_rman

解決策

DBサーバとNFSサーバで同じNTPサーバを基準に時刻同期します。同じNTPサーバを基準にすることで、時刻ずれをなるべく抑えます。それでもサーバ間の時刻ずれがわずかに生じますが、今回の問題に関してはほぼ影響ないと思われます。

参考

回避パッチの提案

本問題に関連して、サーバ間の時刻ずれを考慮し、ファイルのタイムスタンプの比較に余裕時間を加えてはどうか、との提案が出ていました。
Error on Backup into a network filesystem.
ただ、この提案に対しては反応がないようです。

私としては、このパッチが受け入れられることはないように思います。なぜなら、安全・確実なバックアップを行うために取り入れた仕組みを迂回することになるためです。

PostgreSQL実行計画のハッシュノードに出力されるバケット数とバッチ数の解説

目的

PostgreSQLの実行計画のハッシュノード(Hash)に出力されるバケット数(Buckets)とバッチ数(Batches)について解説を行います。また、バッチ数とパフォーマンスの関係についても触れます。

このテーマについて Pat Shaughnessy さんが英語の解説記事を公開しています(以下リンク参照)。本エントリではこの解説記事をベースに、補足を入れながらポイントをまとめます。詳細については解説記事及びエントリ中の引用記事を参照ください。

A Look at How Postgres Executes a Tiny Join - Pat Shaughnessy
Is Your Postgres Query Starved for Memory? - Pat Shaughnessy

前提

本エントリではハッシュ結合に関する基本的な解説を省いています。もし、本エントリを一読して理解し辛い点があれば、(a)先述の Pat Shaughnessy さんの記事を読む、(b)書籍「データベースパフォーマンスアップの教科書」の"6.3.4 ハッシュ (Hash) ジョイン"を読む、のいずれかをお勧めします。

データベースパフォーマンスアップの教科書 基本原理編

データベースパフォーマンスアップの教科書 基本原理編

Pat Shaughnessy さんの記事には対象としたPostgreSQLのバージョンの記載がありません。そこで、PostgreSQLのリリース日と記事の日付からPostgreSQL 9.4がベースになっていると推測し、本エントリでもこれに倣います。

公式ドキュメントの説明

PostgreSQLの公式ドキュメントでは実行計画のハッシュノードとバケット数・バッチ数について以下の説明を行っています。

場合によっては、EXPLAIN ANALYZEは計画ノードの実行時間と行数以上の実行統計情報をさらに表示します。 例えば、ソートとハッシュノードでは以下のような追加情報を提供します。

EXPLAIN ANALYZE SELECT *
FROM tenk1 t1, tenk2 t2
WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2 ORDER BY t1.fivethous;

                                                                 QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=717.34..717.59 rows=101 width=488) (actual time=7.761..7.774 rows=100 loops=1)
   Sort Key: t1.fivethous
   Sort Method: quicksort  Memory: 77kB
   ->  Hash Join  (cost=230.47..713.98 rows=101 width=488) (actual time=0.711..7.427 rows=100 loops=1)
         Hash Cond: (t2.unique2 = t1.unique2)
         ->  Seq Scan on tenk2 t2  (cost=0.00..445.00 rows=10000 width=244) (actual time=0.007..2.583 rows=10000 loops=1)
         ->  Hash  (cost=229.20..229.20 rows=101 width=244) (actual time=0.659..0.659 rows=100 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 28kB
               ->  Bitmap Heap Scan on tenk1 t1  (cost=5.07..229.20 rows=101 width=244) (actual time=0.080..0.526 rows=100 loops=1)
                     Recheck Cond: (unique1 < 100)
                     ->  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0) (actual time=0.049..0.049 rows=100 loops=1)
                           Index Cond: (unique1 < 100)
 Planning time: 0.194 ms
 Execution time: 8.008 ms

ソートノードは使用されるソート方式(具体的にはソートがメモリ内かディスク上か)および必要なメモリまたはディスクの容量を表示します。 ハッシュノードでは、ハッシュバケット数とバッチ数、ハッシュテーブルで使用されるメモリのピーク容量が表示されます。 (バッチ数が1を超える場合、同時にディスクの使用容量も含まれますが、表示はされません。)

EXPLAINの利用

以降の章で、ハッシュノードとバケット数・バッチ数について、より詳しい解説を行います。

用語解説

ハッシュノード (Hash)

Hash Join の実行に先立ち、結合する一方の表の結合キーをハッシュ化してハッシュテーブルを作る必要があります。このハッシュテーブル生成処理が実行計画にハッシュノード(Hash)として出力されます。

バケット数 (Buckets)

ハッシュテーブルはバケットという単位で区切られます。どのバケットに格納されるかは結合キーのハッシュ値によって決まります。
各バケットは linked list 形式で複数のハッシュ値を格納できます。

結合キーのハッシュ値と結合後の処理で利用する列の値がバケットに格納されます。こうすることで、結合後の処理のために結合キーの示す該当レコードを読み直すことなく、ハッシュテーブルだけで結合処理を行うことができます。

バケット数は以下の条件を満たすように決まります。

  • バケットの linked list の長さが10を超えないこと
  • バケット数が2の累乗となること
  • バケット数が1024以上となること

バケット数を2の累乗かつ1024以上としているのはPostgreSQLの設計上の理由からです。詳細は解説記事を参照ください(リンク再掲)。
A Look at How Postgres Executes a Tiny Join - Pat Shaughnessy

バッチ数 (Batches)

PostgreSQLでは Hash Join のアルゴリズムとして Hybrid Hash Join を採用しています。これにより、利用可能なメモリサイズを超過するハッシュ結合処理であっても、実行できるようになります。

ハッシュ結合処理のハッシュテーブル操作に利用可能なメモリサイズはpostgresql.confのwork_memとして設定されています。PostgreSQL 9.4のwork_memのデフォルト値は4MBです。

ハッシュテーブル操作に必要なメモリサイズがwork_memのサイズを超過するとき、ハッシュテーブルをwork_memのサイズで分割します。この分割したハッシュテーブルをバッチと呼びます。バッチ数は2の累乗となります。例えば、ハッシュテーブルのサイズが8MB、work_memが4MBであれば、バッチ数が2となります。

バッチ数が1を超えるとき、ハッシュテーブル出力で2つ目以降のバッチをディスクに書き出します。そして、ハッシュ結合処理でメモリ上の1つ目のバッチに対する処理が終わると、残りのバッチが順次メモリへ読み戻され、処理を継続します。

バッチ数に着目したパフォーマンス改善

バッチ数が1を超えると、ハッシュテーブル操作でバッチのディスクI/Oが発生し、メモリ上で全てを処理する場合と比べてパフォーマンスが劣化します。この問題への対処方法を説明します。

work_mem設定値の見直し

work_memの設定値を大きくすることでバッチ数を減らすことができます。元々、work_memのデフォルト値は小さく設定されているため、適切に設定することが重要です。

work_memは同時に実行する全ての操作で利用可能な合計メモリサイズの最大値ではなく、各操作で利用するメモリサイズの最大値であることに注意してください。このため、実際のメモリサイズはwork_memのサイズの数倍利用されることがあります。このことがPostgreSQLのドキュメントに記載されています。

work_mem (integer)
一時ディスクファイルに書き込む前に、内部並べ替えとハッシュテーブル操作が使用するメモリ容量を指定します。 デフォルト値は4メガバイト(4MB)です。 複雑な問い合わせの場合、いくつかの並び替えもしくはハッシュ操作が並行して実行されることに注意してください。 それぞれの操作による一時メモリへの書き込み開始の前に、この値が指定するのと同じメモリ容量の使用をそれらの操作に許容します。さらに、いくつかの実行中のセッションはこれらの動作を同時に行います。したがって、使用されるメモリの合計は、work_memの数倍になります。値を選択する時には、この事実に留意することが必要です。並び替え操作はORDER BY、DISTINCT、およびマージ結合に対して使われます。ハッシュテーブルはハッシュ結合、ハッシュに基づいた集約、およびIN副問い合わせのハッシュに基づいた処理で使用されます。

資源の消費

クエリの見直し

バケットには(a)結合キーのハッシュ値と(b)結合後の処理で利用する列の値が一緒に格納されます。(b)のデータ量を減らすことができれば、ハッシュテーブルが小さくなり、結果としてバッチ数を減らすことができます。

この具体例を挙げた記事があります。
LANGTYPE{ORMs}における一時オブジェクト : 要素の一部分を読み出す
この記事ではハッシュテーブルを小さくする方法として以下の2つを挙げています。

  • ハッシュ化する前に条件で絞り込んでレコード数を減らす
  • 結合後の処理に不要な選択列を含めない

詳細は記事の具体例を参照ください。

補足

skew table

今回の主題から少し外れますが、パフォーマンスチューニングの調査で本エントリにたどり着いた方向けに補足します。

Pat Shaughnessy さんの記事に以下のNoteがあります。

Note: Postgres actually holds a second hash table in memory, called the skew table. For simplicity I’m not showing this in the diagram. This special hash table is an optimization to handle hash values that occur frequently in the data. Postgres saves the skew table inside the same 4MB working memory buffer, so the primary hash table actually has a bit less than 4MB available to it.

Is Your Postgres Query Starved for Memory? - Pat Shaughnessy

この skew table について解説している記事があります。
モダンハッシュ結合 - 象と戯れ - postgresqlグループ
この記事では統計情報のMCV(最頻値)とハッシュ結合の関係について説明しており、サイズの大きなテーブルのハッシュ結合前にANALYZEが行われていないとパフォーマンスに影響する可能性を触れています。

まとめ

PostgreSQLの実行計画にハッシュノードが出力されたときはバッチ数に着目し、バッチ数が1を超えている場合はwork_memの設定やクエリを見直しましょう。

更新情報

2017/05/30

  • 前提の「データベースパフォーマンスアップの教科書」の紹介に参照章を追記しました。

JPEGファイルを Windows 10 のエクスプローラで開けなくなった事象と解決までの一例

事象

JPEGの画像ファイルを Windows 10 のエクスプローラからダブルクリックで開くことができなくなった。通常であれば「フォト」アプリが起動するところ、ダイアログで「レジストリに対する値が無効です」と表示された。

なお、同じマシンでも管理者ユーザでは画像を上記手順で開くことができた。今回の事象が発生したのは一般ユーザのみだった。

また、事象が発生したユーザのスタートメニューのアプリ一覧で「フォト」アプリの名称表示が壊れていた。そのアプリ名の表示イメージとしては"{24fw23r8sdfwq3qrq2fwq23}-{3qrq2fwq234t..."のようなものだった。

発生環境

  • Windows10 Pro 64bit版
    • バージョン 1703
    • OSビルド 15063.296

事象発生のタイミングを考えると、Creators Update 適用後におかしくなった可能性がある。

管理者ユーザと一般ユーザがいて、どちらもログインにMicrosoftアカウントを利用している。

復旧手順

ピクチャ ライブラリの場所を再設定

事象の発生している一般ユーザで以下の操作を行った。
この作業だけでは復旧しなかったが、後続の作業との組み合わせで復旧できた可能性がある。

1. スタート ボタン右クリック > [ファイル名を指定して実行] > 「shell:Libraries」と入力して [OK]

2. エクスプローラーでライブラリの一覧が表示されたら、[ピクチャ] を右クリック > [プロパティ]

3. [ピクチャのプロパティ] が表示されたら、[ライブラリの場所] 欄に含まれるものを全て削除

4. [ライブラリの場所] が空欄になったら、[既定値に戻す] > [OK]
※ ユーザーのピクチャ フォルダー (C:\ユーザー\ユーザー名\ピクチャ) のみ追加されます

Windows 10 フォトアプリが起動できない、起動してもすぐに閉じてしまう、強制終了になる。 - マイクロソフト コミュニティ

「フォト」アプリを起動する

まず、タスクバーの検索ボックスで"photos"を検索する。その検索結果から「フォト」アプリを起動し、正常に表示されることを確認する。
これ以降、JPEGの画像ファイルをエクスプローラからダブルクリックして「フォト」アプリで開けるようになった。

「事象」に記載の通り、対象のユーザでは「フォト」アプリの名称が壊れていたため、アイコンから判別してアプリを起動した。「フォト」アプリを起動できた後はアプリ名も正しく戻った。

検索方法と「フォト」アプリのアイコンは以下のイメージを参照のこと。
f:id:pato_taityo:20170520195951p:plain

注意事項

問題がすでに解決しているため、今回のエントリは記憶に基づいて再現しており、エラー文言や操作手順の確認・検証ができていないことをご容赦ください。