Received: from localhost (unknown [200.46.208.211]) by mail.postgresql.org (Postfix) with ESMTP id 88F00632BEB for ; Wed, 6 Jan 2010 00:27:04 -0400 (AST) Received: from mail.postgresql.org ([200.46.204.86]) by localhost (mx1.hub.org [200.46.208.211]) (amavisd-maia, port 10024) with ESMTP id 59693-06 for ; Wed, 6 Jan 2010 04:26:53 +0000 (UTC) X-Greylist: domain auto-whitelisted by SQLgrey-1.7.6 Received: from mail-pw0-f44.google.com (mail-pw0-f44.google.com [209.85.160.44]) by mail.postgresql.org (Postfix) with ESMTP id 194C463233E for ; Wed, 6 Jan 2010 00:26:52 -0400 (AST) Received: by pwi15 with SMTP id 15so11729205pwi.3 for ; Tue, 05 Jan 2010 20:26:51 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:mime-version:sender:received:in-reply-to :references:from:date:x-google-sender-auth:message-id:subject:to:cc :content-type; bh=3LwrCX97CQzde5mdxjVo7+fOmmOlGX/p3yjf9I+/+bI=; b=FDWHUjWJvq0Z0WtDz4bsqtgCphSEcjlXGpA5wNQxS47YC1/0eWos7yleEnYYFQvMx1 NFCFNnWcOi3mAthYOsxPEcqkvhvUKg6eWtH+GS4G02Shl8KvIc9h5jdPTCSVjf/jw/WL Gp8k9UOxCD3zv/qfr/kD/OVNEGcN58sV1mJdA= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:sender:in-reply-to:references:from:date :x-google-sender-auth:message-id:subject:to:cc:content-type; b=h16HydhOg8/Wg0hUFrUf8q35s7RKcCV01yuGx7VUSE6qYq8qel/S6zsgRgRw+rBuYy tbvJl5yjC1i4CaaI2VBeaj0edGE1Ns9FS7HFp6T20udzhIbn5agKedbepTAq/342Cmro WzL3seBKo/7YBwpuEdk3jkXtcLZHvfUZDHYpw= MIME-Version: 1.0 Received: by 10.115.28.17 with SMTP id f17mr8184167waj.27.1262752011675; Tue, 05 Jan 2010 20:26:51 -0800 (PST) In-Reply-To: <4B42ABA2.4010103@2ndquadrant.com> References: <4B42ABA2.4010103@2ndquadrant.com> From: Dmitri Girski Date: Wed, 6 Jan 2010 15:26:30 +1100 X-Google-Sender-Auth: f7da55cd5783436f Message-ID: Subject: Re: pg_connect takes 3.0 seconds To: Greg Smith Cc: pgsql-performance@postgresql.org Content-Type: multipart/alternative; boundary=0016367b69a0186a31047c775d88 X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=1.89 tagged_above=-10 required=5 tests=AWL=-1.300, BAYES_50=0.001, FH_DATE_PAST_20XX=3.188, HTML_MESSAGE=0.001 X-Spam-Level: * X-Archive-Number: 201001/56 X-Sequence-Number: 36936 --0016367b69a0186a31047c775d88 Content-Type: text/plain; charset=ISO-8859-1 Hi Greg, Thank you for idea, reading about checkpints & tuning was very useful. I had a checkpoints logging turned on. I studied a couple of days logs and I there is no clear dependency on checkpoint write. Sometimes it is within a vicinity of 3 seconds CONNECT, sometimes well off it. Also the postgres log file does not show any long operations, which inclines me to think that this is a network connectivity/apache/php issue rather than postgres. Here is the excerpts from logs: Log file from WWW server =========================================================== [06-01-10 14:58:16] UserId=15 Time=3.0032 Req=DB CONNECT =========================================================== Log file from DB server: =========================================================== [2010-01-06 14:58:13 EST] idleLOG: 00000: disconnection: session time: 0:00:00.027 user=pri_user database=data host=192.168.1.10 port=50087 [2010-01-06 14:58:13 EST] idleLOCATION: log_disconnections, postgres.c:3982 [2010-01-06 14:58:18 EST] /usr/lib64/postgresql-8.3/bin/postgresLOG: 00000: connection received: host=192.168.1.10 port=52425 [2010-01-06 14:58:18 EST] /usr/lib64/postgresql-8.3/bin/postgresLOCATION: BackendInitialize, postmaster.c:3027 [2010-01-06 14:58:18 EST] authenticationLOG: 00000: connection authorized: user=pri_user database=data [2010-01-06 14:58:18 EST] authenticationLOCATION: BackendInitialize, postmaster.c:3097 [2010-01-06 14:58:18 EST] idleLOG: 00000: statement: SELECT "fIsLoggedIn"(15) [2010-01-06 14:58:18 EST] idleLOCATION: exec_simple_query, postgres.c:845 [2010-01-06 14:58:18 EST] SELECTLOG: 00000: duration: 39.233 ms [2010-01-06 14:58:18 EST] SELECTLOCATION: exec_simple_query, postgres.c:1056 [2010-01-06 14:58:18 EST] idleLOG: 00000: statement: START TRANSACTION [2010-01-06 14:58:18 EST] idleLOCATION: exec_simple_query, postgres.c:845 [2010-01-06 14:58:18 EST] START TRANSACTIONLOG: 00000: duration: 0.050 ms =========================================================== Cheers, Dmitri. On Tue, Jan 5, 2010 at 2:01 PM, Greg Smith wrote: > Dmitri Girski wrote: > > I am running a PostgreSQL server 8.3.5 with a pretty much standard config. > > The web application server which runs Apache 1.3/PHP2.9 has an > intermittent problem: > pg_connect takes exactly 3.0 seconds. The usual connection time is 0.0045. > The long request happens at approximate rate 1:100. > > > First thing to check for intermittent multi-second delays is whether a > checkpoint is happening at that time. See > http://wiki.postgresql.org/wiki/Logging_Checkpoints for an intro, you'd > want to see if the checkpoints are around the same time as the delays each > time. The default configuration makes checkpoints happen all the time if > there's any significant write traffic on your database. > > -- > Greg Smith 2ndQuadrant Baltimore, MD > PostgreSQL Training, Services and Supportgreg@2ndQuadrant.com www.2ndQuadrant.com > > -- @Gmail --0016367b69a0186a31047c775d88 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Hi Greg,

