Go to Qiita Advent Calendar 2024 Top
LoginSignup
1
2

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 1 year has passed since last update.

@megasys1968

pg_auto_failoverによるPostgreSQLサーバの冗長構成をさわってみた

Posted at

PostgreSQLサーバの冗長構成を検討することになりました。

AWSなどのクラウドサービスで運用するなら、そのようなPaaSが提供されているので、ほぼ、それ一択なんでしょうが、今のところVPSを使う案件が中心なので、候補の対象外です。

また約5年前に、Pacemakerを使ったPostgreSQLサーバの評価に関わったことがあるのですが、PacemakerがいろいろなMWの制御ができるだけに、覚えることも多かったので、今回はちょっと敬遠。

そして見つかったのがpg_auto_failoverでした。

  • 以下の内容は多分に推測が混ざってますので、ご注意ください。

評価環境の準備

まずは簡単に動作を確認したいので、リポジトリにある docker-compose.yml を使います。
そのままの設定だと、

  • PostgreSQLサーバのコンテナ3台 (以下、DBノード1, DBノード2のように表記)
  • PostgreSQLクラスタを監視するコンテナ1台 (以下、監視ノード)
  • デモ用アプリケーションのコンテナ1台 (以下、デモアプリ)

の計5台のコンテナが起動しますが、PostgreSQLコンテナは3台もいらないので、node3はコメントアウトしました。

デモ用アプリケーションはドキュメントとdocker-compose.ymlで指定されている環境変数から、以下のように動作するようです。

  • 10個のPostgreSQLクライアントが、１２５秒間クラスタにアクセスする。
  • 45秒経ったら最初のフェールオーバーを実施する。それ以降、30秒間隔にフェールオーバーを実施。
  • 読み書き可能なPostgreSQLサーバへの接続時間を計測する。

評価環境の実行

さっそくdocker composeで動かして、ログを見ると以下のような流れでした。

  • デモアプリは、監視ノードから接続URIを取得し、プライマリのDBノードへ接続所要時間を計測する。
★ デモアプリが監視ノードに接続。でも、接続URIが取れない。
pg_auto_failover-demo-app-1  | 08:36:10 1 INFO  Successfully connected to "postgres://autoctl_node@monitor:/pg_auto_failover?" after 3 attempts in 3475 ms.
pg_auto_failover-demo-app-1  | 08:36:10 1 ERROR Failed to grab the Postgres URI to connect to formation "default", see above for details
pg_auto_failover-demo-app-1  | 08:36:10 1 INFO  Retrying to grab formation "default" URI in 749ms

★ DBノード2が監視ノードに接続。
pg_auto_failover-node2-1     | 08:36:10 9 INFO  Registered node 1 "node_1" (ee34f3f0f896:5432) in formation "default", group 0, state "single"

★ DBノード1が監視ノードに接続。
pg_auto_failover-node1-1     | 08:36:11 9 INFO  Registered node 2 "node_2" (ddb0a4b628c2:5432) in formation "default", group 0, state "wait_standby"

★ デモアプリが接続URIを取得できたが、まだ読み書き可能なDBノードには繋がらない。
pg_auto_failover-demo-app-1  | 08:36:11 1 INFO  Using application connection string "postgres://ee34f3f0f896:5432,ddb0a4b628c2:5432/analytics?target_session_attrs=read-write&sslmode=prefer"
pg_auto_failover-demo-app-1  | 08:36:11 1 WARN  Failed to connect to "postgres://@ee34f3f0f896,ddb0a4b628c2:5432,5432/analytics?sslmode=prefer&target_session_attrs=read-write", retrying until the server is ready

★ デモアプリがDBノードに接続。今から45秒後にフェールオーバー。
pg_auto_failover-demo-app-1  | 08:36:17 1 INFO  Successfully connected to "postgres://@ee34f3f0f896,ddb0a4b628c2:5432,5432/analytics?sslmode=prefer&target_session_attrs=read-write" after 26 attempts in 5606 ms.
pg_auto_failover-demo-app-1  | 08:36:17 7 INFO  Failover client is started, will failover in 45s and every 30s after that
  • 監視ノードに、最初接続できたDBノードがプライマリ、次に接続できたのがセカンダリになり、ストリーミングレプリケーションが行われる。
