2013年11月

IPVSとKeepalivedとApacheは同じOS上で共存出来ない…と思う

はじめに

一つのパソコンのLinuxの上に
  •  KeepalivedでVRRPを設定
  •  IPVSでロードバランシングを設定
  •  Apacheを動作
させて、
  •  パソコンが落ちると、もう一つのパソコンに切り替わり
  •  通常時は2台あるパソコンに処理を分散させる
ことを実現しようと思ったのですが、出来なかった…という記録です。
※何年かしたら、なんで出来ないんだっけ?と思う日が来るかもしれないので書いておきます。
※ちなみに、IPVSとKeepalivedの設定はKeepalivedによるロードバランサLVS構築 - RLBの文書が丁寧でいいかなと思います。


ハードウェア構成
001

実現したかった構成
002
設定
BlogPaint

#VRRP部分
vrrp_instance VI_1 {
    state BACKUP
    interface eth1
    garp_master_delay 5
    virtual_router_id 51
    priority 100
    advert_int 1
    authentication {
        auth_type PASS
        auth_pass 1111
    }
    virtual_ipaddress {
        192.168.0.100/24 dev eth1
    }
}

#ロードバランシング部分
virtual_server_group example_web_servers {
  192.168.0.100  80
}

virtual_server group example_web_servers {
  delay_loop   3
  lvs_sched    lc
  lvs_method   DR
  protocol     TCP

  real_server  192.168.0.1 80 {
    weight 1
    inhibit_on_failure
    HTTP_GET {
      url {
        path /
        status_code 200
      }
      connect_port 80
      connect_timeout 10
    }
  }
  real_server  192.168.0.2 80 {
    weight 1
    inhibit_on_failure
    HTTP_GET {
      url {
        path /
        status_code 200
      }
      connect_port 80
      connect_timeout 10
    }
  }
}
想像していたもの
BlogPaint


現実
BlogPaint


192.168.0.100の80番ポートに要求が来ると、それをロードバランサが処理するのではなくApacheが先に処理をしてしまいます。その結果、ロードバランサは素通りします。

ロードバランサもApacheも80番ポートで待ち構えているのがNGなので、Apacheのポートを8080にすればいいじゃないか!とも思いましたが、DSR構成でないといけないのでApacheのポートを8080にすると80番ポートに要求してきたものが8080番で応答が返ってしまうのでNGです。

