2013年09月

一週間止まっていたサービスを何の考えもなしに最繁時間帯に再開するとどうなるか

概要

一週間止まっていたサービスを何の考えもなしに最繁時間帯に再開するとどうなるか…

今まで考えないことはなかったのですが、具体的な対策もしていなかったので想定通り接続しづらい状態が続きました。
誤算は応答時間が通常通りになるまで2時間を要したことでした。

サーバーを現用に組み込む場合は慣らし運転をして十分にキャッシュにデータがのった後に組み込む必要がある…というのは知っていましたが「まあ、30分くらい耐えられば大丈夫だしなあ」と思って特に対策はしていませんでした。
※事実、今までも半日くらいサービスが止まることはありましたが、30分くらいで落ち着きました。

後述しますが、ErogameScapeはPHPが生成するキャッシュ機構を使ってキャッシュを生成しています。
その生成のためにIOwaitが発生し応答時間が遅延しました。

よくアクセスのあるページのキャッシュを生成するスクリプトを作る必要があるかなあ…と思いました。

詳細

2013年9月9日から2013年9月15日に発生した障害についてに記載したとおり、ErogameScapeは一週間ほどサービスが止まりました。
ハード的な障害ではなくソフトの問題でしたので、サーバーを再起動すれば復旧できました。
今までの経験からサーバーが止まって復旧させるとアクセスが集中して負荷が大変なことになることは分かっていました。

ErogameScapeのソフトの構成は以下のようになっています。
---- Apache ---- PHP  ---- pgpool  ---- PostgreSQL
                  |
                  |----- PHPのキャッシュ(HDD)
ErogameScapeは2台のサーバーで動かしています。
いつもは1台のサーバーでやりくりしているため、ApacheもPostgreSQLも同じサーバーで動かしています。
しかし、今回は多数のアクセスがあることが予想されたため、ApacheとPostgreSQLを別々のサーバーで動かすことにしました。

---- Apache ---- PHP  ---- pgpool  --------   ネットワーク    ---- PostgreSQL
                  |
                  |----- PHPのキャッシュ(HDD)
 
この状態で、twitterで「高負荷になるのでアクセスできない場合は時間をおいてアクセスしてください」とアナウンスして、組み込みました。

その結果
 Apacheを動かしているサーバーのLoad Average → 100越え
 PostgreSQLを動かしているサーバーのLoad Average → 最大でも10程度
と、そんな結果になりました。

「ああ、ErogameScapeって意外にPostgreSQLによる負荷って少ないんだなあ」と今更ながら思いました。
さて、Apackeの方がボトルネックになっているからなんとかしないといけないと思いました。

Apacheのhttpd.confのMaxClientsが大きすぎると接続数が多すぎて処理できないから、少なく設定してクライアントに待ってもらった方が結果的に応答時間が少なくなる…という記述を見たことがあったので、設定値を300から200にしてみました。

その結果、300の場合は応答時間が長いものの応答が返ってきていたのですが、200にしたらそもそも応答が返ってこなくなって、これはまずい…と元の設定に戻しました。

元に戻した途端に応答時間が通常通りになりました。

さて、何がボトルネックになっていて当時応答時間が遅かったのだろう…と思ってmuninのグラフを見て考えました。

無題

①はサーバーを組み込んだ後、応答時間が長かった間のApacheのアクセス数です。
通常50access/secondくらいは問題なく処理できるはずなのですが全然捌処理出来ていません。
キャッシュを生成しきった後と思われる②の時点では、通常通り処理できています。

また、Apacheのprocessesについて、③はサーバーを組み込んだ後で、MaxClientsの上限である300までいってしまっているのが見えます。その後、④で200に設定を変更しても応答がなくなってしまったので、あわてて300に変更したら200processes程度に落ち着いたのが分かります。

無題
当時のDisk throughputを見ると最大で3.8MB/secondの書き込みがあります。
②の段階では520kB/second程度にまで落ちています。
ErogameScapeは主要なページをキャッシュしています。
PHPがキャッシュを生成しまくって、最大で3.8MB/secondの書き込みをしている結果、応答が遅くなったのだろうなあと思います。