pg_auto_failover-node2-1     | 08:36:10 9 INFO  FSM transition from "init" to "single": Start as a single node
pg_auto_failover-node1-1     | 08:36:11 9 INFO  FSM transition from "init" to "wait_standby": Start following a primary

★ DBノード2がレプリケーションスロット作成。
pg_auto_failover-node2-1     | 08:36:17 102 INFO  Creating replication slot "pgautofailover_standby_2"
pg_auto_failover-node2-1     | 08:36:17 102 INFO  FSM transition from "single" to "wait_primary": A new secondary was added
pg_auto_failover-node1-1     | 08:36:17 9 INFO  FSM transition from "wait_standby" to "catchingup": The primary is now ready to accept a standby

* DBノード1のpg_basebackupが完了
pg_auto_failover-node1-1     | 08:36:32 9 INFO  pg_basebackup: base backup completed
pg_auto_failover-node1-1     | 08:36:34 9 INFO  FSM transition from "catchingup" to "secondary": Convinced the monitor that I'm up and running, and eligible for promotion again

* ストリーミングレプリケーション開始
pg_auto_failover-node2-1     | 08:36:34 102 INFO  FSM transition from "wait_primary" to "primary": A healthy secondary appeared
pg_auto_failover-node2-1     | 08:36:35 102 INFO  Standby reached LSN 0/3013DD0, thus advanced past LSN 0/300BBA0
  • デモアプリは、DBノードに接続して45秒経過するとフェールオーバーを実施する。
    • フェールオーバーして、デモアプリとの接続は1〜２秒で復活。
    • ストリーミングレプリケーションの再開までは約10秒。
★ デモアプリからフェールオーバーを実施。
pg_auto_failover-demo-app-1  | 08:37:02 7 INFO  pg_autoctl perform failover
pg_auto_failover-demo-app-1  | 08:37:02 7 WARN  Lost connection.
pg_auto_failover-node1-1     | 08:37:02 9 INFO  FSM transition from "secondary" to "prepare_promotion": Stop traffic to primary, wait for it to finish draining.
pg_auto_failover-node2-1     | 08:37:02 102 INFO  FSM transition from "primary" to "draining": A failover occurred, stopping writes
pg_auto_failover-node1-1     | 08:37:02 9 INFO  FSM transition from "prepare_promotion" to "stop_replication": Prevent against split-brain situations.
pg_auto_failover-node2-1     | 08:37:02 102 INFO  FSM transition from "draining" to "demote_timeout": Secondary confirms it’s receiving no more writes
pg_auto_failover-node1-1     | 08:37:03 9 INFO  FSM transition from "stop_replication" to "wait_primary": Confirmed promotion with the monitor
pg_auto_failover-node2-1     | 08:37:03 102 INFO  FSM transition from "demote_timeout" to "demoted": Demote timeout expired

★ デモアプリのDBノードへの接続復活
pg_auto_failover-demo-app-1  | 08:37:03 8 INFO  Successfully connected to "postgres://@ee34f3f0f896,ddb0a4b628c2:5432,5432/analytics?sslmode=prefer&target_session_attrs=read-write" after 6 attempts in 1854 ms.
pg_auto_failover-demo-app-1  | 08:37:03 8 INFO  Client 1 attempted to connect during a failover, and had to attempt 6 times which took 1855.487 ms with the current retry policy

* DBノード2のpg_basebackupが完了
pg_auto_failover-node2-1     | 08:37:09 102 INFO  pg_basebackup: base backup completed
pg_auto_failover-node2-1     | 08:37:12 102 INFO  FSM transition from "catchingup" to "secondary": Convinced the monitor that I'm up and running, and eligible for promotion again

★ ストリーミングレプリケーションが再開。
pg_auto_failover-node1-1     | 08:37:12 9 INFO  FSM transition from "wait_primary" to "primary": A healthy secondary appeared
pg_auto_failover-node1-1     | 08:37:13 9 INFO  Standby reached LSN 0/5015E40, thus advanced past LSN 0/500E000

Javaアプリケーションでの動作確認