ちなみに左のパソコン自身で
$ curl http://192.168.0.100/index.html
すると、左のパソコンのApacheが選ばれた場合は
21:55:03.363352 IP 192.168.0.1.52535 > 192.168.0.100.http: Flags [S], seq 2243980878, win 14600, options [mss 1460,sackOK,TS val 2335997614 ecr 0,nop,wscale 7], length 0
21:55:03.363465 IP 192.168.0.100.http > 192.168.0.1.52535: Flags [S.], seq 1870693664, ack 2243980879, win 14480, options [mss 1460,sackOK,TS val 2335994093 ecr 2335997614,nop,wscale 7], length 0
21:55:03.363571 IP 192.168.0.1.52535 > 192.168.0.100.http: Flags [.], ack 1, win 115, options [nop,nop,TS val 2335997614 ecr 2335994093], length 0
21:55:03.363659 IP 192.168.0.1.52535 > 192.168.0.100.http: Flags [P.], seq 1:184, ack 1, win 115, options [nop,nop,TS val 2335997614 ecr 2335994093], length 183
21:55:03.363995 IP 192.168.0.100.http > 192.168.0.1.52535: Flags [.], ack 184, win 122, options [nop,nop,TS val 2335994094 ecr 2335997614], length 0
21:55:03.364464 IP 192.168.0.100.http > 192.168.0.1.52535: Flags [P.], seq 1:272, ack 184, win 122, options [nop,nop,TS val 2335994094 ecr 2335997614], length 271
21:55:03.364550 IP 192.168.0.1.52535 > 192.168.0.100.http: Flags [.], ack 272, win 123, options [nop,nop,TS val 2335997616 ecr 2335994094], length 0
21:55:03.364750 IP 192.168.0.1.52535 > 192.168.0.100.http: Flags [F.], seq 184, ack 272, win 123, options [nop,nop,TS val 2335997616 ecr 2335994094], length 0
21:55:03.364997 IP 192.168.0.100.http > 192.168.0.1.52535: Flags [F.], seq 272, ack 185, win 122, options [nop,nop,TS val 2335994095 ecr 2335997616], length 0
21:55:03.365065 IP 192.168.0.1.52535 > 192.168.0.100.http: Flags [.], ack 273, win 123, options [nop,nop,TS val 2335997616 ecr 2335994095], length 0
と、送信元が192.168.0.1で宛先が192.168.0.100となって通信が成立します。
が、右のパソコンが選ばれた場合は
21:57:00.468685 IP 192.168.0.100.40601 > 192.168.0.100.http: Flags [S], seq 1090039344, win 32792, options [mss 16396,sackOK,TS val 2336114720 ecr 0,nop,wscale 7], length 0
21:57:00.468820 ARP, Request who-has 192.168.0.100 tell 192.168.0.2, length 46
21:57:00.468843 ARP, Reply 192.168.0.100 is-at 6c:62:6d:08:c8:97 (oui Unknown), length 28
21:57:00.469031 IP 192.168.0.100.http > 192.168.0.100.40601: Flags [S.], seq 354377091, ack 1090039345, win 14480, options [mss 1460,sackOK,TS val 2336111198 ecr 2336114720,nop,wscale 7], length 0
21:57:01.468573 IP 192.168.0.100.40601 > 192.168.0.100.http: Flags [S], seq 1090039344, win 32792, options [mss 16396,sackOK,TS val 2336115720 ecr 0,nop,wscale 7], length 0
21:57:01.468714 IP 192.168.0.100.http > 192.168.0.100.40601: Flags [S.], seq 354377091, ack 1090039345, win 14480, options [mss 1460,sackOK,TS val 2336112198 ecr 2336114720,nop,wscale 7], length 0
21:57:01.631898 IP 192.168.0.100.http > 192.168.0.100.40601: Flags [S.], seq 354377091, ack 1090039345, win 14480, options [mss 1460,sackOK,TS val 2336112362 ecr 2336114720,nop,wscale 7], length 0
21:57:03.468575 IP 192.168.0.100.40601 > 192.168.0.100.http: Flags [S], seq 1090039344, win 32792, options [mss 16396,sackOK,TS val 2336117720 ecr 0,nop,wscale 7], length 0
21:57:03.468768 IP 192.168.0.100.http > 192.168.0.100.40601: Flags [S.], seq 354377091, ack 1090039345, win 14480, options [mss 1460,sackOK,TS val 2336114198 ecr 2336114720,nop,wscale 7], length 0
21:57:03.631910 IP 192.168.0.100.http > 192.168.0.100.40601: Flags [S.], seq 354377091, ack 1090039345, win 14480, options [mss 1460,sackOK,TS val 2336114362 ecr 2336114720,nop,wscale 7], length 0
となって、192.168.0.100の間でピンポンゲームになってしまいます。
送信元が192.168.0.100になるロジックが分からないのでなんともですが、まず
192.168.0.100 → 192.168.0.100(左のパソコンが受信)
というパケットが左のパソコンに送られます。
左のパソコンには
iptables -t nat -A PREROUTING -d 192.168.0.100 -j REDIRECT
が書いてあるので、送信元が192.168.0.100、宛先が192.168.0.100のパケットを返します。
このパケットを受け取った左のパソコンは…送信元が192.168.0.100で宛先が192.168.0.100ってなんだっけ?と破棄して、またSYNパケットを送る…という動作になっているのだと思います。

実現するには

多分、物理的なパソコン2台に、それぞれ1つのOSがのっているという状態だと無理なのだと思います。

※ぐぐって見つかるIPVS + Keepalivedの設定例は、書いてある図が物理構成なのか論理構成なのかいまいち分からない…というのが悩ましいところだと思っています。

※余談ですが、NW機器をまったく知らないという方が異動したきた際に例えばVRFを使った「論理的なルータ」というものを理解してもらうのに苦労します…しませんか?。「ええとね、このルータは物理的には1台なんだけど、仮想的に3台になっていてね…」「物理的なポートに対して仮想的なポートを設定してね…」と説明すると、明らかに挙動がおかしくなり、じゃあ図を書いて説明しますねとホワイトボードに向かうも…ごちゃごちゃになっていまいち分かりにくいと…自分はいったいこれをどう理解して現在に至るのか分かりません…

多分、以下のように仮想化するしかないのかなと…
006

この構成を取るには学ばなければいけないことがたくさんありすぎるので諦めることにしました。

設定を開始してから諦めるまで5時間くらいかかりました。敗因は「できる」と思い込んでいたことでしょうか…
「できなかったです」という掲示板のやりとりを見て「ああ、やっぱできないんだ」と、そこで、自分でいろいろいじった結果も踏まえて納得して諦めることができました。
この文書が、私と同じ発想に行き着いてしまった方のために役に立つことを祈ります。
※まあ、だいたい、何年後の自分のために役に立つことが多いんですよね。ぐぐると、意外に自分の書いた文書がひっかかったりします…