以上の事象を防ぐには、事前にキャッシュを生成するか、キャッシュを破棄するタイマーを一時的に長くして(通常は5分から1時間に設定しています)みることかなあ…と思います。

終わりに

商用でサービスを提供している技術者の方々には当たり前の内容な気がするのですが、多くのアクセスがある規模のサービスを提供する会社に入るのはすこぶる難しい気がして、でもそういう会社に入らないと学べないこともあると思うんですが、そういう会社に入るためにはそういう会社の当たり前なこと知らないと入れない気もして(求人の条件を見ると、そんな人は少ないんじゃないか…なものばかりに見えます)、できる人はよりできるようになるけど、できないけどやる気がある人は…昔よりは大規模サービスを運用している方々がいろんな本を書いてくださっているので学ぶことはできるのですが、昔よりすこぶる内容が難しくなっているし覚えることも多いし、大変だよなあ…と思います。
こう…なんといいますか、中間くらいの知識が欲しいです。
初心者でもないけど、大規模なサービス運用者でも全然なくて、サーバーが2,3台で済むくらいのサービス運用のノウハウ的な何か。
Webサービス以外の分野もそんな気がしますが、初心者向けの本(サーバーを構築してみよう的な)と、専門書(数百台規模のサーバーを運用します的な)は充実しているのですが、その中間というか、1台だったサーバーを2台で運用してみよう!的な段階の本があるとうれしいなあと思います。
実はあったら教えて欲しいなあと思います。 

プロセス名を指定してプロセスをkillする方法について

例えばhttpをkillしたい場合は
pkill httpd
もしくは
killall  httpd

上記のような止め方をすることは通常ないと思いますが
/sbin/service httpd restart
で止めようとしても、止まらない状況が発生した場合…例えば、Apacheへの接続が多すぎてさばききれないとそうい状況に陥ります…は、上記コマンドで止めましょう。

killはたまに使うので覚えているのですが、pkill、killallは年に1回使うか使わないか程度なので、自分用に記録します。 

2013年9月9日から2013年9月15日に発生した障害について

概要

2013年9月9日から2013年9月15日までErogameScapeに接続できない状態でした。
現在は復旧しております。
 
原因は有効なログが手元にないので推測の域をでないのですが、当時のpsコマンドの結果から、どれかのテーブル(おそらくuserreviewテーブル)のLOCKが獲得できなくてあらかじめ用意されたpostgresqlのコネクションを使い切ってpostgresqlへ接続できなくなり、ErogameScapeに接続できなくなったと思われます。
 
当時、どのテーブルがロックされ続けているのかの確認をするコマンドをうてばよかったのですが、うっていなかったため、どのテーブルのロックの獲得ができなかったのか特定ができません。
 
前に一度この事象が発生したことがあり、その際はpsコマンドの結果からおそらくユーザーSQLが原因であろうと推測し対策をしました。
具体的には新規に作成されたSQLは実行コストを制限するというものでした。
当時、既存のSQLについてはそのままとしたのですが、今回の件を受けて既存のSQLについてもコストを調査し、コストが高いものは非公開とさせて頂きました。
この結果、今まで使えていたSQLが使えなくなっています。

原因はユーザーSQLであるという確証はないのですが(psコマンドの結果からすると?な感じです)、そうではないという確証もないので、すみません、まずはこの対策をさせて頂きました。
waitingが多数発生した場合、ログに残してロックを解除するスクリプトがcloudpackブログ - cloudpack(クラウドパック)Amazon EC2などクラウドの導入設計、運用・保守サービス: Postgres waitingがたまったら強制解除にありましたので、こちらを実装しました。

障害が長引いたのは私が不在だったためです。
サーバーは必要最低限のアクセスしか出来ないようにしているので、障害があった際は私がサーバーの前まで行かないと復旧できません。
それはそれでどうかと思うのですが、私の知識で出来るセキュリティ対策と天秤にかけて、現状のようになっています。
この状況を解決するには私が賢くなるか、賢い方に教えて頂くかになると思うのですが、どちらもハードルが高いです。

詳細

ErogameScapeは2台のパソコンで動かしています。
DBにはpostgresqlを使用し、2台のパソコン各々にpostgresqlを動作させ、pgpoolで冗長を取っています。

