Received: from localhost (unknown [200.46.204.183]) by mail.postgresql.org (Postfix) with ESMTP id B0791632235 for ; Wed, 4 Mar 2009 12:19:11 -0400 (AST) Received: from mail.postgresql.org ([200.46.204.86]) by localhost (mx1.hub.org [200.46.204.183]) (amavisd-maia, port 10024) with ESMTP id 81431-03 for ; Wed, 4 Mar 2009 12:19:03 -0400 (AST) Received: from mx1.hub.org (mx1.hub.org [200.46.208.106]) by mail.postgresql.org (Postfix) with ESMTP id 6C49D632225 for ; Wed, 4 Mar 2009 12:19:02 -0400 (AST) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from outbound.afilias.info (outbound.afilias.info [69.46.124.26]) by mx1.hub.org (Postfix) with ESMTP id 773EC1259E92 for ; Wed, 4 Mar 2009 12:18:58 -0400 (AST) Received: from ms6.yyz2.afilias-ops.info ([10.50.129.112] helo=smtp.afilias.info) by outbound.afilias.info with esmtp (Exim 4.69) (envelope-from ) id 1Leto3-0004nx-4E for pgsql-performance@postgresql.org; Wed, 04 Mar 2009 16:18:51 +0000 Received: from vgateway.libertyrms.info ([207.219.45.62] helo=[10.1.3.44]) by smtp.afilias.info with esmtpsa (SSLv3:AES256-SHA:256) (Exim 4.69) (envelope-from ) id 1Leto3-0000BV-77 for pgsql-performance@postgresql.org; Wed, 04 Mar 2009 16:18:51 +0000 Subject: Long Running Commits From: Brad Nicholson To: pgsql-performance Content-Type: text/plain; charset=UTF-8 Date: Wed, 04 Mar 2009 11:18:50 -0500 Message-Id: <1236183530.21727.82.camel@bnicholson-desktop> Mime-Version: 1.0 X-Mailer: Evolution 2.22.3.1 Content-Transfer-Encoding: quoted-printable X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=0 tagged_above=0 required=5 tests=none X-Spam-Level: X-Archive-Number: 200903/43 X-Sequence-Number: 32965 Running PG 8.1.11 on AIX 5.3 Trying to track down the cause of long running commits on one of our DB ser= vers. =20 I can rule checkpoints out (I've set log_min_messages to debug2 and the com= mits are not happening during checkpoints). We have this problem over a period of ~ 35 minutes per day only. during tha= t period we have no change in our write load, but we do have substantial increase in reads on one table (pretty much all being served by index scans= from the buffer pool - which most likely points to a shift in activity over the time period, and not the problem itself). =20 Over the same time, we also see an abnormally large number of connections b= eing opened and closed. We can see this in the DB connection pool=20 logs as well as the DB logs). This is most likely being driven by the acti= vity shift that we can see in the stats. =20 What we do see is connections being opened and closed rapidly during this s= ame period of time (DB logs below). I'm wondering if the=20 commits are waiting on something at the file system level due to the proce= sses. Ulimit settings on the server: ulimit -a core file size (blocks, -c) soft data seg size (kbytes, -d) soft file size (blocks, -f) unlimited max memory size (kbytes, -m) hard open files (-n) 4096 pipe size (512 bytes, -p) 64 stack size (kbytes, -s) soft cpu time (seconds, -t) unlimited max user processes (-u) 10240 virtual memory (kbytes, -v) unlimited DB logs: 2009-03-04 09:56:13.465 CUT [561402] DEBUG: forked new backend, pid=3D7= 94696 socket=3D9 2009-03-04 09:56:13.645 CUT [561402] DEBUG: forked new backend, pid=3D2= 101474 socket=3D9 2009-03-04 09:56:13.645 CUT [561402] DEBUG: server process (PID 516334)= exited with exit code 0 2009-03-04 09:56:13.646 CUT [561402] DEBUG: server process (PID 1458332= ) exited with exit code 0 2009-03-04 09:56:13.646 CUT [561402] DEBUG: server process (PID 2174998= ) exited with exit code 0 2009-03-04 09:56:13.647 CUT [561402] DEBUG: server process (PID 1519662= ) exited with exit code 0 2009-03-04 09:56:13.647 CUT [561402] DEBUG: server process (PID 1646618= ) exited with exit code 0 2009-03-04 09:56:13.647 CUT [561402] DEBUG: server process (PID 999648)= exited with exit code 0 2009-03-04 09:56:13.648 CUT [561402] DEBUG: server process (PID 2285774= ) exited with exit code 0 2009-03-04 09:56:13.648 CUT [561402] DEBUG: server process (PID 1622108= ) exited with exit code 0 2009-03-04 09:56:13.648 CUT [561402] DEBUG: server process (PID 1024216= ) exited with exit code 0 2009-03-04 09:56:13.649 CUT [561402] DEBUG: server process (PID 1392706= ) exited with exit code 0 2009-03-04 09:56:13.665 CUT [561402] DEBUG: forked new backend, pid=3D1= 392708 socket=3D9 2009-03-04 09:56:13.666 CUT [561402] DEBUG: server process (PID 1773680= ) exited with exit code 0 2009-03-04 09:56:13.669 CUT [561402] DEBUG: forked new backend, pid=3D1= 773682 socket=3D9 2009-03-04 09:56:13.805 CUT [561402] DEBUG: forked new backend, pid=3D1= 024218 socket=3D9 2009-03-04 09:56:13.805 CUT [561402] DEBUG: server process (PID 1589374= ) exited with exit code 0 2009-03-04 09:56:13.806 CUT [561402] DEBUG: server process (PID 995536)= exited with exit code 0 2009-03-04 09:56:13.806 CUT [561402] DEBUG: server process (PID 688336)= exited with exit code 0 2009-03-04 09:56:13.806 CUT [561402] DEBUG: server process (PID 2035798= ) exited with exit code 0 2009-03-04 09:56:13.807 CUT [561402] DEBUG: server process (PID 1429700= ) exited with exit code 0 2009-03-04 09:56:13.807 CUT [561402] DEBUG: server process (PID 2043960= ) exited with exit code 0 2009-03-04 09:56:13.807 CUT [561402] DEBUG: server process (PID 2158782= ) exited with exit code 0 2009-03-04 09:56:13.808 CUT [561402] DEBUG: server process (PID 2306144= ) exited with exit code 0 2009-03-04 09:56:13.808 CUT [561402] DEBUG: server process (PID 884978)= exited with exit code 0 2009-03-04 09:56:13.808 CUT [561402] DEBUG: server process (PID 1781930= ) exited with exit code 0 2009-03-04 09:56:13.809 CUT [561402] DEBUG: server process (PID 2277572= ) exited with exit code 0 2009-03-04 09:56:13.809 CUT [561402] DEBUG: server process (PID 663656)= exited with exit code 0 2009-03-04 09:56:13.809 CUT [561402] DEBUG: server process (PID 2343006= ) exited with exit code 0 2009-03-04 09:56:13.810 CUT [561402] DEBUG: server process (PID 889026)= exited with exit code 0 2009-03-04 09:56:13.810 CUT [561402] DEBUG: server process (PID 2404546= ) exited with exit code 0 2009-03-04 09:56:13.810 CUT [561402] DEBUG: server process (PID 581830)= exited with exit code 0 2009-03-04 09:56:13.811 CUT [561402] DEBUG: server process (PID 1433846= ) exited with exit code 0 2009-03-04 09:56:13.811 CUT [561402] DEBUG: server process (PID 667690)= exited with exit code 0 2009-03-04 09:56:13.932 CUT [561402] DEBUG: forked new backend, pid=3D6= 67692 socket=3D9 2009-03-04 09:56:13.933 CUT [561402] DEBUG: server process (PID 864402)= exited with exit code 0 2009-03-04 09:56:13.933 CUT [561402] DEBUG: server process (PID 594124)= exited with exit code 0 2009-03-04 09:56:13.934 CUT [561402] DEBUG: server process (PID 852202)= exited with exit code 0 2009-03-04 09:56:13.935 CUT [561402] DEBUG: server process (PID 2433156= ) exited with exit code 0 2009-03-04 09:56:13.935 CUT [561402] DEBUG: server process (PID 2216120= ) exited with exit code 0 2009-03-04 09:56:13.936 CUT [561402] DEBUG: server process (PID 1761484= ) exited with exit code 0 2009-03-04 09:56:13.936 CUT [561402] DEBUG: server process (PID 815268)= exited with exit code 0 2009-03-04 09:56:13.936 CUT [561402] DEBUG: server process (PID 876668)= exited with exit code 0 2009-03-04 09:56:13.937 CUT [561402] DEBUG: server process (PID 897060)= exited with exit code 0 2009-03-04 09:56:13.937 CUT [561402] DEBUG: server process (PID 2199742= ) exited with exit code 0 2009-03-04 09:56:13.937 CUT [561402] DEBUG: server process (PID 913618)= exited with exit code 0 2009-03-04 09:56:13.937 CUT [561402] DEBUG: server process (PID 2334774= ) exited with exit code 0 2009-03-04 09:56:13.984 CUT [561402] DEBUG: forked new backend, pid=3D2= 334776 socket=3D9 2009-03-04 09:56:14.065 CUT [602282] appdb appuser 1.2.3.3 LOG: duration: = 872.457 ms statement: EXECUTE [PREPARE: commit] 2009-03-04 09:56:14.065 CUT [868552] appdb appuser 1.2.3.4 LOG: duration: = 873.756 ms statement: EXECUTE [PREPARE: commit] 2009-03-04 09:56:14.075 CUT [2212000] appdb appuser 1.2.3.5 LOG: duration:= 586.276 ms statement: EXECUTE [PREPARE: commit] 2009-03-04 09:56:14.076 CUT [561402] DEBUG: forked new backend, pid=3D9= 13620 socket=3D9 2009-03-04 09:56:14.095 CUT [561402] DEBUG: forked new backend, pid=3D7= 82510 socket=3D9 2009-03-04 09:56:14.106 CUT [561402] DEBUG: forked new backend, pid=3D2= 285776 socket=3D9 2009-03-04 09:56:14.179 CUT [561402] DEBUG: forked new backend, pid=3D9= 99650 socket=3D9 2009-03-04 09:56:14.194 CUT [561402] DEBUG: forked new backend, pid=3D1= 646620 socket=3D9 2009-03-04 09:56:14.245 CUT [561402] DEBUG: forked new backend, pid=3D9= 21634 socket=3D9 2009-03-04 09:56:14.255 CUT [561402] DEBUG: forked new backend, pid=3D1= 257600 socket=3D9 2009-03-04 09:56:14.265 CUT [561402] DEBUG: forked new backend, pid=3D1= 622114 socket=3D9 2009-03-04 09:56:14.325 CUT [561402] DEBUG: forked new backend, pid=3D1= 519664 socket=3D9 2009-03-04 09:56:14.326 CUT [561402] DEBUG: forked new backend, pid=3D1= 839238 socket=3D9 2009-03-04 09:56:14.335 CUT [561402] DEBUG: forked new backend, pid=3D2= 412680 socket=3D9 2009-03-04 09:56:14.425 CUT [561402] DEBUG: forked new backend, pid=3D2= 007238 socket=3D9 2009-03-04 09:56:14.426 CUT [561402] DEBUG: server process (PID 2363424= ) exited with exit code 0 2009-03-04 09:56:14.426 CUT [561402] DEBUG: server process (PID 1749056= ) exited with exit code 0 2009-03-04 09:56:14.426 CUT [561402] DEBUG: server process (PID 2056242= ) exited with exit code 0 2009-03-04 09:56:14.427 CUT [561402] DEBUG: server process (PID 770156)= exited with exit code 0 2009-03-04 09:56:14.433 CUT [561402] DEBUG: forked new backend, pid=3D7= 70158 socket=3D9 2009-03-04 09:56:14.433 CUT [561402] DEBUG: server process (PID 2379944= ) exited with exit code 0 2009-03-04 09:56:14.484 CUT [561402] DEBUG: forked new backend, pid=3D2= 379946 socket=3D9 2009-03-04 09:56:14.485 CUT [561402] DEBUG: server process (PID 1130616= ) exited with exit code 0 2009-03-04 09:56:14.494 CUT [561402] DEBUG: forked new backend, pid=3D1= 130618 socket=3D9 2009-03-04 09:56:14.505 CUT [561402] DEBUG: forked new backend, pid=3D5= 16338 socket=3D9 2009-03-04 09:56:14.506 CUT [561402] DEBUG: forked new backend, pid=3D2= 199744 socket=3D9 --=20 =EF=BB=BFBrad Nicholson 416-673-4106 Database Administrator, Afilias Canada Corp.