※ちなみに、keepalivedによるVRRP --- nginx(80番ポートで待ち受け)によるロードバランス ---- Apache(8080番ポートで待ち受け)な構成で、元々やりたかったことが実現可能だと分かりました。


 
もう5年も前に発売された本ですが、個人でサーバーを運用している私にとってはその内容は色あせることがないです。Webの世界…特にフロントエンドは新しい技術がわさわさ出てきてついていくのが大変ですが、インフラの世界は比較的穏やかなのかな…という気がしました。
そのかわり、達人の域に達するには、達人の域が必要である環境に飛び込まないとスキルが身につかない気がいたします。一度、すごいトラヒックをさばく環境で仕事をしてみたいです。

Web開発の基礎徹底攻略 (WEB+DB PRESS plus)

Web開発の基礎徹底攻略 (WEB+DB PRESS plus)を読みました。
表紙に「for BEGINNERS」と書いてあるので、初心者向けに違いないと思っていたのですが、私はWebエンジニアの初心者の域にも達していなかった…と思いました。

Web開発の基礎徹底攻略は特集記事5本から構成されています。
  1. Web技術まるごと整理
  2. コーディングの基礎知識
  3. はじめての設計
  4. データベース&SQL入門
  5. クラウド時代のインフラ知識
私がどんな道を歩んできたかというと
  • ErogameScapeを作って10年くらい
  • 違和感なく書ける言語はPHPだけ
  • よく知っているデータベースはPostgreSQLだけ
  • 今の仕事は主にCisco等のNW機器の監視 
な感じです。 

各記事の感想は以下の通りです。

Web技術まるごと整理
 Webに使われてる技術をさらっと概観をなめていて初心者向けの良い記事だと思いました。

コーディングの基礎知識
 例として使われいてる言語がRubyで、Rubyをかじったことがない時点でハードルが高いです。
 第1章 きれいなコードの重要性、第2章 適切な名前をつけ、不要なコメントはつけない、まではサクサク読めました。しかし、第3章のテスト駆動開発を実践する、から内容のハードルがあがり、Rubyをよく知らないということも加わって、読むのがきつかったです。
 常にリファクタリングを行う、1つのメソッドが行うことは1つにする、クラスの責務は1つにする、と現在では良いとされていて、自分も理解していることが書いてあるのですが、Rubyを知らないのと、そもそもErogameScapeはテストコードを書いてなくて(よくないと思っているのですが…)テストコードの経験がないから、テストコードを書くことを前提にしているこの記事を読むのがつらい要因かと思いました。


はじめての設計
 一番書いてある内容が難しくて、抽象的で、どうやって実践するのかが分からない…記事でした。
 この記事の内容は実際にコードを書いてみて、この記事を理解している方にレビューしてもらわないと身につかない気がします。 
 Web開発の基礎徹底攻略を読む方の多くは「組織」としてWeb開発をされる方々だと思うので、実際にレビューしてもらう機会があると思いますが、私のように1人で書くな環境だと、この記事の内容をちゃんと理解して実践するのは難易度が高いと感じます。

データベース & SQL入門
 ミックさんの記事はよく読んでいることと、本当に初心者向けですので、さらっと読めました。
 初心者にお勧めの記事です。


クラウド時代のインフラ知識
 こちらも日頃から普通にやっていることなので、さらっと読みました。
 日頃からインフラに触れて、運用をやっていない方々にこの記事は響くのかな…とも思いました。
  運用は実際にやってみて毎日数字を見て、あれ?今日はなんかいつもと違うぞ…と感じ取る何かが必要な気がしています。

全部読んでみて分かったのですが
  • 私はWebエンジニアとしては失格
  • 私はWebエンジニアが知っているべきインフラの知識はクリアしている
  • どうも私はWebエンジニアではなくて、どちらかといえばインフラエンジニアよりらしい

ということでした。

Web開発の基礎徹底攻略はインフラエンジニアの方々にはお勧めできないです。
というのは、
インフラよりの記事はとても優しいからです。
※趣味の延長でErogsmeScapeを運用している私が優しいと感じているので、本職な方々にとっては、当たり前すぎる内容しか書いていないです。


pgpool-II-3.3.1でオンメモリクエリキャッシュを使用すると不要なログが出力される

おそらく設定は問題ないと思うのですが、pgpool-II-3.3.1でオンメモリクエリキャッシュを使用すると以下のログをはき出します。