次にJDBCではどうなるかを確認します。

  • DBノード1を5433ポート、DBノード2を5434ポートにマッピング。

    • pg_hba.cnfを、PostgreSQLのオフィシャルイメージと同様に、どこからでも接続可に修正してpg_ctl reload。
    • 接続用のアカウントや、データベース(sample)およびテーブルを追加。

  • Javaアプリケーションはホスト側で実行。

    • 1秒間に１レコードずつ追加。
    • JDBC　URLに jdbc:postgresql://localhost:5433,localhost:5434/sample?targetServerType=master を指定。

  • 実際の障害を想定して、pg_autoctl perform failoverコマンドではなく、DBノードのコンテナを停止。以下は監視ノードのログの抜粋です。

    ★ 15:15:23頃に、DBノード2を停止。

★ 監視ノードが、DBノード2(pg_auto_failoverではnod_1)の以上を検知。
pg_auto_failover-monitor-1  | 15:15:42 27 INFO  Node node 1 "node_1" (ee34f3f0f896:5432) is marked as unhealthy by the monitor
pg_auto_failover-monitor-1  | 15:15:42 27 INFO  New state for node 2 "node_2" (ddb0a4b628c2:5432): secondary ➜ prepare_promotion
pg_auto_failover-monitor-1  | 15:15:42 27 INFO  New state for node 2 "node_2" (ddb0a4b628c2:5432): prepare_promotion ➜ stop_replication
pg_auto_failover-monitor-1  | 15:15:42 27 INFO  New state for node 1 "node_1" (ee34f3f0f896:5432): primary ➜ demote_timeout

★ DBノード２のデモート(降格)がタイムアウトし、DBノード1がwait_primary、DBノード2がdemotedに状態遷移。
pg_auto_failover-monitor-1  | 15:16:13 27 INFO  Setting goal state of node 2 "node_2" (ddb0a4b628c2:5432) to wait_primary and node 1 "node_1" (ee34f3f0f896:5432) to demoted after the demote timeout expired.
pg_auto_failover-monitor-1  | 15:16:13 27 INFO  New state for node 2 "node_2" (ddb0a4b628c2:5432): stop_replication ➜ wait_primary
pg_auto_failover-monitor-1  | 15:16:13 27 INFO  New state for node 1 "node_1" (ee34f3f0f896:5432): primary ➜ demoted
    • DBノード2を停止してから異常を検知するまで約20秒かかったのは、Unhealthy Nodesの記述通りのようです。
    • また異常を検知してからDBノードがwait_primaryになるまで30秒かかったのも、Monitor can’t connect to Primaryの通りなんだと思います。

この時のJavaアプリケーション側のログの抜粋が以下になります。

★ 書き込み成功
2022-09-15 15:15:22.904 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Executing query          : insert into sample (text, insert_at) values (?, cast(? as timestamp))
2022-09-15 15:15:22.904 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : -> with bind values      : insert into sample (text, insert_at) values ('14', timestamp '2022-09-15 15:15:22.903612')
2022-09-15 15:15:22.912 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Affected row(s)          : 1

★ ここでPostgreSQLがダウンし応答待ち
2022-09-15 15:15:23.917 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Executing query          : insert into sample (text, insert_at) values (?, cast(? as timestamp))
2022-09-15 15:15:23.917 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : -> with bind values      : insert into sample (text, insert_at) values ('15', timestamp '2022-09-15 15:15:23.917026')

★ コネクションプールの接続確認でエラー
2022-09-15 15:15:23.931  WARN 22674 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@2d7a9786 (このコネクションは既にクローズされています。). Possibly consider using a shorter maxLifetime value.
  〜 割愛 〜
2022-09-15 15:15:23.945  WARN 22674 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@25673087 (このコネクションは既にクローズされています。). Possibly consider using a shorter maxLifetime value.

★ 応答待ちタイムアウトして例外発生。
2022-09-15 15:15:53.925 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Exception                

