Message-ID: <4FFB9781.60601@ringerc.id.au>
Date: Tue, 10 Jul 2012 10:46:25 +0800
From: Craig Ringer <ringerc@ringerc.id.au>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
	rv:13.0) Gecko/20120605 Thunderbird/13.0
MIME-Version: 1.0
To: Yan Chunlu <springrider@gmail.com>
CC: Albe Laurenz <laurenz.albe@wien.gv.at>, pgsql-performance@postgresql.org
Subject: Re: how could select id=xx so slow?
References: 
 <CAOA66tEJLDOt4JpJ0RwOEsgizfQPWkCHd+SgT7kbiHix_io18A@mail.gmail.com>
	<D960CB61B694CF459DCFB4B0128514C2081BF021@exadv11.host.magwien.gv.at>
	<CAOA66tF8dAzAS9wG381bhp+AiC2LrzcF7MDmOxvgW0p07rMNtw@mail.gmail.com>
	<4FFB848D.7080900@ringerc.id.au>
	<CAOA66tEe4m8OQQ+26AKxrreEF458R-983UVMARZ6zeqEkZxwCQ@mail.gmail.com>
In-Reply-To: 
 <CAOA66tEe4m8OQQ+26AKxrreEF458R-983UVMARZ6zeqEkZxwCQ@mail.gmail.com>
Content-Type: multipart/alternative;
	boundary="------------080809080600070808040201"

This is a multi-part message in MIME format.
--------------080809080600070808040201
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit

On 07/10/2012 10:25 AM, Yan Chunlu wrote:
> I didn't set log_min_duration_statement in the postgresql.conf, but 
> execute
> /dbapi_con.cursor().execute("SET log_min_duration_statement to 30")/
> /for every connection./

OK, same effect: You're only logging slow statements.

It's not at all surprising that BEGIN doesn't appear when a 
log_min_duration_statement is set. It's an incredibly fast operation. 
What's amazing is that it appears even once - that means your database 
must be in serious performance trouble, as BEGIN should take tenths of a 
millisecond on an unloaded system. For example my quick test here:

LOG:  statement: BEGIN;
LOG:  duration: 0.193 ms

... which is actually a lot slower than I expected, but hardly slow 
statement material.

The frequent appearance of slow (multi-second) COMMIT statements in your 
slow statement logs suggests there's enough load on your database that 
there's real contention for disk, and/or that checkpoints are stalling 
transactions.


First, you need to set log_min_messages = 'info' to allow Pg to complain 
about things like checkpoint frequency.

Now temporarily set log_checkpoints = on to record when checkpoints 
happen and how long they take. Most likely you'll find you need to tune 
checkpoint behaviour. Some information, albeit old, on that is here:

http://www.westnet.com/~gsmith/content/postgresql/chkp-bgw-83.htm 
<http://www.westnet.com/%7Egsmith/content/postgresql/chkp-bgw-83.htm>

Basically you might want to try increasing your 
checkpoint_completion_target and making the bgwriter more aggressive - 
assuming that your performance issues are in fact checkpoint related.

It's also possible that they're just overall load, especially if you 
have lots and lots (hundreds) of connections to the database all trying 
to do work at once without any kind of admission control or 
pooling/queuing. In that case, introducing a connection pool like 
PgBouncer may help.

--
Craig Ringer

--------------080809080600070808040201
Content-Type: text/html; charset=ISO-8859-1
Content-Transfer-Encoding: 7bit

<html>
  <head>
    <meta content="text/html; charset=ISO-8859-1"
      http-equiv="Content-Type">
  </head>
  <body bgcolor="#FFFFFF" text="#000000">
    <div class="moz-cite-prefix">On 07/10/2012 10:25 AM, Yan Chunlu
      wrote:</div>
    <blockquote
cite="mid:CAOA66tEe4m8OQQ+26AKxrreEF458R-983UVMARZ6zeqEkZxwCQ@mail.gmail.com"
      type="cite">
      <div>I didn't set&nbsp;log_min_duration_statement in the
        postgresql.conf, but execute</div>
      <div><i>dbapi_con.cursor().execute("SET log_min_duration_statement
          to 30")</i></div>
      <div><i>for every connection.</i></div>
    </blockquote>
    <br>
    OK, same effect: You're only logging slow statements.<br>
    <br>
    It's not at all surprising that BEGIN doesn't appear when a
    log_min_duration_statement is set. It's an incredibly fast
    operation. What's amazing is that it appears even once - that means
    your database must be in serious performance trouble, as BEGIN
    should take tenths of a millisecond on an unloaded system. For
    example my quick test here:<br>
    <br>
    LOG:&nbsp; statement: BEGIN;<br>
    LOG:&nbsp; duration: 0.193 ms<br>
    <br>
    ... which is actually a lot slower than I expected, but hardly slow
    statement material.<br>
    <br>
    The frequent appearance of slow (multi-second) COMMIT statements in
    your slow statement logs suggests there's enough load on your
    database that there's real contention for disk, and/or that
    checkpoints are stalling transactions. <br>
    <br>
    <br>
    First, you need to set log_min_messages = 'info' to allow Pg to
    complain about things like checkpoint frequency.<br>
    <br>
    Now temporarily set log_checkpoints = on to record when checkpoints
    happen and how long they take. Most likely you'll find you need to
    tune checkpoint behaviour. Some information, albeit old, on that is
    here:<br>
    <br>
    &nbsp;
    <meta http-equiv="content-type" content="text/html;
      charset=ISO-8859-1">
    <a
href="http://www.westnet.com/%7Egsmith/content/postgresql/chkp-bgw-83.htm">http://www.westnet.com/~gsmith/content/postgresql/chkp-bgw-83.htm</a><br>
    <br>
    Basically you might want to try increasing your
    checkpoint_completion_target and making the bgwriter more aggressive
    - assuming that your performance issues are in fact checkpoint
    related.<br>
    <br>
    It's also possible that they're just overall load, especially if you
    have lots and lots (hundreds) of connections to the database all
    trying to do work at once without any kind of admission control or
    pooling/queuing. In that case, introducing a connection pool like
    PgBouncer may help.<br>
    <br>
    --<br>
    Craig Ringer<br>
  </body>
</html>

--------------080809080600070808040201--