2013-11-09 22:35:48 ERROR: pid 32459: pool_delete_item_shmem_cache: item 1083 was deleted
2013-11-09 22:35:48 ERROR: pid 32459: pool_delete_item_shmem_cache: item 1090 was deleted
2013-11-09 22:35:48 ERROR: pid 32459: pool_delete_item_shmem_cache: item 1097 was deleted
2013-11-09 22:35:48 ERROR: pid 32459: pool_delete_item_shmem_cache: item 1104 was deleted
2013-11-09 22:35:48 LOG:   pid 3877: pool_reuse_block: blockid: 47
2013-11-09 22:35:51 LOG:   pid 3689: pool_reuse_block: blockid: 48
2013-11-09 22:35:58 LOG:   pid 4696: pool_reuse_block: blockid: 49

2013-11-10 10:30:01 ERROR: pid 26379: Child process 1292 was terminated by segmentation fault


pool_delete_item_shmem_cacheはキャッシュしているクエリで使われているテーブルが更新されたためキャッシュを削除しましたというログです。
pool_reuse_blockは分かりません。


pool_delete_item_shmem_cacheとpool_reuse_block: blockidについては0000079: Pgpool 3.2 memory cache log:  pool_delete_item_shmem_cache - pgpool Bug Trackerで同じ話題があがっていますが、調査のために再現する環境が必要とのことです。
※ キャッシュしているクエリで使われているテーブルが更新されたためキャッシュを削除しましたというログは必要ないからログとしてはき出さないようにするという修正がすでにされているようですが、その修正がされていないのではないかという話題です。

ErogameScapeの環境では、起動した直後に100%再現するのですが、ErogameScapeのPostgreSQLのdumpとphpのスクリプトをお渡しするわけにもいかない…パスワード以外は公開しているのでお渡ししてもOKなのですが、いかんせん容量が大きいので…再現するコンパクトな環境を作りたいです。 


Child process 26583 was terminated by segmentation faultについては、0000055: Child process ##### was terminated by segmentation fault - pgpool Bug Trackerが似ています。同じく調査のために再現する環境が必要とのことです。 

●pgpoolのログ
2013-11-10 10:30:01 ERROR: pid 26379: Child process 1292 was terminated by segmentation fault

●/var/log/messages
Nov 10 10:30:01 erogamescape14 abrt[2832]: Saved core dump of pid 1292 (/usr/local/pgpool-II-3.3.1/bin/pgpool) to /var/spool/abrt/ccpp-2013-11-10-10:29:58-1292 (162537472 bytes)
Nov 10 10:30:01 erogamescape14 abrtd: Directory 'ccpp-2013-11-10-10:29:58-1292' creation detected
Nov 10 10:30:01 erogamescape14 abrtd: Executable '/usr/local/pgpool-II-3.3.1/bin/pgpool' doesn't belong to any package
Nov 10 10:30:01 erogamescape14 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2013-11-10-10:29:58-1292' exited with 1
Nov 10 10:30:01 erogamescape14 abrtd: Corrupted or bad directory '/var/spool/abrt/ccpp-2013-11-10-10:29:58-1292', deleting

ErogameScapeでは1時間に5回ほどsegmentation faultが起こるので、log_statementをtrueにして、SQL依存があるかどうかの確認からスタートでしょうか…


pgpoolのオンメモリクエリキャッシュの設定は以下の通りです。
memory_cache_enabled = on
memqcache_memcached_host = 'localhost'
memqcache_memcached_port = 11211
memqcache_total_size = 67108864
memqcache_max_num_cache = 1000000
memqcache_expire = 0
memqcache_auto_cache_invalidation = on
memqcache_maxcache = 409600
memqcache_cache_block_size = 1048576
Mandatory if memqcache_method = 'shmem'.
memqcache_oiddir = '/home/ap2/oiddir'
white_memqcache_table_list = ''
black_memqcache_table_list = ''

SHOW pool_cacheの結果は以下の通りです。
# SHOW pool_cache;
-[ RECORD 1 ]---------------+---------
num_cache_hits              | 7885445
num_selects                 | 11780541
cache_hit_ratio             | 0.40
num_hash_entries            | 1048576
used_hash_entries           | 120918
num_cache_entries           | 120918
used_cache_entries_size     | 66125645
free_cache_entries_size     | 801177
fragment_cache_entries_size | 181658
40%ほどキャッシュにあたっています。
以下のグラフはmuninでPostgreSQLの読み取りデータ量を表示しているものです。
赤矢印の部分がオンメモリクエリキャッシュを利用した部分です。
確かにPostgreSQLの読み取りデータ量が減っていることが確認できます。
無題
 体感速度も速くなっている…はず…
 