org.jooq.exception.DataAccessException: SQL [insert into sample (text, insert_at) values (?, cast(? as timestamp))]; HikariPool-1 - Connection is not available, request timed out after 30002ms.
	at org.jooq_3.14.16.POSTGRES.debug(Unknown Source) ~[na:na]
	at org.jooq.impl.Tools.translate(Tools.java:2903) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:757) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:389) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractDelegatingQuery.execute(AbstractDelegatingQuery.java:119) ~[jooq-3.14.16.jar:na]
	at jp.co.supportas.samplemysql.SamplePostgreSQLApplication.run(SamplePostgreSQLApplication.kt:32) ~[main/:na]
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:771) ~[spring-boot-2.7.2.jar:2.7.2]
	at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:755) ~[spring-boot-2.7.2.jar:2.7.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:315) ~[spring-boot-2.7.2.jar:2.7.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1306) ~[spring-boot-2.7.2.jar:2.7.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1295) ~[spring-boot-2.7.2.jar:2.7.2]
	at jp.co.supportas.samplemysql.SamplePostgreSQLApplicationKt.main(SamplePostgreSQLApplication.kt:49) ~[main/:na]
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30002ms.
	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-4.0.3.jar:na]
	at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:159) ~[spring-jdbc-5.3.22.jar:5.3.22]
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:117) ~[spring-jdbc-5.3.22.jar:5.3.22]
	at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:223) ~[spring-jdbc-5.3.22.jar:5.3.22]
	at jdk.proxy2/jdk.proxy2.$Proxy54.prepareStatement(Unknown Source) ~[na:na]
	at org.jooq.impl.ProviderEnabledConnection.prepareStatement(ProviderEnabledConnection.java:109) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.SettingsEnabledConnection.prepareStatement(SettingsEnabledConnection.java:73) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractQuery.prepare(AbstractQuery.java:442) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractDMLQuery.prepare0(AbstractDMLQuery.java:847) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractDMLQuery.prepare(AbstractDMLQuery.java:830) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:342) ~[jooq-3.14.16.jar:na]
	... 8 common frames omitted
Caused by: org.postgresql.util.PSQLException: 指定された targetServerType のサーバーが見つかりません: primary
	at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:346) ~[postgresql-42.3.6.jar:42.3.6]
	at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:49) ~[postgresql-42.3.6.jar:42.3.6]
	at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:223) ~[postgresql-42.3.6.jar:42.3.6]
	at org.postgresql.Driver.makeConnection(Driver.java:402) ~[postgresql-42.3.6.jar:42.3.6]
	at org.postgresql.Driver.connect(Driver.java:261) ~[postgresql-42.3.6.jar:42.3.6]
	at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:364) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:476) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool.access$100(HikariPool.java:71) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:726) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:712) ~[HikariCP-4.0.3.jar:na]
	at java.base/java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:264) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]

  〜 割愛 〜

★ 接続は復活したが応答は遅い
2022-09-15 15:15:55.012 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Executing query          : insert into sample (text, insert_at) values (?, cast(? as timestamp))
2022-09-15 15:15:55.013 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : -> with bind values      : insert into sample (text, insert_at) values ('16', timestamp '2022-09-15 15:15:55.012116')
2022-09-15 15:16:23.686 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Affected row(s)          : 1
★ ここから元通り
2022-09-15 15:16:24.690 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Executing query          : insert into sample (text, insert_at) values (?, cast(? as timestamp))
2022-09-15 15:16:24.690 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : -> with bind values      : insert into sample (text, insert_at) values ('17', timestamp '2022-09-15 15:16:24.690208')
2022-09-15 15:16:24.722 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Affected row(s)          : 1

DBノードがダウンしてから、約１分でフェールオーバーできました。

所感

まずは良さそうな感じです。

DBノードがダウンしてからフェールオーバーするまで約1分というのは、心情的にちょっと長い気もしますが、チューニングの余地もあると思います。

ストリーミングレプリケーションを行うもろもろを自動的にやってくれるので、現段階でまだ知識の足りてない自分には助かります。
もちろん、実際に運用していくには、これを元にちゃんと理解していく必用はあるでしょう。
特に、pg_auto_failoverでフェールオーバーに失敗したような場合に、手動で復旧させるノウハウは必須です。

あと評価に使用したコンテナのPostgreSQLはバージョン10が使われていることから、バージョン13か14にした環境を自前で構築してみて、評価する必用もありますね。

1
2
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
1
2

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?