当時の1台目のサーバーのpsコマンドの出力は以下の通りでした。
[********@erogamescape ~]$ cat 20130915.log | grep waiting
  842 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57118) LOCK TABLE waiting
  871 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57196) LOCK TABLE waiting
 1108 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57267) LOCK TABLE waiting
 1109 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57271) LOCK TABLE waiting
 1116 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57277) LOCK TABLE waiting
 1214 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57465) LOCK TABLE waiting
 1700 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58063) LOCK TABLE waiting
 1753 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58294) LOCK TABLE waiting
 1857 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58383) LOCK TABLE waiting
 1903 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58401) LOCK TABLE waiting
 1908 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58436) LOCK TABLE waiting
 1947 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58560) LOCK TABLE waiting
 1986 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58672) LOCK TABLE waiting
 2067 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58874) LOCK TABLE waiting
 2089 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58983) LOCK TABLE waiting
 2129 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59131) LOCK TABLE waiting
 2136 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59169) LOCK TABLE waiting
 2157 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59253) LOCK TABLE waiting
 2164 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59264) LOCK TABLE waiting
 2165 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59272) LOCK TABLE waiting
 2192 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59307) LOCK TABLE waiting
 2200 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59359) LOCK TABLE waiting
 2201 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59376) LOCK TABLE waiting
 2208 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59491) LOCK TABLE waiting
 2240 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59892) LOCK TABLE waiting
 2267 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60402) LOCK TABLE waiting
 2313 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60563) LOCK TABLE waiting
 2341 ?        Ss     0:12 postgres: ******** ******** 192.168.0.2(33981) VACUUM waiting
 2344 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60649) UPDATE waiting
 2345 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60673) LOCK TABLE waiting
 2432 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60752) LOCK TABLE waiting
 2439 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60813) LOCK TABLE waiting
 2446 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60832) LOCK TABLE waiting
 2450 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60901) LOCK TABLE waiting
 2451 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60928) LOCK TABLE waiting
 2477 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(32849) LOCK TABLE waiting
 2484 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33128) LOCK TABLE waiting
 2611 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33531) LOCK TABLE waiting
 2617 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33608) LOCK TABLE waiting
 2619 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33620) LOCK TABLE waiting
 2620 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33625) LOCK TABLE waiting
 2625 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33861) LOCK TABLE waiting
 2650 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34543) LOCK TABLE waiting
 2655 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34959) LOCK TABLE waiting
 2668 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35158) LOCK TABLE waiting
 2669 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35191) LOCK TABLE waiting
 2674 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35354) LOCK TABLE waiting
 2678 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35470) LOCK TABLE waiting
 2705 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35851) LOCK TABLE waiting
 2712 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35938) LOCK TABLE waiting
 2714 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36009) LOCK TABLE waiting
 2731 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36291) LOCK TABLE waiting
 2737 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36809) LOCK TABLE waiting
 2739 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36969) LOCK TABLE waiting
 2740 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(37003) LOCK TABLE waiting
 2810 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38692) LOCK TABLE waiting
 2813 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38823) LOCK TABLE waiting
 2819 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39241) LOCK TABLE waiting
 2858 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39561) LOCK TABLE waiting
 2859 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39675) LOCK TABLE waiting
 2861 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39737) LOCK TABLE waiting
 2863 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39816) LOCK TABLE waiting
 2866 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39947) LOCK TABLE waiting
 2868 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40134) LOCK TABLE waiting
 2870 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40216) LOCK TABLE waiting
 2875 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40577) LOCK TABLE waiting
 2876 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40763) LOCK TABLE waiting
 2974 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41120) LOCK TABLE waiting
 3026 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41192) LOCK TABLE waiting
 3273 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41457) LOCK TABLE waiting
 3421 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41712) LOCK TABLE waiting
 3553 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41892) LOCK TABLE waiting
 3608 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42292) LOCK TABLE waiting
 3609 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45322) LOCK TABLE waiting
 3629 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42615) LOCK TABLE waiting
 3630 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42622) LOCK TABLE waiting
 3635 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42796) LOCK TABLE waiting
 3662 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43240) LOCK TABLE waiting
 3671 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43487) LOCK TABLE waiting
 3672 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43593) LOCK TABLE waiting
 3678 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43842) LOCK TABLE waiting
 3680 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43962) LOCK TABLE waiting
 3683 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44065) LOCK TABLE waiting
 3686 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44138) LOCK TABLE waiting
 3695 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44410) LOCK TABLE waiting
 3704 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44484) LOCK TABLE waiting
 3721 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45363) LOCK TABLE waiting
 3723 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45430) LOCK TABLE waiting
 3732 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45703) LOCK TABLE waiting
 3737 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45932) LOCK TABLE waiting
 3741 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46241) LOCK TABLE waiting
 3743 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46263) LOCK TABLE waiting
 3747 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46358) LOCK TABLE waiting
 3750 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46375) LOCK TABLE waiting
 3757 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46431) LOCK TABLE waiting
 3766 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46475) LOCK TABLE waiting
 3768 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46667) LOCK TABLE waiting
 3770 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46885) LOCK TABLE waiting
 3774 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47164) LOCK TABLE waiting
 3775 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47245) LOCK TABLE waiting
 3779 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47858) LOCK TABLE waiting
 3781 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48012) LOCK TABLE waiting
 3805 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48638) LOCK TABLE waiting
 3817 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48769) LOCK TABLE waiting
 3822 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48837) LOCK TABLE waiting
 3832 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49218) LOCK TABLE waiting
 3838 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53792) LOCK TABLE waiting
 3840 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49396) LOCK TABLE waiting
 3841 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49414) LOCK TABLE waiting
 3843 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49516) LOCK TABLE waiting
 3849 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49600) LOCK TABLE waiting
 3851 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49633) LOCK TABLE waiting
 3868 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49701) LOCK TABLE waiting
 3869 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49705) LOCK TABLE waiting
 3874 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49807) LOCK TABLE waiting
 3971 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49878) LOCK TABLE waiting
 4448 ?        Ss     0:10 postgres: ******** ******** 192.168.0.2(58662) VACUUM waiting
 4549 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50041) LOCK TABLE waiting
 4600 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50127) LOCK TABLE waiting
 5258 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50368) LOCK TABLE waiting
 5586 ?        Ss     0:12 postgres: ******** ******** 192.168.0.2(50897) VACUUM waiting
 5917 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(55418) LOCK TABLE waiting
 5954 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50495) LOCK TABLE waiting
 5955 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50501) LOCK TABLE waiting
 5957 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50505) LOCK TABLE waiting
 6026 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50595) LOCK TABLE waiting
 6050 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50629) LOCK TABLE waiting
 6906 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(37406) LOCK TABLE waiting
 7557 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(51042) LOCK TABLE waiting
 8192 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(51140) LOCK TABLE waiting
 8200 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(51154) LOCK TABLE waiting
 8970 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(51282) LOCK TABLE waiting
 9724 ?        Ss     0:10 postgres: ******** ******** 192.168.0.2(55184) VACUUM waiting
