あるとき 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 だけを当てることにした。
さて、今後のアップグレードはどうしたもんか・・・。
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 秒かかることに比べれば、私にとっては問題でない。そもそも主キーなんてそうそう変更しないし。
