Message-ID: <53500CBC.9030002@axege.com>
Date: Thu, 17 Apr 2014 19:17:48 +0200
From: Franck Routier <franck.routier@axege.com>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
 rv:24.0) Gecko/20100101 Thunderbird/24.4.0
MIME-Version: 1.0
To: pgsql-performance@postgresql.org
Subject: Re: Fast distinct not working as expected
References: <534FEF1D.5010706@axege.com>
 <CAMkU=1wTdkHmNkt9euasQux8LZ=JbWBcVb+5y1=XH3cYCpPTZw@mail.gmail.com>
In-Reply-To: 
 <CAMkU=1wTdkHmNkt9euasQux8LZ=JbWBcVb+5y1=XH3cYCpPTZw@mail.gmail.com>
Content-Type: multipart/alternative;
 boundary="------------080403070304010300020406"
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

This is a multi-part message in MIME format.
--------------080403070304010300020406
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit

Hi,
>
> That is not equivalent to a distinct.  There must be more to it than that.
Indeed, this query is used in a loop:

CREATE OR REPLACE FUNCTION small_distinct(IN tablename character
varying, IN fieldname character varying, IN sample anyelement DEFAULT
''::character varying)
  RETURNS SETOF anyelement AS
$BODY$
BEGIN
   EXECUTE 'SELECT '||fieldName||' FROM '||tableName||' ORDER BY
'||fieldName
      ||' LIMIT 1'  INTO result;
   WHILE result IS NOT NULL LOOP
      RETURN NEXT;
      EXECUTE 'SELECT '||fieldName||' FROM '||tableName
         ||' WHERE '||fieldName||' > $1 ORDER BY ' || fieldName || '
LIMIT 1'
         INTO result USING result;
   END LOOP;
END;
$BODY$
  LANGUAGE plpgsql VOLATILE
  COST 100
  ROWS 1000;


Since we have the problem, some iteration of the query are still quick
(< 1ms), but others are long (> 5s).
>  
>
>
>
>
>
> My best guess would be that the index got stuffed full of entries for
> rows that are not visible, either because they are not yet committed,
> or have been deleted but are not yet vacuumable.  Do you have any
> long-lived transactions?
There has been a delete on the table (about 20% of the records). Then a
manual VACUUM.
We have recreated the index, but it did not help.

In the explain analyze output, the index scan begins at 5798.912. What
can be happening before that ?

Index Scan using vsn_idx on dwhinv  (cost=0.00..302591122.05
rows=267473826 width=12) (actual time=5798.912..5798.912 rows=1 loops=1)

(Notice the delay is not planning itself, as explain is instantaneous)

>  
>
>
>     - postgresql Version 8.4
>
>
> Newer versions have better diagnostic tools.  An explain (analyze,
> buffers)  would be nice, especially with track_io_timing on.
Yep, we certainly would like to, but this is a distant prod box, with no
access to an online upgrade source, and no planned upgrade for now :-((

Regards,
Franck

--------------080403070304010300020406
Content-Type: text/html; charset=UTF-8
Content-Transfer-Encoding: 8bit

<html>
  <head>
    <meta content="text/html; charset=UTF-8" http-equiv="Content-Type">
  </head>
  <body bgcolor="#FFFFFF" text="#000000">
    Hi,<br>
    <blockquote
cite="mid:CAMkU=1wTdkHmNkt9euasQux8LZ=JbWBcVb+5y1=XH3cYCpPTZw@mail.gmail.com"
      type="cite">
      <div dir="ltr">
        <div class="gmail_extra">
          <div class="gmail_quote">
            <div><br>
            </div>
            <div>That is not equivalent to a distinct.  There must be
              more to it than that.</div>
          </div>
        </div>
      </div>
    </blockquote>
    Indeed, this query is used in a loop:<br>
    <br>
    CREATE OR REPLACE FUNCTION small_distinct(IN tablename character
    varying, IN fieldname character varying, IN sample anyelement
    DEFAULT ''::character varying)<br>
      RETURNS SETOF anyelement AS<br>
    $BODY$<br>
    BEGIN<br>
       EXECUTE 'SELECT '||fieldName||' FROM '||tableName||' ORDER BY
    '||fieldName<br>
          ||' LIMIT 1'  INTO result;<br>
       WHILE result IS NOT NULL LOOP<br>
          RETURN NEXT;<br>
          EXECUTE 'SELECT '||fieldName||' FROM '||tableName<br>
             ||' WHERE '||fieldName||' &gt; $1 ORDER BY ' || fieldName
    || ' LIMIT 1'<br>
             INTO result USING result;<br>
       END LOOP;<br>
    END;<br>
    $BODY$<br>
      LANGUAGE plpgsql VOLATILE<br>
      COST 100<br>
      ROWS 1000;<br>
    <br>
    <br>
    Since we have the problem, some iteration of the query are still
    quick (&lt; 1ms), but others are long (&gt; 5s).<br>
    <blockquote
cite="mid:CAMkU=1wTdkHmNkt9euasQux8LZ=JbWBcVb+5y1=XH3cYCpPTZw@mail.gmail.com"
      type="cite">
      <div dir="ltr">
        <div class="gmail_extra">
          <div class="gmail_quote">
            <div> </div>
            <blockquote class="gmail_quote" style="margin:0px 0px 0px
0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><br>
              <br>
            </blockquote>
            <div><br>
            </div>
            <div><br>
            </div>
            <div>My best guess would be that the index got stuffed full
              of entries for rows that are not visible, either because
              they are not yet committed, or have been deleted but are
              not yet vacuumable.  Do you have any long-lived
              transactions?</div>
          </div>
        </div>
      </div>
    </blockquote>
    There has been a delete on the table (about 20% of the records).
    Then a manual VACUUM.<br>
    We have recreated the index, but it did not help.<br>
    <br>
    In the explain analyze output, the index scan begins at 5798.912.
    What can be happening before that ?<br>
    <pre wrap="">Index Scan using vsn_idx on dwhinv  (cost=0.00..302591122.05
rows=267473826 width=12) (actual time=5798.912..5798.912 rows=1 loops=1)</pre>
    (Notice the delay is not planning itself, as explain is
    instantaneous)<br>
    <br>
    <blockquote
cite="mid:CAMkU=1wTdkHmNkt9euasQux8LZ=JbWBcVb+5y1=XH3cYCpPTZw@mail.gmail.com"
      type="cite">
      <div dir="ltr">
        <div class="gmail_extra">
          <div class="gmail_quote">
            <div> </div>
            <blockquote class="gmail_quote" style="margin:0px 0px 0px
0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><br>
              - postgresql Version 8.4<br>
            </blockquote>
            <div><br>
            </div>
            <div>Newer versions have better diagnostic tools.  An
              explain (analyze, buffers)  would be nice, especially with
              track_io_timing on.</div>
          </div>
        </div>
      </div>
    </blockquote>
    Yep, we certainly would like to, but this is a distant prod box,
    with no access to an online upgrade source, and no planned upgrade
    for now :-((<br>
    <br>
    Regards,<br>
    Franck<br>
  </body>
</html>

--------------080403070304010300020406--