10225 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(52159) LOCK TABLE waiting
10671 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58523) LOCK TABLE waiting
10681 ?        Ss     0:13 postgres: ******** ******** 192.168.0.2(59101) VACUUM waiting
13081 ?        Ss     0:11 postgres: ******** ******** 192.168.0.2(42113) VACUUM waiting
13949 ?        Ss     0:12 postgres: ******** ******** 192.168.0.2(60879) VACUUM waiting
14340 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36418) LOCK TABLE waiting
16205 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43918) LOCK TABLE waiting
16504 ?        Ss     0:07 postgres: ******** ******** 192.168.0.2(46920) VACUUM waiting
16518 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53097) LOCK TABLE waiting
17357 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53245) LOCK TABLE waiting
17387 ?        Ss     0:11 postgres: ******** ******** 192.168.0.2(38856) VACUUM waiting
19877 ?        Ss     0:04 postgres: ******** ******** 192.168.0.2(53310) VACUUM waiting
20628 ?        Ss     0:10 postgres: ******** ******** 192.168.0.2(48334) VACUUM waiting
22710 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54272) LOCK TABLE waiting
23173 ?        Ss     0:15 postgres: ******** ******** 192.168.0.2(58004) VACUUM waiting
23712 ?        Ss     0:10 postgres: ******** ******** 192.168.0.2(48797) VACUUM waiting
24642 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54489) LOCK TABLE waiting
25813 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45276) LOCK TABLE waiting
25986 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50454) LOCK TABLE waiting
26094 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53746) LOCK TABLE waiting
26450 ?        Ss     0:11 postgres: ******** ******** 192.168.0.2(35952) VACUUM waiting
27000 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35568) LOCK TABLE waiting
27075 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39790) LOCK TABLE waiting
27078 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39899) LOCK TABLE waiting
27276 ?        Ss     0:10 postgres: ******** ******** 192.168.0.2(60642) VACUUM waiting
27856 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47920) LOCK TABLE waiting
28042 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53992) LOCK TABLE waiting
28051 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54198) LOCK TABLE waiting
28150 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58474) LOCK TABLE waiting
28298 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36520) LOCK TABLE waiting
28773 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38179) LOCK TABLE waiting
28986 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41314) LOCK TABLE waiting
28997 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41431) LOCK TABLE waiting
29037 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42460) LOCK TABLE waiting
29062 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44100) LOCK TABLE waiting
29114 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45545) LOCK TABLE waiting
29129 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45627) LOCK TABLE waiting
29152 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46473) LOCK TABLE waiting
29177 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47993) DELETE waiting
29192 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48813) LOCK TABLE waiting
29223 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(52453) LOCK TABLE waiting
29286 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54872) LOCK TABLE waiting
29354 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59312) LOCK TABLE waiting
29607 ?        Ss     0:10 postgres: ******** ******** 192.168.0.2(52579) VACUUM waiting
29788 ?        Ss     0:08 postgres: ******** ******** 192.168.0.2(43110) VACUUM waiting
29985 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33745) LOCK TABLE waiting
30002 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34163) LOCK TABLE waiting
30062 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35973) LOCK TABLE waiting
30090 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38160) LOCK TABLE waiting
30099 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38277) LOCK TABLE waiting
30124 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40599) LOCK TABLE waiting
30144 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41052) LOCK TABLE waiting
30150 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41633) LOCK TABLE waiting
30219 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43994) LOCK TABLE waiting
30220 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44032) LOCK TABLE waiting
30222 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44058) LOCK TABLE waiting
30235 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44598) LOCK TABLE waiting
30236 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44681) LOCK TABLE waiting
30237 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44729) LOCK TABLE waiting
30258 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45182) LOCK TABLE waiting
30259 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45237) LOCK TABLE waiting
30260 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45402) LOCK TABLE waiting
30261 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45427) LOCK TABLE waiting
30270 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45880) LOCK TABLE waiting
30271 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45906) LOCK TABLE waiting
30321 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46702) LOCK TABLE waiting
30336 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47241) LOCK TABLE waiting
30342 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47432) LOCK TABLE waiting
30377 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47775) LOCK TABLE waiting
30387 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48193) LOCK TABLE waiting
30392 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48829) LOCK TABLE waiting
30399 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49109) LOCK TABLE waiting
30402 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49118) LOCK TABLE waiting
30407 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49146) LOCK TABLE waiting
30419 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49348) LOCK TABLE waiting
30564 ?        Ss     0:07 postgres: ******** ******** 192.168.0.2(42302) VACUUM waiting
31016 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50460) LOCK TABLE waiting
31056 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(51483) LOCK TABLE waiting
31060 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(51621) LOCK TABLE waiting
31070 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(52276) LOCK TABLE waiting
31081 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(52532) LOCK TABLE waiting
31134 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53156) LOCK TABLE waiting
31135 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53179) LOCK TABLE waiting
31140 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53375) LOCK TABLE waiting
31151 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53735) LOCK TABLE waiting
31157 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53961) LOCK TABLE waiting
31159 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54045) LOCK TABLE waiting
31161 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54186) LOCK TABLE waiting
31164 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54273) LOCK TABLE waiting
31169 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54534) LOCK TABLE waiting
31178 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54918) LOCK TABLE waiting
31182 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(55034) LOCK TABLE waiting
31186 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(55143) LOCK TABLE waiting
31194 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(55817) LOCK TABLE waiting
31200 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(55884) LOCK TABLE waiting
31204 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(55992) LOCK TABLE waiting
31209 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56090) LOCK TABLE waiting
31218 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56150) LOCK TABLE waiting
31219 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56167) LOCK TABLE waiting
31222 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56258) LOCK TABLE waiting
31223 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56298) LOCK TABLE waiting
31225 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56308) LOCK TABLE waiting
31231 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56393) LOCK TABLE waiting
31240 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56447) LOCK TABLE waiting
31241 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56451) LOCK TABLE waiting
31308 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56641) LOCK TABLE waiting
31916 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56728) LOCK TABLE waiting
31918 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56738) LOCK TABLE waiting
31972 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56791) LOCK TABLE waiting
31977 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56809) LOCK TABLE waiting
31995 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56839) LOCK TABLE waiting
32066 ?        Ss     0:37 postgres: ******** ******** 192.168.0.2(60697) VACUUM waiting
32483 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53850) LOCK TABLE waiting
テーブルのロック待ちが発生しているのが一目瞭然です。
もう一台のサーバーのpsコマンドの結果は以下のとおりでした。
[********@erogamescape ~]$ cat 20130915.log | grep postgres | grep -v nobody
  616 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49421) idle in transaction
  651 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49584) idle in transaction
  661 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49670) idle in transaction
 1279 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49911) idle in transaction
 1892 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50019) idle
 1894 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50038) idle in transaction
 1895 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50044) idle in transaction
 1896 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50048) idle in transaction
 1916 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50123) idle
 1919 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50138) idle in transaction
 1932 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50172) idle in transaction
 2520 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50263) idle
 2529 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50293) idle
 2534 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50299) idle
 3483 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50577) idle
 3737 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50585) idle in transaction
 3760 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50683) idle in transaction
 3765 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50697) idle in transaction
 4360 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(50825) idle in transaction