PostgreSQLを9.0から9.3にあげたらsoftirqの値が低くなった

PostgreSQLを9.0から9.3にあげたらsoftirqの値が低くなりました。

 無題3
こちらが9.0で動かしていたときのmuninのグラフです。
日に日にsoftirqのしめる割合が大きくなっています。

ちなみにuserのしめる割合も日に日に増加しています。
ErogameScapeを使っているユーザーさんはほとんど増えていないので、userのしめる割合が増えているのはデータ量が増えていっているからです。

※userのグラフがすごく大きな値になっている部分は、ErogameScapeでデッドロックに使い事象が発生した時のものですので無視して下さい。

無題4
userのしめる割合が増えているのは設定ミスが原因ですので無視して下さい。
9.3にあげたらsoftirqが減りました。
※softurqが何をやっているのかいまいち分からないので、減るのがいいことなのかそうでもないのか分からないですが減りました。

ErogameScapeにおいてPostgreSQLのロケールをデフォルトのUTF8で初期化すると重いクエリがある

結論

CentOSにyumでインストールしたPostgreSQLはinitdbするとロケールがUTF8となります。
# SELECT name, setting, context FROM pg_settings WHERE name LIKE 'lc%';
    name     |   setting   |  context
-------------+-------------+-----------
 lc_collate  | ja_JP.UTF-8 | internal
 lc_ctype    | ja_JP.UTF-8 | internal
 lc_messages | ja_JP.UTF-8 | superuser
 lc_monetary | ja_JP.UTF-8 | user
 lc_numeric  | ja_JP.UTF-8 | user
 lc_time     | ja_JP.UTF-8 | user
(6 行)
ロケールがUTF8の場合、日本語を含む列をGROUP BYするような場合、とても遅くなります。

$ /usr/pgsql-9.3/bin/initdb -D /var/lib/pgsql/9.3/data --locale=C
と、ロケールをCに設定することをお勧めします。
# SELECT name, setting, context FROM pg_settings WHERE name LIKE 'lc%';
    name     | setting |  context
-------------+---------+-----------
 lc_collate  | C       | internal
 lc_ctype    | C       | internal
 lc_messages | C       | superuser
 lc_monetary | C       | user
 lc_numeric  | C       | user
 lc_time     | C       | user
(6 行)

いきさつ概要

PostgreSQL9.0からPostgreSQL9.3にVerUPする際、今までは
$ /usr/pgsql-9.0/bin/initdb -D /var/lib/pgsql/9.0/data --locale=C
と、ロケールにCを指定して初期化していました。
※確か、ロケールをCにしないとORDER BYしたときの並び方が感覚にあっていない…という理由だったと思います。

しかし、9.3を導入したときは
# service postgresql-9.3 initdb
としていました。
この場合、ロケールはUTF8で設定されます。

理屈は分かりませんが、ロケールをUTF-8とした場合、特に大量の日本語が格納されている列をGROUP BY句にいれると、SQLの実行が異常に遅くなる事象を確認しました。


いきさつ

PostgreSQLを9.0から9.3 にあげたらCPU負荷があがりました。

無題

また微妙にディスクI/Oも増えました。
無題1

9.0と9.3でコストが高いSQLを実行して比較しました。
実行したSQLは以下の通りです。

select u.uid,COUNT(u.tokuten),m.hitokoto FROM myuserview m ,userreview u WHERE m.uid = u.uid GROUP BY u.uid,m.hitokoto ORDER BY COUNT(u.tokuten) DESC;

まずはEXPLAINの結果を比較します。
9.0のEXPLAINの結果は以下の通りです。
# EXPLAIN select u.uid,COUNT(u.tokuten),m.hitokoto FROM myuserview m ,userreview u WHERE m.uid = u.uid GROUP BY u.uid,m.hitokoto ORDER BY COUNT(u.tokuten) DESC;
                                          QUERY PLAN
----------------------------------------------------------------------------------------------
 Sort  (cost=796875.09..799229.12 rows=941611 width=291)
   Sort Key: (count(u.tokuten))
   ->  GroupAggregate  (cost=424784.57..445970.82 rows=941611 width=291)
         ->  Sort  (cost=424784.57..427138.60 rows=941611 width=291)
               Sort Key: u.uid, myuser.hitokoto
               ->  Hash Join  (cost=5755.99..73880.29 rows=941611 width=291)
                     Hash Cond: (u.uid = myuser.uid)
                     ->  Seq Scan on userreview u  (cost=0.00..39965.11 rows=941611 width=12)
                     ->  Hash  (cost=2455.44..2455.44 rows=65244 width=288)
                           ->  Seq Scan on myuser  (cost=0.00..2455.44 rows=65244 width=288)