Thank you for idea, reading about checkpints & tuning= was very useful.

I had a checkpoints l= ogging turned on. I studied a couple of days logs and I there is no clear= =A0dependency=A0on checkpoint write. Sometimes it is within a vicinity of 3= seconds CONNECT, sometimes well off it.

Also the postgres log= file does not show any long operations, which inclines me to think that th= is is a network connectivity/apache/php issue rather than postgres.<= /div>


Here is the excerpts fr= om logs:

Log f= ile from WWW server
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D
[06-01-10 14:58:16] UserId=3D15 =A0Ti= me=3D3.0032 Req=3DDB CONNECT
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D

Log file from DB server:
=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D
[20= 10-01-06 14:58:13 EST] idleLOG: =A000000: disconnection: session time: 0:00= :00.027 user=3Dpri_user database=3Ddata host=3D192.168.1.10 port=3D50087
[2010-01-06 14= :58:13 EST] idleLOCATION: =A0log_disconnections, postgres.c:3982
=
[2010-01-06 14:58:18 EST] /usr/lib64/postgresql-8.3/bin/post= gresLOG: =A000000: connection received: host=3D192.168.1.10 port=3D52425
[2010-01-06 14:58:18 EST] /usr/lib64/postgresql-8.3/bin/postgresLOCATI= ON: =A0BackendInitialize, postmaster.c:3027
[2010-01-06 14:58:18 = EST] authenticationLOG: =A000000: connection authorized: user=3Dpri_user da= tabase=3Ddata
[2010-01-06 14:58:18 EST] authenticationLOCATION: =A0BackendInitialize= , postmaster.c:3097

[2010-01-06 14:58:18 EST] idle= LOG: =A000000: statement: SELECT "fIsLoggedIn"(15)
[2010-01-06 14= :58:18 EST] idleLOCATION: =A0exec_simple_query, postgres.c:845
[2= 010-01-06 14:58:18 EST] SELECTLOG: =A000000: duration: 39.233 ms
= [2010-01-06 14:58:18 EST] SELECTLOCATION: =A0exec_simple_query, postgres.c:= 1056
[2010-01-06 14:58:18 EST] idleLOG: =A000000: statement: START TRANSACT= ION
[2010-01-06 14:58:18 EST] idleLOCATION: =A0exec_simple_query,= postgres.c:845
[2010-01-06 14:58:18 EST] START TRANSACTIONLOG: = =A000000: duration: 0.050 ms
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D

Cheers,
Dmitri.


On = Tue, Jan 5, 2010 at 2:01 PM, Greg Smith <greg@2ndquadrant.com> wrote:
=20
Dmitri Girski wrote:
I am running a PostgreSQL server 8.3.5 with a pretty much standard config.

The web application server which runs Apache 1.3/PHP2.9 =A0has an intermittent problem:
pg_connect takes exactly 3.0 seconds. The usual connection time is 0.0045.
The long request happens at approximate rate 1:100.

First thing to check for intermittent multi-second delays is whether a checkpoint is happening at that time.=A0 See http://wiki.postgresql.org/wiki/Logging_Checkpoints for an intro= , you'd want to see if the checkpoints are around the same time as the delays each time.=A0 The default configuration makes checkpoints happen all the time if there's any significant write traffic on your database.

--=20
Greg Smith    2ndQuadrant   Baltimore, MD
PostgreSQL Training, Services and Support
greg@2ndQuadrant.=
com  www.2ndQu=
adrant.com



--
@Gmail
--0016367b69a0186a31047c775d88--