10543 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(52640) idle in transaction
11148 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(52788) idle in transaction
13556 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49712) idle
13578 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(51879) idle
14197 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60233) idle
14218 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58293) idle
14814 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58441) idle
14824 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53691) idle
14899 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53185) idle
15053 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53335) idle in transaction
15313 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58856) idle
15394 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58491) idle
15397 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58503) idle
15408 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58529) idle
15410 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58547) idle
15437 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53815) idle in transaction
16060 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40859) idle
16859 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35176) idle
24607 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44819) idle in transaction
25500 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35111) idle in transaction
25648 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46074) idle
25695 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46095) idle
25810 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46322) idle
26324 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53535) idle in transaction
26365 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(55963) idle
26391 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57880) idle
26393 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58017) idle in transaction
26394 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58043) idle
26469 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36386) idle
27042 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(37691) idle
27069 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38970) idle
27148 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43620) idle
27169 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45088) idle in transaction
27186 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53393) idle in transaction
27207 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47572) idle
27209 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47668) idle
27213 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48037) idle
27241 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(51960) idle
27243 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(51996) idle in transaction
27249 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(52312) idle
27274 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54356) idle
27276 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54417) idle in transaction
27278 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54484) idle
27282 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(54598) idle
27298 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(55962) idle
27301 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56472) idle
27303 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(56754) idle
27917 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33646) idle
27919 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33706) idle in transaction
27925 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34100) idle
27948 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35516) idle in transaction
27952 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36091) idle
27956 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36785) idle
27990 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41054) idle
28080 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47736) idle in transaction
28676 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49782) idle
28705 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(52356) idle
28709 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(55858) idle
28731 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(53504) idle in transaction
31245 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57008) idle in transaction
31293 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57180) idle
31294 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57361) idle
31296 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57674) idle
31305 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57798) idle
31324 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57921) idle
31325 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57926) idle in transaction
31328 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57944) idle in transaction
31333 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(57979) idle in transaction
31357 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58103) idle in transaction
31379 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58215) idle in transaction
31384 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58268) idle
31391 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58280) idle
31397 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58313) idle
31411 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58386) idle
31413 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58417) idle in transaction
31427 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58515) idle
31429 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58526) idle in transaction
31450 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58630) idle
31456 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58674) idle in transaction
31461 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58712) idle in transaction
31464 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58743) idle
31467 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58762) idle
31469 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58774) idle
31474 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58796) idle in transaction
31480 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58807) idle in transaction
31481 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58815) idle in transaction
31482 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58821) idle
31491 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58840) idle
31492 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58846) idle
31493 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58850) idle in transaction
31500 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58902) idle in transaction
31501 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58919) idle in transaction
31503 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(58971) idle
31508 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59034) idle in transaction
31509 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59057) idle
31511 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59179) idle
31512 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59188) idle
31518 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59435) idle in transaction
31520 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59631) idle
31523 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59836) idle
31524 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59945) idle in transaction
31525 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59955) idle
31526 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(59994) idle
31527 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60029) idle
31529 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60089) idle
31531 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60106) idle in transaction
31533 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60192) idle in transaction
31534 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60216) idle in transaction
31535 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60231) idle
31537 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60252) idle
31540 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60295) idle in transaction
31547 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60356) idle in transaction
31548 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60359) idle
31550 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60375) idle in transaction
31553 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60444) idle in transaction
31554 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60471) idle in transaction
31558 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60625) idle in transaction
31559 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60721) idle
31560 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60806) idle
31561 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60883) idle
31562 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(60904) idle in transaction
31564 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33074) idle in transaction
31566 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33151) idle in transaction
31567 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33163) idle in transaction
31568 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33168) idle in transaction
31571 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33404) idle in transaction
31572 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33597) idle
31573 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33655) idle
31575 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33687) idle
31576 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33917) idle
31577 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(33992) idle
31578 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34082) idle
31579 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34086) idle in transaction
31580 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34260) idle
31582 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34374) idle
31583 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34378) idle
31584 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34494) idle
31585 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34502) idle in transaction
31586 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34507) idle
31590 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34701) idle in transaction
31591 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34735) idle
31592 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34737) idle in transaction
31594 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(34897) idle in transaction
31595 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35009) idle
31596 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35013) idle in transaction
31603 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35252) idle
31606 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35342) idle
31608 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35394) idle in transaction
31615 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35481) idle in transaction
31616 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35552) idle in transaction
31618 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35567) idle
31621 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35703) idle
31622 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35802) idle
31623 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(35834) idle in transaction
31625 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36084) idle
31628 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36352) idle in transaction
31630 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36512) idle in transaction
31631 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36546) idle in transaction
31634 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36750) idle
31636 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36853) idle
31637 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(36936) idle
31644 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(37151) idle
31645 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(37278) idle
31647 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(37519) idle
31654 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(37841) idle
31655 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(37900) idle
31657 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38235) idle in transaction
31660 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38366) idle in transaction
31661 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38427) idle
31664 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38718) idle
31665 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38784) idle in transaction
31667 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(38927) idle
31670 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39104) idle in transaction
31671 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39218) idle in transaction
31672 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39280) idle in transaction
31674 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39359) idle in transaction
31676 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39406) idle
31677 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39490) idle in transaction
31680 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39677) idle in transaction
31682 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39759) idle in transaction
31684 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(39949) idle
31687 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40120) idle in transaction
31688 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40306) idle in transaction
31690 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40495) idle
31695 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40663) idle in transaction
31708 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40697) idle
31733 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40713) idle
31785 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(40735) idle in transaction
32039 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41000) idle in transaction
32064 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41029) idle
32093 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41101) idle
32101 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41110) idle
32231 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41255) idle in transaction
32237 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41287) idle
32294 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41360) idle
32295 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41435) idle in transaction
32296 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41489) idle
32297 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41498) idle
32299 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41586) idle
32305 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(41835) idle in transaction
32307 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42018) idle
32308 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42033) idle
32310 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42052) idle
32313 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42158) idle in transaction
32314 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42165) idle in transaction
32316 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42339) idle in transaction
32318 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42407) idle
32336 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42777) idle
32337 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42783) idle in transaction
32341 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(42991) idle
32343 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43030) idle in transaction
32344 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43136) idle in transaction
32346 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43292) idle
32348 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43385) idle in transaction
32350 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43505) idle in transaction
32352 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43608) idle in transaction
32353 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43669) idle
32354 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43681) idle in transaction
32356 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(43953) idle in transaction
32357 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44027) idle in transaction
32358 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44110) idle
32360 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44320) idle
32364 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44567) idle
32367 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44675) idle
32370 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44906) idle in transaction
32371 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44960) idle
32372 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(44973) idle in transaction
32374 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45012) idle
32379 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45246) idle in transaction
32383 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45397) idle
32384 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45475) idle in transaction
32388 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45784) idle in transaction
32390 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45806) idle in transaction
32393 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45901) idle in transaction
32394 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45918) idle in transaction
32395 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45946) idle
32396 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(45974) idle in transaction
32397 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46018) idle in transaction
32398 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46210) idle in transaction
32400 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46428) idle in transaction
32403 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46564) idle
32404 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46707) idle in transaction
32406 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(46788) idle in transaction
32409 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47401) idle in transaction
32410 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47555) idle in transaction
32411 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47607) idle
32412 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(47725) idle
32416 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48181) idle in transaction
32425 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48266) idle
32426 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48312) idle in transaction
32431 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48380) idle in transaction
32441 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48761) idle in transaction
32444 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48829) idle
32445 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48899) idle
32447 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48939) idle in transaction
32448 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(48957) idle in transaction
32451 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49059) idle in transaction
32456 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49143) idle in transaction
32458 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49176) idle in transaction
32465 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49244) idle in transaction
32466 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49248) idle in transaction
32472 ?        Ss     0:00 postgres: ******** ******** 192.168.0.2(49350) idle in transaction
トランザクション中でアイドルのプロセスがいっばいです。
ここで、どのテーブルがロック待ちなのか、pg_stat_activityテーブル、pg_locksテーブルの内容を保存してから再起動すればよかったのですが、当時の私にそんな知識はなかったので、再起動してしまいました。
結果、何が原因だったのか分かりません。 