(10 行)

9.3のEXPLAINの結果は以下の通りです。
# EXPLAIN  select u.uid,COUNT(u.tokuten),m.hitokoto FROM myuserview m ,userreview u WHERE m.uid = u.uid GROUP BY u.uid,m.hitokoto ORDER BY COUNT(u.tokuten) DESC;
                                          QUERY PLAN
----------------------------------------------------------------------------------------------
 Sort  (cost=810050.34..812417.85 rows=947004 width=298)
   Sort Key: (count(u.tokuten))
   ->  GroupAggregate  (cost=431679.86..450619.94 rows=947004 width=298)
         ->  Sort  (cost=431679.86..434047.37 rows=947004 width=298)
               Sort Key: u.uid, myuser.hitokoto
               ->  Hash Join  (cost=5805.85..72249.46 rows=947004 width=298)
                     Hash Cond: (u.uid = myuser.uid)
                     ->  Seq Scan on userreview u  (cost=0.00..38070.04 rows=947004 width=12)
                     ->  Hash  (cost=2438.82..2438.82 rows=65282 width=295)
                           ->  Seq Scan on myuser  (cost=0.00..2438.82 rows=65282 width=295)
(10 行)

EXPLAINの実行結果はあまりかわりません。
次に、  EXPLAIN ANALYZEの結果をみます。

まずは9.0です。
# EXPLAIN ANALYZE select u.uid,COUNT(u.tokuten),m.hitokoto FROM myuserview m ,userreview u WHERE m.uid = u.uid GROUP BY u.uid,m.hitokoto ORDER BY COUNT(u.tokuten) DESC;
                                                                   QUERY PLAN

------------------------------------------------------------------------------------------------------------------------
-------------------------
 Sort  (cost=796875.09..799229.12 rows=941611 width=291) (actual time=7839.773..7842.543 rows=26204 loops=1)
   Sort Key: (count(u.tokuten))
   Sort Method:  quicksort  Memory: 3985kB
   ->  GroupAggregate  (cost=424784.57..445970.82 rows=941611 width=291) (actual time=6589.616..7826.559 rows=26204 loop
s=1)
         ->  Sort  (cost=424784.57..427138.60 rows=941611 width=291) (actual time=6589.603..7410.715 rows=946356 loops=1
)
               Sort Key: u.uid, myuser.hitokoto
               Sort Method:  external merge  Disk: 162392kB
               ->  Hash Join  (cost=5755.99..73880.29 rows=941611 width=291) (actual time=291.349..2941.949 rows=946356
loops=1)
                     Hash Cond: (u.uid = myuser.uid)
                     ->  Seq Scan on userreview u  (cost=0.00..39965.11 rows=941611 width=12) (actual time=14.134..1748.
609 rows=946356 loops=1)
                     ->  Hash  (cost=2455.44..2455.44 rows=65244 width=288) (actual time=276.851..276.851 rows=65244 loo
ps=1)
                           Buckets: 2048  Batches: 8  Memory Usage: 508kB
                           ->  Seq Scan on myuser  (cost=0.00..2455.44 rows=65244 width=288) (actual time=6.345..229.775
 rows=65244 loops=1)
 Total runtime: 7874.282 ms
(14 行)

次に9.3です。
# EXPLAIN  ANALYZE select u.uid,COUNT(u.tokuten),m.hitokoto FROM myuserview m ,userreview u WHERE m.uid = u.uid GROUP BY u.uid,m.hitokoto ORDER BY COUNT(u.tokuten) DESC;
                                                                  QUERY PLAN

------------------------------------------------------------------------------------------------------------------------
-----------------------
 Sort  (cost=810050.34..812417.85 rows=947004 width=298) (actual time=466359.118..466362.684 rows=26224 loops=1)
   Sort Key: (count(u.tokuten))
   Sort Method: quicksort  Memory: 3986kB
   ->  GroupAggregate  (cost=431679.86..450619.94 rows=947004 width=298) (actual time=388687.232..466347.076 rows=26224
loops=1)
         ->  Sort  (cost=431679.86..434047.37 rows=947004 width=298) (actual time=388678.206..465844.530 rows=947102 loo
ps=1)
               Sort Key: u.uid, myuser.hitokoto
               Sort Method: external merge  Disk: 162656kB
               ->  Hash Join  (cost=5805.85..72249.46 rows=947004 width=298) (actual time=48.662..1106.059 rows=947102 l
oops=1)
                     Hash Cond: (u.uid = myuser.uid)
                     ->  Seq Scan on userreview u  (cost=0.00..38070.04 rows=947004 width=12) (actual time=0.045..291.16
0 rows=947102 loops=1)
                     ->  Hash  (cost=2438.82..2438.82 rows=65282 width=295) (actual time=48.411..48.411 rows=65291 loops
=1)
                           Buckets: 2048  Batches: 8  Memory Usage: 505kB
                           ->  Seq Scan on myuser  (cost=0.00..2438.82 rows=65282 width=295) (actual time=0.036..28.135
rows=65291 loops=1)
 Total runtime: 466395.321 ms
