2012-02-27

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 で入ったコレが原因。

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

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

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

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

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

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

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


2016-06-07 追記

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

--- 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 秒かかることに比べれば、私にとっては些細なことだ。(そもそも主キーを変更することなんてないし)

2012-02-22

Slony-I: duplicate key value violates unique constraint "sl_nodelock-pkey", part 1

Slony-I をアップグレードしたら、エラーが起こるようになった。

2012-02-22 12:15:13.37963 FATAL  localListenThread: "select "_slony1".cleanupNodelock(); insert into "_slony1".sl_nodelock values (    1, 0, "pg_catalog".pg_backend_pid()); " - ERROR:  duplicate key value violates unique constraint "sl_nodelock-pkey"

slon 再起動でも復旧しない。公式ドキュメントによると、

This error message is typically a sign that you have started up a second slon process for a given node. The slon asks the obvious question: "Do you already have a slon running against this node?"

Supposing you experience some sort of network outage, the connection between slon and database may fail, and the slon may figure this out long before the PostgreSQL instance it was connected to does. The result is that there will be some number of idle connections left on the database server, which won't be closed out until TCP/IP timeouts complete, which seems to normally take about two hours. For that two hour period, the slon will try to connect, over and over, and will get the above fatal message, over and over.

とのことだが、今回の場合には二重起動もネットワークエラーも有り得ない。サーバーを再起動しても直らないし。エラーになる前にやったことは、

  1. slave: stop slon
  2. slave: upgrade Slony-I 2.0.6 -> 2.0.7
  3. slave: reboot (start slon)
  4. master: stop slon
  5. master: upgrade Slony-I 2.0.6 -> 2.0.7
  6. master: reboot (start slon)

で、master 側がエラーになる。今まで 2 回起こったので、再現性はあるような気がする。いつか調べるハメになるかも知れないが、まずは復旧させないと。

# psql -U postgres testdb
testdb=# select * from _slony1.sl_nodelock;
 nl_nodeid | nl_conncnt | nl_backendpid
-----------+------------+---------------
         2 |        184 |          2608
         2 |        185 |          2593
         2 |        186 |         11678
         1 |          0 |          2583
         2 |        183 |          2606
(5 rows)

testdb=# delete from _slony1.sl_nodelock where nl_nodeid = 1 and nl_conncnt = 0;
DELETE 1
testdb=# \q

sl_nodelock から duplicate しているレコードを削除して、slon を再起動すれば復旧する。


2016-06-27 追記

いつか調べるハメになるかも知れないが、まずは復旧させないと。

調べた。

2012-02-20

runit: svlogd failed.


runit をビルドして使っていれば一生のうち何回かは出くわすエラー。かくいう私も初見はかなり焦った。「何も変えてないのに何で!?」って。

・・・と思ったけど、検索しても目ぼしいものが見つからないね。これに悩むのはかなりレアらしい。

make[1]: Entering directory `/package/admin/runit-2.1.1/compile'
./check-local chpst runit runit-init runsv runsvchdir runsvdir sv svlogd utmpset

Checking chpst...
Checking runit...
Checking runit-init...
Checking runsv...
Checking runsvchdir...
Checking runsvdir...
Checking sv...
Checking svlogd...
usage: svlogd [-ttv] [-r c] [-R abc] [-l len] [-b buflen] dir ...

111
$Id: 5e55a90e0a1b35ec47fed3021453c50675ea1117 $
usage: svlogd [-ttv] [-r c] [-R abc] [-l len] [-b buflen] dir ...

111
0
foo
0
foo
bar
baz
0
foo
bar
baz
:oo
:ar
:az
0
foo
bar
baz
:oo
:ar
:az
foo
svlogd failed.
make[1]: *** [check] Error 1
make[1]: Leaving directory `/package/admin/runit-2.1.1/compile'

svlogd のテストに失敗している。これを眺めてても訳分からんし、失敗する環境では何度やっても失敗するので、とっとと諦めてソースを読むのが吉。