ただpsコマンドの結果から、どのユーザー権限で実行されたSQLか?は分かりました。
LOCK TABLE waitingとなっているプロセスは、ユーザーSQLを実行する権限でした。
ユーザーSQLには実行に超時間要するものがあり、今回のような事象を引き起こす可能性が高いと判断しました。
そこで、実行コストの高いユーザーSQLを非公開とさせて頂きました。
(再度公開とするためには、現在規定しているコスト以下に修正する必要があります。)

今回のような事象を引き起こした原因の1つは、長期ロック保持があるかを確認すべきところしていなかったことにあると思っています。
ロック待ちとなっている処理内容は稼動統計情報を活用しよう(2)—Let's Postgresで確認できることが分かりましたので、cronで定期時にSQLをチェックし、ロック待ちとなっている処理を常時確認できるようにいたしました。

またloudpackブログ - cloudpack(クラウドパック)Amazon EC2などクラウドの導入設計、運用・保守サービス: Postgres waitingがたまったら強制解除を参考に、waitingが発生しているプロセスが5を超えて発生した場合、in transactionなSQLの接続を強制的に切断するようにしました。

今回の例ではin transactionな状態になっているのは、もう一つのサーバーのみでした。
もう一つのサーバーのみSQLの接続が強制的に切断された場合、pgpoolがどのような動作をするのか検証していないので不明です。
サーバー同士でデータの不整合が発生する可能性があります。

今回のような事象が発生する前に、ロック待ちとなっている処理を確認できることを祈ります。

無題

ログがないのでなんともですが、上図のCPUの使用率からLOCK TABLE waitingが発生したのは8日の12時以降と推測します。
そしてサーバーが応答できなくなったのは、9日の12時頃と推測します。
同じ原因でLOCK TABLE watingが発生しても1日は耐えられそうですので、自分が不在でなければユーザーのみなさんに分からないうちに対処が完了できると思っています。

終わりに

以上が事象の報告と対策のご説明です。
大変ご迷惑をおかけいたしました。
また、「こうした方がいい」というご意見がございましたら、ぜひコメントを頂きたく思います。
 
今後ともよろしくお願いします。
記事検索