Slony-I 2.0.7: EXECUTE SCRIPT is terribly slow

あるとき PostgreSQL が死ぬほど遅くなった。思えば PostgreSQL も Slony-I もアップグレードしたし、 VM の CPU 割り当て個数も変えた。そう言えばアンチウィルスもアップグレードした。もう心当たりがあり過ぎて、何が原因なのか切り分けるのも面倒臭え。

しかし観察していると、PostgreSQL が止まっている間、PostgreSQL が CPU を使い切っている。いったい何を?と pg_stat_activity を覗くと、

testdb=# select * from pg_stat_activity;
 datid  | datname | procpid | usesysid | usename  |                     current_query                      | waiting |          xact_start           |          query_start          |         backend_start         | client_addr | client_port
--------+---------+---------+----------+----------+--------------------------------------------------------+---------+-------------------------------+-------------------------------+-------------------------------+-------------+-------------
 415435 | testdb  |    5255 |    16389 | slony    | <IDLE>                                                 | f       |                               | 2012-02-24 19:48:07.394428+09 | 2012-02-24 19:22:35.865852+09 | 127.0.0.1   |       48965
 415435 | testdb  |    5260 |    16389 | slony    | <IDLE>                                                 | f       |                               | 2012-02-24 19:22:36.307407+09 | 2012-02-24 19:22:36.034956+09 | 127.0.0.1   |       48966
 415435 | testdb  |    5261 |    16389 | slony    | <IDLE>                                                 | f       |                               | 2012-02-24 19:45:36.396714+09 | 2012-02-24 19:22:36.03749+09  | 127.0.0.1   |       48968
 415435 | testdb  |    9887 |    16389 | slony    | select "_slony1".ddlScript_complete(1, $1::text, -1);  | f       | 2012-02-24 19:48:01.33087+09  | 2012-02-24 19:48:01.349439+09 | 2012-02-24 19:48:01.325438+09 | **.***.*.** |       43807
 415435 | testdb  |    5262 |    16389 | slony    | select "_slony1".createEvent('_slony1', 'SYNC', NULL); | t       | 2012-02-24 19:48:08.113728+09 | 2012-02-24 19:48:08.113921+09 | 2012-02-24 19:22:36.044133+09 | 127.0.0.1   |       48969
 415435 | testdb  |    4417 |       10 | postgres | select * from pg_stat_activity;                        | f       | 2012-02-24 19:48:08.321619+09 | 2012-02-24 19:48:08.321619+09 | 2012-02-24 19:17:32.972981+09 |             |          -1
(6 rows)

Slony-I が犯人っぽい。多分、2.0.6 -> 2.0.7 で入ったコレが原因。

• slony1-engine.git/commitdiff: Fix for bug 217.
• Bug 217 - Changing the primary key of a replicated table leads to trouble

この変更によって、EXECUTE SCRIPT の実行に最大 30 秒かかるようになった。連続で EXECUTE SCRIPT を流すと、2 回目以降の EXECUTE SCRIPT は確実に 30 秒かかる。

もちろん Slony-I に悪意はない。EXECUTE SCRIPT で主キーを変更すると同期が壊れる問題の対処として、EXECUTE SCRIPT を実行するタイミングを変更したのだろう。EXECUTE SCRIPT なんて滅多に実行しないはずだから、30 秒かかるくらいは大した問題ではない、と。しかし、

私には大問題だー! :-(

私のシステムは大量の DDL を使う。それも複数の DDL を纏めて流すのではなく、それぞれの DDL を個々に EXECUTE SCRIPT で流す。そうして、いつもなら 5 分で終わる処理が、1 時間かかるようになった。orz

そもそも 2.0.7 に上げたのには理由がある。2.0.6 には、一方のサーバーを再起動するだけで同期が停止する という、非同期レプリケーションとしてあるまじき致命的な不具合がある(slon 再起動で復旧する)。この問題だけは放置できない。しかし EXECUTE SCRIPT の問題も、私にとっては大問題だ。

ひとしきり悩んだ結果、2.0.7 から bug 217 の修正を除去するのは面倒そうなので、2.0.6 に同期復旧の patch だけを当てることにした。

• slony1-engine.git/commitdiff: SchedStatus is not an integer.

さて、今後のアップグレードはどうしたもんか・・・。

---

2016-06-07 追記

今更の更新だが、この EXECUTE SCRIPT が遅い問題は、下記の patch で解決する。ddlScript_complete_int 中の 1 行をコメントアウトするだけで良い。

--- slony1-2.0.8/src/backend/slony1_funcs.sql.orig	2014-04-09 08:18:17.000000000 +0900
+++ slony1-2.0.8/src/backend/slony1_funcs.sql	2016-06-07 20:09:32.000000000 +0900
@@ -3800,7 +3800,7 @@
 	v_row				record;
 begin
 	perform @NAMESPACE@.updateRelname(p_set_id, p_only_on_node);
-	perform @NAMESPACE@.repair_log_triggers(true);
+	-- perform @NAMESPACE@.repair_log_triggers(true);
 	return p_set_id;
 end;
 $$ language plpgsql;

2.1.4 で動作することも確認している。2.2.x は未確認だが、たぶん問題ないと思う。

もちろん、これは「EXECUTE SCRIPT で主キーを変更しない」ことが条件となる。仮に主キーの変更が必要になったとしても、そのテーブルを一旦 Slony-I から外して主キーを変更し、Slony-I に再登録すれば良い。テーブルの再構築は発生してしまうが、EXUCUTE SCRIPT に 30 秒かかることに比べれば、私にとっては問題でない。そもそも主キーなんてそうそう変更しないし。