(14 行)

9.3の方がとんでもなく時間がかかっています。
ソートにディスクを使いまくっているので、9.3になったらディスクの使い方がまずくなったのか?と思いましたので、work_memを300MBに増やして再度実行してみました。
※ぐぐると、 external merge  Diskの量だけwork_memに積めばOKなことが書いてあるのですが、実際はexternal merge  Diskより多くのメモリを確保しないとメモリを使ってソートしてくれませんでした。今回のSQLの場合、work_memを276610kB確保する必要がありました。

9.0の実行結果は以下の通りです。
# EXPLAIN ANALYZE select u.uid,COUNT(u.tokuten),m.hitokoto FROM myuserview m ,userreview u WHERE m.uid = u.uid GROUP BY u.uid,m.hitokoto ORDER BY COUNT(u.tokuten) DESC;
                                                                  QUERY PLAN

------------------------------------------------------------------------------------------------------------------------
-----------------------
 Sort  (cost=272469.15..274823.18 rows=941611 width=291) (actual time=3018.428..3021.111 rows=26204 loops=1)
   Sort Key: (count(u.tokuten))
   Sort Method:  quicksort  Memory: 3985kB
   ->  GroupAggregate  (cost=157852.62..179038.87 rows=941611 width=291) (actual time=2432.474..3006.945 rows=26204 loop
s=1)
         ->  Sort  (cost=157852.62..160206.65 rows=941611 width=291) (actual time=2432.464..2570.835 rows=946356 loops=1
)
               Sort Key: u.uid, myuser.hitokoto
               Sort Method:  quicksort  Memory: 277269kB
               ->  Hash Join  (cost=3270.99..64422.35 rows=941611 width=291) (actual time=47.316..816.311 rows=946356 lo
ops=1)
                     Hash Cond: (u.uid = myuser.uid)
                     ->  Seq Scan on userreview u  (cost=0.00..39965.11 rows=941611 width=12) (actual time=0.009..202.23
3 rows=946356 loops=1)
                     ->  Hash  (cost=2455.44..2455.44 rows=65244 width=288) (actual time=47.250..47.250 rows=65244 loops
=1)
                           Buckets: 8192  Batches: 1  Memory Usage: 3744kB
                           ->  Seq Scan on myuser  (cost=0.00..2455.44 rows=65244 width=288) (actual time=0.020..27.486
rows=65244 loops=1)
 Total runtime: 3030.406 ms

実行時間が半分以下になりました。
続いて9.3の実行結果です。

# EXPLAIN ANALYZE select u.uid,COUNT(u.tokuten),m.hitokoto FROM myuserview m ,userreview u WHERE m.uid = u.uid GROUP BY u.uid,m.hitokoto ORDER BY COUNT(u.tokuten) DESC;
                                                                  QUERY PLAN

------------------------------------------------------------------------------------------------------------------------
-----------------------
 Sort  (cost=269816.36..272183.87 rows=947004 width=290) (actual time=92436.600..92440.232 rows=26224 loops=1)
   Sort Key: (count(u.tokuten))
   Sort Method: quicksort  Memory: 3986kB
   ->  GroupAggregate  (cost=156871.88..175811.96 rows=947004 width=290) (actual time=91778.152..92427.445 rows=26224 lo
ops=1)
         ->  Sort  (cost=156871.88..159239.39 rows=947004 width=290) (actual time=91778.083..91913.285 rows=947105 loops
=1)
               Sort Key: u.uid, myuser.hitokoto
               Sort Method: quicksort  Memory: 276610kB
               ->  Hash Join  (cost=3253.85..62867.48 rows=947004 width=290) (actual time=45.518..925.404 rows=947105 lo
ops=1)
                     Hash Cond: (u.uid = myuser.uid)
                     ->  Seq Scan on userreview u  (cost=0.00..38306.04 rows=947004 width=12) (actual time=0.012..329.67
0 rows=947105 loops=1)
                     ->  Hash  (cost=2437.82..2437.82 rows=65282 width=287) (actual time=45.460..45.460 rows=65291 loops
=1)
                           Buckets: 8192  Batches: 1  Memory Usage: 3746kB
                           ->  Seq Scan on myuser  (cost=0.00..2437.82 rows=65282 width=287) (actual time=0.011..27.265
rows=65291 loops=1)
 Total runtime: 92451.731 ms
