To: pgsql-hackers@postgresql.org
From: Grigory Smolkin <g.smolkin@postgrespro.ru>
Subject: Fun fact about autovacuum and orphan temp tables
Message-ID: <7b7f3e98-9753-3fa9-aaa4-b6f8a766c251@postgrespro.ru>
Date: Mon, 5 Sep 2016 14:54:05 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101
 Thunderbird/45.1.0
MIME-Version: 1.0
Content-Type: multipart/alternative;
 boundary="------------1509A57DCE8E829C22953273"
Precedence: bulk
Sender: pgsql-hackers-owner@postgresql.org

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

Hello, hackers!

We were testing how well some application works with PostgreSQL and 
stumbled upon an autovacuum behavior which I fail to understand.
Application in question have a habit to heavily use temporary tables in 
funny ways.
For example it creates A LOT of them.
Which is ok.
Funny part is that it never drops them. So when backend is finally 
terminated, it tries to drop them and fails with error:

FATAL:  out of shared memory
HINT:  You might need to increase max_locks_per_transaction

If I understand that rigth, we are trying to drop all these temp tables 
in one transaction and running out of locks to do so.
After that postgresql.log is flooded at the rate 1k/s with messages like 
that:

LOG:  autovacuum: found orphan temp table "pg_temp_15"."tt38147" in 
database "DB_TEST"

It produces a noticeable load on the system and it`s getting worst with 
every terminated backend or restart.
I did some RTFS and it appears that autovacuum has no intention of 
cleaning that orphan tables unless
it`s wraparound time:

src/backend/postmaster/autovacuum.c
              /* We just ignore it if the owning backend is still active */
  2037             if (backendID == MyBackendId || 
BackendIdGetProc(backendID) == NULL)
  2038             {
  2039                 /*
  2040                  * We found an orphan temp table (which was 
probably left
  2041                  * behind by a crashed backend).  If it's so old 
as to need
  2042                  * vacuum for wraparound, forcibly drop it. 
Otherwise just
  2043                  * log a complaint.
  2044                  */
  2045                 if (wraparound)
  2046                 {
  2047                     ObjectAddress object;
  2048
  2049                     ereport(LOG,
  2050                             (errmsg("autovacuum: dropping orphan 
temp table \"%s\".\"%s\" in database \"%s\"",
  2051 get_namespace_name(classForm->relnamespace),
  2052 NameStr(classForm->relname),
  2053 get_database_name(MyDatabaseId))));
  2054                     object.classId = RelationRelationId;
  2055                     object.objectId = relid;
  2056                     object.objectSubId = 0;
  2057                     performDeletion(&object, DROP_CASCADE, 
PERFORM_DELETION_INTERNAL);
  2058                 }
  2059                 else
  2060                 {
  2061                     ereport(LOG,
  2062                             (errmsg("autovacuum: found orphan 
temp table \"%s\".\"%s\" in database \"%s\"",
  2063 get_namespace_name(classForm->relnamespace),
  2064 NameStr(classForm->relname),
  2065 get_database_name(MyDatabaseId))));
  2066                 }
  2067             }
  2068         }


What is more troubling is that pg_statistic is starting to bloat badly.

LOG:  automatic vacuum of table "DB_TEST.pg_catalog.pg_statistic": index 
scans: 0
         pages: 0 removed, 68225 remain, 0 skipped due to pins
         tuples: 0 removed, 2458382 remain, 2408081 are dead but not yet 
removable
         buffer usage: 146450 hits, 31 misses, 0 dirtied
         avg read rate: 0.010 MB/s, avg write rate: 0.000 MB/s
         system usage: CPU 3.27s/6.92u sec elapsed 23.87 sec

What is the purpose of keeping orphan tables around and not dropping 
them on the spot?


-- 
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company


--------------1509A57DCE8E829C22953273
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 8bit