先のエラーと突き合わせると、場所は次の部分。

runit-2.1.1/src/svlogd.check:

echo t2 >"${ctmp}"/config
( echo foo; sleep 3 ) |svlogd "${ctmp}"
echo $?
cat "${ctmp}"/current

これから予想するに、2 秒でローテートする設定にして 3 秒待ったのに current ログがローテートして(空になって)いない?

ということは時計? クロック? あ、これ VM 環境だ。ビンゴ。


もういい加減に学習しろ、と言われても仕方が無い感じだが、色んな所にシステムを入れまくっていると忘れることもあるんだよ。VMware も Server とか Player とか ESX とか色々あってバージョンによっても挙動変わるしイメージをコピー・移動とかしてたらそりゃあいつか間違うわ。せめてもの予防策は divider=10 を必ず付けておくくらいか。

さて、時計さえ直れば解決するはずだが、何をやってもどうにもならんときは svlogd のテストをスキップさせるのも手。今までどうにもならんかったことは無いけど。

--- src/check-local.orig	2009-10-05 05:44:02.000000000 +0900
+++ src/check-local	2012-02-16 09:37:13.000000000 +0900
@@ -4,6 +4,7 @@
 
 for i in ${1+"$@"}; do
   echo "Checking $i..."
+  [ "$i" = svlogd ] && continue
   env - PATH="$PATH" ctmp="`pwd`/check-tmp" $i.check 2>&1 |cat -v >$i.local
   ./check-diff $i || ( cat $i.local; echo "$i failed."; exit 1 ) || exit 1
 done

2012-02-16

Bash: BASH_SOURCE


Bash で __FILE__ みたいなのが欲しい。つまり Python でいう

if __name__ == '__main__':
   main()

とか、Perl での

if ($0 eq __FILE__) {
   main;
}

おっと、Perl ではこっちの方がイケてるんだっけ?

main unless caller;

とかいうのを Bash でやりたい。今まで何とか誤魔化してお茶を濁してきたが、そろそろ我慢できなくなってきた。で、調べると BASH_SOURCE を使え、と。

if [ "$0" = "$BASH_SOURCE" ] ; then
    main "$@"
fi

組み込み配列変数 BASH_SOURCE の 0 番目要素に現在処理中のファイル名が入っている。なので本来は ${BASH_SOURCE[0]} とするのが正解なのだろうが、みんなやってるし動くなら簡単な方でいいや。

ただ、配列変数を単純参照したとき 0 番目要素の参照になる、という根拠は manpage や「O'reilly 入門 bash 第3版」などからは見つけきらんかった。

2012-02-12

Java: OmitStackTraceInFastThrow

あるとき開発者からこんなことを聞かれた。

「Java のスタックトレースが出なくなることがあるんだけど、リモートデバッグすると出るようになるんだよ。そういうの、何か知らない?」

最初、「この人は何を言ってるんだろう? :-o」と思っていたが、念のため調べてみると・・・、

本当にあったー!

OmitStackTraceInFastThrow が原因らしい。こいつはデフォルトで ON になっているので、OFF にするにはオプション -XX:-OmitStackTraceInFastThrow を使う。

昔 Java のオプションを決めるときに散々調べたけど、このオプションは見なかったなー。GC 関連のオプションは飽きるほど見たけど。でもこれはもっと有名になっても良いオプションだと思う。

サーバ VM のコンパイラではすべての「コールド」組み込み例外に対する的確なスタックバックトレースを提供しています。このような例外が数回スローされると、パフォーマンス向上のため、メソッドが再コンパイルされることがあります。再コンパイルの後、コンパイラはスタックトレースを提供しない事前割り当て済みの例外を使用して、より速い方法を選択できます。事前割り当て済みの例外を全く使用しないようにするには新しいフラグ -XX:-OmitStackTraceInFastThrow を使用します。