(14 行)

実行時間が20%になりましたが、それでも9.0での実行に遠く及びません。

この後
  • 別サーバーにPostgreSQL9.0をインストールしてSQLを実行し、遅いことを確認 → PostgreSQL9.3は悪くない
  • GROUP BY句を使うと遅いのか → 遅くない
  • GROUP BY句にインデックスをはっていない列があると遅いのか → 遅くない
  • GROUP BY句に数字だけの列だと速いか → 速い
等々を試して、
  • 日本語を含む列をGROUP BY句にいれると遅いこと
を発見し
  • GROUP BY句はソートが実行される
ことをドキュメントで発見し、
  • そういえば元々はどうやってPostgreSQLをインストールしてたんだっけ?
と思って手順書を確認し、もともとロケールはCで設定していたことに気がつき(ここまではpostgresql.confしか見ていませんでした…)
  • ロケールをCにしたのは、ソートが関係していたんだったような…あー、もしかして、UTF8だとソートが遅い?
と思って、ロケールをCにしたら、元々のスピードになりました。

pgpool_status

pgpoolのレプリケーションや負荷分散の動作や設定を検証のため、わざと片方のpostgresqlを落とすということをすると思います。

その後、pgpoolの機能を使って落としたpostgresqlのリカバリをして立ち上げるのではなく、落とした方のpostgresqlと落としていない方のpostgresqlのデータを整合させて(具体的には双方ともに予めバックアップしておいたファイルをインポートする等ですね)、pgpoolを再立ち上げすることが多いかなと思います。

※pgpoolでオンラインリカバリが出来るように設定するのは結構骨が折れると思っています。権限の設定とか忘れたりします。

マニュアルに書いてあるとおり、pgpoolは停止する際にpgpool_statusというファイルにバックエンドの状態を書き込みます。そして、再度pgpoolを起動するとき、pgpool_statusが存在すると、 バックエンドの状態をpgpool_statusの通りに復元します。

何を言っているのかというと…以下のようになります。
[ID] hostname:port Status       (weight)
------------------------------------------------
[00] erogamescape14:5432 Connected    (1932735282)
[01] erogamescape15:5432 Connected    (214748364)
という状態でIDが01のpostgresqlを落とすと
[ID] hostname:port Status       (weight)
------------------------------------------------
[00] erogamescape14:5432 Connected    (1932735282)
[01] erogamescape15:5432 down         (214748364)
という状態になります。
この状態でpgpoolを落として、erogamescape14とerogamescape15のpostgresqlのDBの内容を一致化させたとします。
再度pgpoolを起動した際には
[ID] hostname:port Status       (weight)
------------------------------------------------
[00] erogamescape14:5432 Connected    (1932735282)
[01] erogamescape15:5432 Connected    (214748364)
となって欲しいのですが、そうなりません。
pgpoolを落としたときに
[ID] hostname:port Status       (weight)
------------------------------------------------
[00] erogamescape14:5432 Connected    (1932735282)
[01] erogamescape15:5432 down         (214748364)
という状態だったとpgpool_statusに書いてあるので、
[ID] hostname:port Status       (weight)
------------------------------------------------
[00] erogamescape14:5432 Connected    (1932735282)
[01] erogamescape15:5432 down         (214748364)
という状態で起動してしまいます。
これを防ぐには、pgpoolを起動する前にpgpool_statusを削除するか、Ver3.0以上のpgpoolの場合、起動する際に-Dまたは--discard-statusのオプションをつけて起動することが必要です。

※たまにオンラインリカバリがうまくいかない場合、pg_dumpしたデータをインポートして2つのpostgresqlのデータを同期させることを、今でもたまにやるのですが(やると30分くらいサービスが中断しますので、あまりやりたくないのですが…)、その際にpgpool_statusを消し忘れてpgpoolを起動してしまって、ぐあーっ!となったことがよくありました。まあ、その場合はなぜかオンラインリカバリができるようになっているので、再度pg_dumpしたデータから復旧させることはないので、いいっちゃあいいのですが、オンラインリカバリができなかったら悲しいです。
記事検索