<html>
  <head>

    <meta http-equiv="content-type" content="text/html; charset=utf-8">
  </head>
  <body bgcolor="#FFFFFF" text="#000000">
    <p>Hello, hackers!</p>
    <p>We were testing how well some application works with PostgreSQL
      and stumbled upon an autovacuum behavior which I fail to
      understand.<br>
      Application in question have a habit to heavily use temporary
      tables in funny ways.<br>
      For example it creates A LOT of them.<br>
      Which is ok.<br>
      Funny part is that it never drops them. So when backend is finally
      terminated, it tries to drop them and fails with error:<br>
      <br>
      FATAL:  out of shared memory<br>
      HINT:  You might need to increase max_locks_per_transaction<br>
      <br>
      If I understand that rigth, we are trying to drop all these temp
      tables in one transaction and running out of locks to do so.<br>
      After that postgresql.log is flooded at the rate 1k/s with
      messages like that:<br>
      <br>
      LOG:  autovacuum: found orphan temp table "pg_temp_15"."tt38147"
      in database "DB_TEST"<br>
      <br>
      It produces a noticeable load on the system and it`s getting worst
      with every terminated backend or restart.<br>
      I did some RTFS and it appears that autovacuum has no intention of
      cleaning that orphan tables unless<br>
      it`s wraparound time:<br>
      <br>
      src/backend/postmaster/autovacuum.c<br>
                   /* We just ignore it if the owning backend is still
      active */<br>
       2037             if (backendID == MyBackendId ||
      BackendIdGetProc(backendID) == NULL)<br>
       2038             {<br>
       2039                 /*<br>
       2040                  * We found an orphan temp table (which was
      probably left<br>
       2041                  * behind by a crashed backend).  If it's so
      old as to need<br>
       2042                  * vacuum for wraparound, forcibly drop it. 
      Otherwise just<br>
       2043                  * log a complaint.<br>
       2044                  */<br>
       2045                 if (wraparound)<br>
       2046                 {<br>
       2047                     ObjectAddress object;<br>
       2048 <br>
       2049                     ereport(LOG,<br>
       2050                             (errmsg("autovacuum: dropping
      orphan temp table \"%s\".\"%s\" in database \"%s\"",<br>
       2051                                 
      get_namespace_name(classForm-&gt;relnamespace),<br>
       2052                                    
      NameStr(classForm-&gt;relname),<br>
       2053                                    
      get_database_name(MyDatabaseId))));<br>
       2054                     object.classId = RelationRelationId;<br>
       2055                     object.objectId = relid;<br>
       2056                     object.objectSubId = 0;<br>
       2057                     performDeletion(&amp;object,
      DROP_CASCADE, PERFORM_DELETION_INTERNAL);<br>
       2058                 }<br>
       2059                 else<br>
       2060                 {<br>
       2061                     ereport(LOG,<br>
       2062                             (errmsg("autovacuum: found
      orphan temp table \"%s\".\"%s\" in database \"%s\"",<br>
       2063                                 
      get_namespace_name(classForm-&gt;relnamespace),<br>
       2064                                    
      NameStr(classForm-&gt;relname),<br>
       2065                                    
      get_database_name(MyDatabaseId))));<br>
       2066                 }<br>
       2067             }<br>
       2068         }<br>
      <br>
      <br>
      What is more troubling is that pg_statistic is starting to bloat
      badly.<br>
      <br>
      LOG:  automatic vacuum of table "DB_TEST.pg_catalog.pg_statistic":
      index scans: 0<br>
              pages: 0 removed, 68225 remain, 0 skipped due to pins<br>
              tuples: 0 removed, 2458382 remain, 2408081 are dead but
      not yet removable<br>
              buffer usage: 146450 hits, 31 misses, 0 dirtied<br>
              avg read rate: 0.010 MB/s, avg write rate: 0.000 MB/s<br>
              system usage: CPU 3.27s/6.92u sec elapsed 23.87 sec<br>
      <br>
      What is the purpose of keeping orphan tables around and not
      dropping them on the spot?<br>
      <br>
    </p>
    <br>
    <pre class="moz-signature" cols="72">-- 
Grigory Smolkin
Postgres Professional: <a class="moz-txt-link-freetext" href="http://www.postgrespro.com">http://www.postgrespro.com</a>
The Russian Postgres Company</pre>
  </body>
</html>

--------------1509A57DCE8E829C22953273--