Thread: Unexpected page allocation behavior on insert-only tables

While preparing a replication test setup with 9.0beta1 I noticed strange 
page allocation patterns which Andrew Gierth found interesting enough to 
report here.

I've written a simple tool to generate traffic on a database [1], which 
did about 30 TX/inserts per second to a table. Upon inspecting the data 
in the table, I noticed the expected grouping of tuples which came from 
a single backend to matching pages [2]. The strange part was that the 
pages weren't completely filled but the backends seemed to jump 
arbitrarily from one page to the next [3]. For the table in question 
this resulted in about 10% wasted space.

After issuing a VACUUM on the table the free space map got updated (or 
initialized?) and the backends used the remaining space in the pages, 
though the spurious page allocation continued.


best regards,
Michael

[1] https://workbench.amd.co.at/hg/pgworkshop/file/dc5ab49c99bb/pgexerciser

[2] E.g.:

(0,1) TX1
(0,2) TX5
(0,3) TX7
..
(1,1) TX2
(1,2) TX6
(1,3) TX9

etc.

[3] http://nopaste.narf.at/show/55/
Optimal usage seems to be 136 tuples per page for the table in question.

Michael Renner <michael.renner@amd.co.at> writes:
> I've written a simple tool to generate traffic on a database [1], which 
> did about 30 TX/inserts per second to a table. Upon inspecting the data 
> in the table, I noticed the expected grouping of tuples which came from 
> a single backend to matching pages [2]. The strange part was that the 
> pages weren't completely filled but the backends seemed to jump 
> arbitrarily from one page to the next [3]. For the table in question 
> this resulted in about 10% wasted space.

Which table would that be?  The trigger-driven updates to "auction",
in particular, would certainly guarantee some amount of "wasted" space.
        regards, tom lane

On 16.05.2010 02:16, Tom Lane wrote:
> Michael Renner<michael.renner@amd.co.at>  writes:
>> I've written a simple tool to generate traffic on a database [1], which
>> did about 30 TX/inserts per second to a table. Upon inspecting the data
>> in the table, I noticed the expected grouping of tuples which came from
>> a single backend to matching pages [2]. The strange part was that the
>> pages weren't completely filled but the backends seemed to jump
>> arbitrarily from one page to the next [3]. For the table in question
>> this resulted in about 10% wasted space.
>
> Which table would that be?  The trigger-driven updates to "auction",
> in particular, would certainly guarantee some amount of "wasted" space.

Yeah, the auction table receives heavy updates and gets vacuumed regularly.

The behavior I showed was for the "bid" table, which only gets inserts 
(and triggers the updates for the auction table).

best regards,
Michael

Excerpts from Michael Renner's message of sáb may 15 20:24:36 -0400 2010:
> On 16.05.2010 02:16, Tom Lane wrote:
> > Michael Renner<michael.renner@amd.co.at>  writes:
> >> I've written a simple tool to generate traffic on a database [1], which
> >> did about 30 TX/inserts per second to a table. Upon inspecting the data
> >> in the table, I noticed the expected grouping of tuples which came from
> >> a single backend to matching pages [2]. The strange part was that the
> >> pages weren't completely filled but the backends seemed to jump
> >> arbitrarily from one page to the next [3]. For the table in question
> >> this resulted in about 10% wasted space.
> >
> > Which table would that be?  The trigger-driven updates to "auction",
> > in particular, would certainly guarantee some amount of "wasted" space.
> 
> Yeah, the auction table receives heavy updates and gets vacuumed regularly.
> 
> The behavior I showed was for the "bid" table, which only gets inserts 
> (and triggers the updates for the auction table).

I think this may be related to the smgr_targblock stuff; if the relcache
entry gets invalidated at the wrong time for whatever reason, the
"current page" could be abandoned in favor of extending the rel.  This
has changed since 8.4, but a quick perusal suggests that it should be
less likely on 9.0 than 8.4 but maybe there's something weird going on.
-- 

Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Excerpts from Michael Renner's message of sáb may 15 20:24:36 -0400 2010:
>>> I've written a simple tool to generate traffic on a database [1], which
>>> did about 30 TX/inserts per second to a table. Upon inspecting the data
>>> in the table, I noticed the expected grouping of tuples which came from
>>> a single backend to matching pages [2]. The strange part was that the
>>> pages weren't completely filled but the backends seemed to jump
>>> arbitrarily from one page to the next [3]. For the table in question
>>> this resulted in about 10% wasted space.

> I think this may be related to the smgr_targblock stuff; if the relcache
> entry gets invalidated at the wrong time for whatever reason, the
> "current page" could be abandoned in favor of extending the rel.  This
> has changed since 8.4, but a quick perusal suggests that it should be
> less likely on 9.0 than 8.4 but maybe there's something weird going on.

I found time to try this example finally.  The behavior that I see in
HEAD is even worse than Michael describes: there is room for 136 rows
per block in the bid table, but most blocks have only a few rows.  The
distribution after letting the exerciser run for 500 bids or so is
typically like this:

  #rows  block#
    136  0
      6  1
      5  2
      4  3
      3  4
      5  5
      3  6
      1  7
      4  8
      4  9
    136  10
      6  11
      7  12
      9  13
      9  14
      7  15
      9  16
      7  17
      8  18
      5  19
    136  20
      2  21
      4  22
      4  23
      3  24
      5  25
      3  26
      4  27
      3  28
      2  29
      1  30

Examining the insertion timestamps and bidder numbers (client process
IDs), and correlating this with logged autovacuum activity, makes it
pretty clear what is going on.  See the logic in
RelationGetBufferForTuple, and note that at no time do we have any FSM
data for the bid table:

1. Initially, all backends will decide to insert into block 0.  They do
so until the block is full.

2. At that point, each active backend individually decides it needs to
extend the relation.  They each create a new block and start inserting
into that one, each carefully not telling anyone else about the block
so as to avoid block-level insertion contention.  In the above diagram,
blocks 1-9 are each created by a different backend and the rows inserted
into it come (mostly?) from just one backend.  Block 10's first few rows
also come from the one backend that created it, but it doesn't manage to
fill the block entirely before ...

3. After awhile, autovacuum notices all the insert activity and kicks
off an autoanalyze on the bid table.  When committed, this forces a
relcache flush for each other backend's relcache entry for "bid".
In particular, the smgr targblock gets reset.

4. Now, all the backends again decide to try to insert into the last
available block.  So everybody jams into the partly-filled block 10,
until it gets filled.

5. Lather, rinse, repeat.  Since there are exactly 10 active clients
(by default) in this test program, the repeat distance is exactly 10
blocks.

The obvious thing to do about this would be to not reset targblock
on receipt of a relcache flush event, but we can *not* do that in the
general case.  The reason that that gets reset is so that it's not
left pointing to a no-longer-existent block after a VACUUM truncation.
Maybe we could develop a way to distinguish truncation events from
others, but right now the sinval signaling mechanism can't do that.
This looks like there might be sufficient grounds to do something,
though.

Attached exhibits: contents of relevant columns of the bid table
and postmaster log entries for autovacuum actions during the run.

            regards, tom lane

   ctid   | bidder |             time
----------+--------+-------------------------------
 (0,1)    |      1 | 2010-05-30 22:02:34.315279-04
 (0,2)    |      2 | 2010-05-30 22:02:34.664073-04
 (0,3)    |     10 | 2010-05-30 22:02:34.731018-04
 (0,4)    |      4 | 2010-05-30 22:02:34.787941-04
 (0,5)    |      6 | 2010-05-30 22:02:35.873605-04
 (0,6)    |      2 | 2010-05-30 22:02:36.173464-04
 (0,7)    |      4 | 2010-05-30 22:02:36.563819-04
 (0,8)    |      4 | 2010-05-30 22:02:37.039633-04
 (0,9)    |      3 | 2010-05-30 22:02:37.41705-04
 (0,10)   |      9 | 2010-05-30 22:02:37.66857-04
 (0,11)   |      8 | 2010-05-30 22:02:37.842781-04
 (0,12)   |      6 | 2010-05-30 22:02:39.554071-04
 (0,13)   |      9 | 2010-05-30 22:02:39.659859-04
 (0,14)   |      7 | 2010-05-30 22:02:40.470786-04
 (0,15)   |      6 | 2010-05-30 22:02:40.555843-04
 (0,16)   |      6 | 2010-05-30 22:02:42.587344-04
 (0,17)   |      5 | 2010-05-30 22:02:42.613972-04
 (0,18)   |      1 | 2010-05-30 22:02:42.624847-04
 (0,19)   |      3 | 2010-05-30 22:02:43.330164-04
 (0,20)   |      9 | 2010-05-30 22:02:43.480749-04
 (0,21)   |      3 | 2010-05-30 22:02:44.285052-04
 (0,22)   |      2 | 2010-05-30 22:02:44.810929-04
 (0,23)   |      4 | 2010-05-30 22:02:46.635974-04
 (0,24)   |      7 | 2010-05-30 22:02:47.172423-04
 (0,25)   |      1 | 2010-05-30 22:02:47.281285-04
 (0,26)   |      6 | 2010-05-30 22:02:50.451008-04
 (0,27)   |      3 | 2010-05-30 22:02:51.090318-04
 (0,28)   |      3 | 2010-05-30 22:02:51.649891-04
 (0,29)   |      2 | 2010-05-30 22:02:51.856301-04
 (0,30)   |      9 | 2010-05-30 22:02:52.061757-04
 (0,31)   |      6 | 2010-05-30 22:02:52.237952-04
 (0,32)   |      4 | 2010-05-30 22:02:52.468708-04
 (0,33)   |      5 | 2010-05-30 22:02:52.549329-04
 (0,34)   |      2 | 2010-05-30 22:02:52.584932-04
 (0,35)   |      6 | 2010-05-30 22:02:53.267937-04
 (0,36)   |      3 | 2010-05-30 22:02:53.382076-04
 (0,37)   |      7 | 2010-05-30 22:02:54.311843-04
 (0,38)   |      9 | 2010-05-30 22:02:54.877031-04
 (0,39)   |      7 | 2010-05-30 22:02:55.416411-04
 (0,40)   |      7 | 2010-05-30 22:02:55.757207-04
 (0,41)   |      4 | 2010-05-30 22:02:56.614201-04
 (0,42)   |      1 | 2010-05-30 22:02:56.986382-04
 (0,43)   |      3 | 2010-05-30 22:02:58.075939-04
 (0,44)   |      2 | 2010-05-30 22:02:58.158501-04
 (0,45)   |      2 | 2010-05-30 22:02:58.280742-04
 (0,46)   |      9 | 2010-05-30 22:02:58.366737-04
 (0,47)   |      1 | 2010-05-30 22:02:58.883395-04
 (0,48)   |      7 | 2010-05-30 22:03:00.238707-04
 (0,49)   |      3 | 2010-05-30 22:03:00.457997-04
 (0,50)   |      2 | 2010-05-30 22:03:00.64021-04
 (0,51)   |      3 | 2010-05-30 22:03:00.959877-04
 (0,52)   |      5 | 2010-05-30 22:03:01.984486-04
 (0,53)   |      2 | 2010-05-30 22:03:02.59789-04
 (0,54)   |      3 | 2010-05-30 22:03:02.919283-04
 (0,55)   |      7 | 2010-05-30 22:03:03.175857-04
 (0,56)   |      1 | 2010-05-30 22:03:03.328611-04
 (0,57)   |      9 | 2010-05-30 22:03:05.325658-04
 (0,58)   |      5 | 2010-05-30 22:03:08.137349-04
 (0,59)   |      3 | 2010-05-30 22:03:09.037132-04
 (0,60)   |      5 | 2010-05-30 22:03:09.48715-04
 (0,61)   |      9 | 2010-05-30 22:03:09.795161-04
 (0,62)   |      3 | 2010-05-30 22:03:10.429896-04
 (0,63)   |     12 | 2010-05-30 22:03:10.543446-04
 (0,64)   |      7 | 2010-05-30 22:03:11.805945-04
 (0,65)   |      2 | 2010-05-30 22:03:12.33334-04
 (0,66)   |      7 | 2010-05-30 22:03:13.039753-04
 (0,67)   |      3 | 2010-05-30 22:03:13.775375-04
 (0,68)   |      3 | 2010-05-30 22:03:13.983872-04
 (0,69)   |      5 | 2010-05-30 22:03:14.121341-04
 (0,70)   |      3 | 2010-05-30 22:03:15.650233-04
 (0,71)   |     14 | 2010-05-30 22:03:16.58213-04
 (0,72)   |      5 | 2010-05-30 22:03:18.677188-04
 (0,73)   |      3 | 2010-05-30 22:03:18.824854-04
 (0,74)   |     14 | 2010-05-30 22:03:20.04284-04
 (0,75)   |      3 | 2010-05-30 22:03:20.337673-04
 (0,76)   |      7 | 2010-05-30 22:03:20.845697-04
 (0,77)   |      7 | 2010-05-30 22:03:20.939362-04
 (0,78)   |      7 | 2010-05-30 22:03:20.982737-04
 (0,79)   |      7 | 2010-05-30 22:03:21.169013-04
 (0,80)   |      2 | 2010-05-30 22:03:22.072606-04
 (0,81)   |     13 | 2010-05-30 22:03:22.27614-04
 (0,82)   |      3 | 2010-05-30 22:03:22.30986-04
 (0,83)   |      8 | 2010-05-30 22:03:23.003485-04
 (0,84)   |      5 | 2010-05-30 22:03:23.63513-04
 (0,85)   |      5 | 2010-05-30 22:03:23.856639-04
 (0,86)   |      3 | 2010-05-30 22:03:24.348565-04
 (0,87)   |      5 | 2010-05-30 22:03:24.356068-04
 (0,88)   |      3 | 2010-05-30 22:03:26.732694-04
 (0,89)   |      7 | 2010-05-30 22:03:28.11097-04
 (0,90)   |     14 | 2010-05-30 22:03:28.171367-04
 (0,91)   |      2 | 2010-05-30 22:03:28.361304-04
 (0,92)   |      2 | 2010-05-30 22:03:29.65062-04
 (0,93)   |      8 | 2010-05-30 22:03:29.706961-04
 (0,94)   |      7 | 2010-05-30 22:03:30.561132-04
 (0,95)   |     13 | 2010-05-30 22:03:30.791242-04
 (0,96)   |      3 | 2010-05-30 22:03:31.190208-04
 (0,97)   |      8 | 2010-05-30 22:03:32.924914-04
 (0,98)   |      5 | 2010-05-30 22:03:33.361922-04
 (0,99)   |     13 | 2010-05-30 22:03:34.052696-04
 (0,100)  |      5 | 2010-05-30 22:03:34.247399-04
 (0,101)  |      5 | 2010-05-30 22:03:34.733424-04
 (0,102)  |     14 | 2010-05-30 22:03:35.248725-04
 (0,103)  |      3 | 2010-05-30 22:03:35.422218-04
 (0,104)  |     13 | 2010-05-30 22:03:35.613603-04
 (0,105)  |      2 | 2010-05-30 22:03:36.200464-04
 (0,106)  |      3 | 2010-05-30 22:03:37.072832-04
 (0,107)  |      8 | 2010-05-30 22:03:38.61889-04
 (0,108)  |     13 | 2010-05-30 22:03:39.930287-04
 (0,109)  |      7 | 2010-05-30 22:03:40.190397-04
 (0,110)  |      3 | 2010-05-30 22:03:40.46579-04
 (0,111)  |      3 | 2010-05-30 22:03:40.696981-04
 (0,112)  |      5 | 2010-05-30 22:03:40.712213-04
 (0,113)  |     13 | 2010-05-30 22:03:42.487266-04
 (0,114)  |      3 | 2010-05-30 22:03:42.539229-04
 (0,115)  |      5 | 2010-05-30 22:03:43.863454-04
 (0,116)  |     14 | 2010-05-30 22:03:44.422672-04
 (0,117)  |      3 | 2010-05-30 22:03:45.454489-04
 (0,118)  |      7 | 2010-05-30 22:03:45.559527-04
 (0,119)  |      2 | 2010-05-30 22:03:45.870314-04
 (0,120)  |      3 | 2010-05-30 22:03:46.45456-04
 (0,121)  |      3 | 2010-05-30 22:03:46.700556-04
 (0,122)  |      5 | 2010-05-30 22:03:47.408051-04
 (0,123)  |      5 | 2010-05-30 22:03:47.463331-04
 (0,124)  |      5 | 2010-05-30 22:03:47.494352-04
 (0,125)  |     14 | 2010-05-30 22:03:48.159308-04
 (0,126)  |     13 | 2010-05-30 22:03:48.602946-04
 (0,127)  |     13 | 2010-05-30 22:03:49.936622-04
 (0,128)  |     14 | 2010-05-30 22:03:51.156095-04
 (0,129)  |      8 | 2010-05-30 22:03:52.548205-04
 (0,130)  |      5 | 2010-05-30 22:03:52.971054-04
 (0,131)  |      3 | 2010-05-30 22:03:53.251663-04
 (0,132)  |      5 | 2010-05-30 22:03:53.419514-04
 (0,133)  |     14 | 2010-05-30 22:03:53.904537-04
 (0,134)  |      5 | 2010-05-30 22:03:54.994985-04
 (0,135)  |      5 | 2010-05-30 22:03:55.085393-04
 (0,136)  |      7 | 2010-05-30 22:03:55.383185-04
 (1,1)    |      2 | 2010-05-30 22:03:55.390418-04
 (1,2)    |      2 | 2010-05-30 22:03:56.437267-04
 (1,3)    |      2 | 2010-05-30 22:04:01.628036-04
 (1,4)    |      2 | 2010-05-30 22:04:09.869941-04
 (1,5)    |      2 | 2010-05-30 22:04:19.739467-04
 (1,6)    |      2 | 2010-05-30 22:04:21.082397-04
 (2,1)    |      5 | 2010-05-30 22:03:55.631213-04
 (2,2)    |      5 | 2010-05-30 22:04:00.291552-04
 (2,3)    |     15 | 2010-05-30 22:04:08.675358-04
 (2,4)    |     15 | 2010-05-30 22:04:09.504961-04
 (2,5)    |     15 | 2010-05-30 22:04:17.825315-04
 (3,1)    |      3 | 2010-05-30 22:03:56.185684-04
 (3,2)    |      3 | 2010-05-30 22:03:56.217881-04
 (3,3)    |      3 | 2010-05-30 22:04:05.983922-04
 (3,4)    |      3 | 2010-05-30 22:04:14.693978-04
 (4,1)    |     14 | 2010-05-30 22:03:56.529236-04
 (4,2)    |     14 | 2010-05-30 22:04:06.366691-04
 (4,3)    |     14 | 2010-05-30 22:04:12.969244-04
 (5,1)    |      8 | 2010-05-30 22:03:57.032587-04
 (5,2)    |      8 | 2010-05-30 22:04:04.711173-04
 (5,3)    |      8 | 2010-05-30 22:04:10.385307-04
 (5,4)    |      8 | 2010-05-30 22:04:12.995841-04
 (5,5)    |      8 | 2010-05-30 22:04:21.659177-04
 (6,1)    |      5 | 2010-05-30 22:03:57.736973-04
 (6,2)    |      5 | 2010-05-30 22:04:00.918095-04
 (6,3)    |      5 | 2010-05-30 22:04:16.858052-04
 (7,1)    |      3 | 2010-05-30 22:03:58.593202-04
 (8,1)    |     13 | 2010-05-30 22:03:59.459804-04
 (8,2)    |     13 | 2010-05-30 22:04:07.264812-04
 (8,3)    |     13 | 2010-05-30 22:04:14.346924-04
 (8,4)    |     13 | 2010-05-30 22:04:19.506547-04
 (9,1)    |      5 | 2010-05-30 22:04:00.404804-04
 (9,2)    |      5 | 2010-05-30 22:04:03.546589-04
 (9,3)    |      5 | 2010-05-30 22:04:12.098966-04
 (9,4)    |      5 | 2010-05-30 22:04:19.4649-04
 (10,1)   |      7 | 2010-05-30 22:04:02.963213-04
 (10,2)   |      7 | 2010-05-30 22:04:06.407131-04
 (10,3)   |      7 | 2010-05-30 22:04:15.511039-04
 (10,4)   |      7 | 2010-05-30 22:04:22.054093-04
 (10,5)   |      5 | 2010-05-30 22:04:22.875169-04
 (10,6)   |     15 | 2010-05-30 22:04:24.445067-04
 (10,7)   |     13 | 2010-05-30 22:04:24.563925-04
 (10,8)   |      7 | 2010-05-30 22:04:26.156114-04
 (10,9)   |      3 | 2010-05-30 22:04:26.675876-04
 (10,10)  |      5 | 2010-05-30 22:04:26.808316-04
 (10,11)  |      8 | 2010-05-30 22:04:27.162303-04
 (10,12)  |      5 | 2010-05-30 22:04:27.751572-04
 (10,13)  |      3 | 2010-05-30 22:04:29.172045-04
 (10,14)  |      2 | 2010-05-30 22:04:29.427004-04
 (10,15)  |      2 | 2010-05-30 22:04:30.407821-04
 (10,16)  |      8 | 2010-05-30 22:04:32.837345-04
 (10,17)  |      7 | 2010-05-30 22:04:33.27516-04
 (10,18)  |     15 | 2010-05-30 22:04:33.758701-04
 (10,19)  |      3 | 2010-05-30 22:04:34.482641-04
 (10,20)  |     16 | 2010-05-30 22:04:34.664568-04
 (10,21)  |     15 | 2010-05-30 22:04:36.155-04
 (10,22)  |      3 | 2010-05-30 22:04:36.278901-04
 (10,23)  |      2 | 2010-05-30 22:04:36.50105-04
 (10,24)  |      5 | 2010-05-30 22:04:36.827059-04
 (10,25)  |     13 | 2010-05-30 22:04:38.524347-04
 (10,26)  |      2 | 2010-05-30 22:04:39.239226-04
 (10,27)  |      2 | 2010-05-30 22:04:39.694077-04
 (10,28)  |     15 | 2010-05-30 22:04:39.708984-04
 (10,29)  |      5 | 2010-05-30 22:04:39.884655-04
 (10,30)  |      7 | 2010-05-30 22:04:40.578602-04
 (10,31)  |     15 | 2010-05-30 22:04:40.663863-04
 (10,32)  |      3 | 2010-05-30 22:04:41.088619-04
 (10,33)  |      3 | 2010-05-30 22:04:42.086321-04
 (10,34)  |     16 | 2010-05-30 22:04:42.646463-04
 (10,35)  |      8 | 2010-05-30 22:04:42.805799-04
 (10,36)  |      5 | 2010-05-30 22:04:44.25052-04
 (10,37)  |      3 | 2010-05-30 22:04:44.675792-04
 (10,38)  |     15 | 2010-05-30 22:04:45.40194-04
 (10,39)  |     16 | 2010-05-30 22:04:45.820147-04
 (10,40)  |      7 | 2010-05-30 22:04:45.904989-04
 (10,41)  |      2 | 2010-05-30 22:04:46.501651-04
 (10,42)  |     13 | 2010-05-30 22:04:46.679056-04
 (10,43)  |      3 | 2010-05-30 22:04:47.113848-04
 (10,44)  |     10 | 2010-05-30 22:04:47.426067-04
 (10,45)  |      5 | 2010-05-30 22:04:48.909876-04
 (10,46)  |     10 | 2010-05-30 22:04:49.549874-04
 (10,47)  |      3 | 2010-05-30 22:04:50.459377-04
 (10,48)  |     15 | 2010-05-30 22:04:51.902201-04
 (10,49)  |     13 | 2010-05-30 22:04:52.0388-04
 (10,50)  |     16 | 2010-05-30 22:04:52.865359-04
 (10,51)  |      7 | 2010-05-30 22:04:53.282653-04
 (10,52)  |      3 | 2010-05-30 22:04:53.566923-04
 (10,53)  |      3 | 2010-05-30 22:04:54.862262-04
 (10,54)  |      8 | 2010-05-30 22:04:55.431193-04
 (10,55)  |      2 | 2010-05-30 22:04:55.574083-04
 (10,56)  |     16 | 2010-05-30 22:04:56.372021-04
 (10,57)  |     13 | 2010-05-30 22:04:56.459045-04
 (10,58)  |     10 | 2010-05-30 22:04:56.730657-04
 (10,59)  |     15 | 2010-05-30 22:04:57.978827-04
 (10,60)  |      5 | 2010-05-30 22:04:58.093083-04
 (10,61)  |     13 | 2010-05-30 22:04:59.78596-04
 (10,62)  |      2 | 2010-05-30 22:05:00.162797-04
 (10,63)  |     15 | 2010-05-30 22:05:00.547095-04
 (10,64)  |     16 | 2010-05-30 22:05:00.972174-04
 (10,65)  |      8 | 2010-05-30 22:05:00.999949-04
 (10,66)  |     15 | 2010-05-30 22:05:01.469334-04
 (10,67)  |     10 | 2010-05-30 22:05:02.160411-04
 (10,68)  |      3 | 2010-05-30 22:05:02.302325-04
 (10,69)  |     15 | 2010-05-30 22:05:03.18475-04
 (10,70)  |      5 | 2010-05-30 22:05:03.510688-04
 (10,71)  |      5 | 2010-05-30 22:05:03.887237-04
 (10,72)  |     13 | 2010-05-30 22:05:04.422976-04
 (10,73)  |      8 | 2010-05-30 22:05:04.969423-04
 (10,74)  |      5 | 2010-05-30 22:05:06.002372-04
 (10,75)  |      3 | 2010-05-30 22:05:06.139659-04
 (10,76)  |     16 | 2010-05-30 22:05:06.234012-04
 (10,77)  |      2 | 2010-05-30 22:05:06.925084-04
 (10,78)  |      3 | 2010-05-30 22:05:07.064369-04
 (10,79)  |     13 | 2010-05-30 22:05:08.913288-04
 (10,80)  |     16 | 2010-05-30 22:05:08.958923-04
 (10,81)  |      8 | 2010-05-30 22:05:09.327576-04
 (10,82)  |      5 | 2010-05-30 22:05:09.344259-04
 (10,83)  |     15 | 2010-05-30 22:05:09.547854-04
 (10,84)  |     16 | 2010-05-30 22:05:10.008545-04
 (10,85)  |     15 | 2010-05-30 22:05:10.489665-04
 (10,86)  |     16 | 2010-05-30 22:05:10.780785-04
 (10,87)  |     10 | 2010-05-30 22:05:11.578183-04
 (10,88)  |      3 | 2010-05-30 22:05:11.919329-04
 (10,89)  |      3 | 2010-05-30 22:05:14.299399-04
 (10,90)  |     13 | 2010-05-30 22:05:14.479554-04
 (10,91)  |     10 | 2010-05-30 22:05:14.843091-04
 (10,92)  |     15 | 2010-05-30 22:05:14.968214-04
 (10,93)  |      8 | 2010-05-30 22:05:16.619045-04
 (10,94)  |     10 | 2010-05-30 22:05:17.168592-04
 (10,95)  |     15 | 2010-05-30 22:05:17.909316-04
 (10,96)  |     16 | 2010-05-30 22:05:18.099496-04
 (10,97)  |     15 | 2010-05-30 22:05:18.199018-04
 (10,98)  |      2 | 2010-05-30 22:05:18.392446-04
 (10,99)  |     15 | 2010-05-30 22:05:18.610399-04
 (10,100) |      5 | 2010-05-30 22:05:18.671028-04
 (10,101) |     16 | 2010-05-30 22:05:18.855266-04
 (10,102) |      2 | 2010-05-30 22:05:19.187143-04
 (10,103) |     15 | 2010-05-30 22:05:20.530605-04
 (10,104) |      3 | 2010-05-30 22:05:21.433012-04
 (10,105) |      2 | 2010-05-30 22:05:22.176109-04
 (10,106) |     13 | 2010-05-30 22:05:22.671407-04
 (10,107) |      3 | 2010-05-30 22:05:23.427644-04
 (10,108) |      8 | 2010-05-30 22:05:23.785148-04
 (10,109) |     13 | 2010-05-30 22:05:24.346186-04
 (10,110) |     10 | 2010-05-30 22:05:24.430648-04
 (10,111) |     15 | 2010-05-30 22:05:25.949055-04
 (10,112) |      5 | 2010-05-30 22:05:26.212027-04
 (10,113) |     16 | 2010-05-30 22:05:26.754683-04
 (10,114) |      2 | 2010-05-30 22:05:26.818682-04
 (10,115) |      5 | 2010-05-30 22:05:27.245066-04
 (10,116) |     10 | 2010-05-30 22:05:27.970603-04
 (10,117) |      3 | 2010-05-30 22:05:28.884857-04
 (10,118) |      3 | 2010-05-30 22:05:30.219441-04
 (10,119) |      8 | 2010-05-30 22:05:30.246895-04
 (10,120) |     15 | 2010-05-30 22:05:30.277736-04
 (10,121) |      3 | 2010-05-30 22:05:31.896931-04
 (10,122) |      5 | 2010-05-30 22:05:31.964403-04
 (10,123) |      2 | 2010-05-30 22:05:32.483057-04
 (10,124) |      3 | 2010-05-30 22:05:32.724733-04
 (10,125) |     13 | 2010-05-30 22:05:33.10718-04
 (10,126) |      3 | 2010-05-30 22:05:33.189649-04
 (10,127) |      2 | 2010-05-30 22:05:35.284732-04
 (10,128) |     13 | 2010-05-30 22:05:35.786865-04
 (10,129) |     16 | 2010-05-30 22:05:36.017323-04
 (10,130) |     10 | 2010-05-30 22:05:36.0248-04
 (10,131) |      8 | 2010-05-30 22:05:36.10732-04
 (10,132) |      3 | 2010-05-30 22:05:36.129561-04
 (10,133) |     13 | 2010-05-30 22:05:37.494743-04
 (10,134) |     16 | 2010-05-30 22:05:39.198999-04
 (10,135) |     15 | 2010-05-30 22:05:39.645164-04
 (10,136) |      3 | 2010-05-30 22:05:39.871763-04
 (11,1)   |      2 | 2010-05-30 22:05:40.636137-04
 (11,2)   |      2 | 2010-05-30 22:05:48.185134-04
 (11,3)   |      2 | 2010-05-30 22:05:50.280028-04
 (11,4)   |      2 | 2010-05-30 22:05:52.807023-04
 (11,5)   |     12 | 2010-05-30 22:06:09.049648-04
 (11,6)   |     12 | 2010-05-30 22:06:13.486697-04
 (12,1)   |      5 | 2010-05-30 22:05:41.186159-04
 (12,2)   |      5 | 2010-05-30 22:05:54.04493-04
 (12,3)   |      5 | 2010-05-30 22:05:57.985563-04
 (12,4)   |      5 | 2010-05-30 22:06:01.580222-04
 (12,5)   |      5 | 2010-05-30 22:06:06.030723-04
 (12,6)   |      5 | 2010-05-30 22:06:15.474481-04
 (12,7)   |      5 | 2010-05-30 22:06:17.329733-04
 (13,1)   |      2 | 2010-05-30 22:05:41.75727-04
 (13,2)   |      2 | 2010-05-30 22:05:44.06081-04
 (13,3)   |      2 | 2010-05-30 22:05:51.291318-04
 (13,4)   |      2 | 2010-05-30 22:05:54.793822-04
 (13,5)   |      2 | 2010-05-30 22:05:55.853234-04
 (13,6)   |      2 | 2010-05-30 22:06:04.381489-04
 (13,7)   |      2 | 2010-05-30 22:06:12.41618-04
 (13,8)   |      2 | 2010-05-30 22:06:13.555677-04
 (13,9)   |      2 | 2010-05-30 22:06:16.015511-04
 (14,1)   |      3 | 2010-05-30 22:05:42.119008-04
 (14,2)   |      3 | 2010-05-30 22:05:45.76651-04
 (14,3)   |      3 | 2010-05-30 22:05:51.05622-04
 (14,4)   |      3 | 2010-05-30 22:05:54.668724-04
 (14,5)   |      3 | 2010-05-30 22:05:59.961998-04
 (14,6)   |      3 | 2010-05-30 22:06:07.203422-04
 (14,7)   |      3 | 2010-05-30 22:06:07.873917-04
 (14,8)   |      3 | 2010-05-30 22:06:09.014275-04
 (14,9)   |     13 | 2010-05-30 22:06:19.799128-04
 (15,1)   |     16 | 2010-05-30 22:05:42.659635-04
 (15,2)   |     16 | 2010-05-30 22:05:53.244816-04
 (15,3)   |     16 | 2010-05-30 22:05:55.332821-04
 (15,4)   |     16 | 2010-05-30 22:06:05.250527-04
 (15,5)   |     16 | 2010-05-30 22:06:10.529188-04
 (15,6)   |     16 | 2010-05-30 22:06:19.745598-04
 (15,7)   |     16 | 2010-05-30 22:06:20.086468-04
 (16,1)   |     10 | 2010-05-30 22:05:45.32973-04
 (16,2)   |     10 | 2010-05-30 22:05:48.261647-04
 (16,3)   |     10 | 2010-05-30 22:05:49.104934-04
 (16,4)   |     10 | 2010-05-30 22:05:50.333536-04
 (16,5)   |     10 | 2010-05-30 22:05:54.623456-04
 (16,6)   |     10 | 2010-05-30 22:06:03.914076-04
 (16,7)   |     10 | 2010-05-30 22:06:09.022665-04
 (16,8)   |     10 | 2010-05-30 22:06:12.186486-04
 (16,9)   |     10 | 2010-05-30 22:06:19.077916-04
 (17,1)   |      7 | 2010-05-30 22:05:48.100083-04
 (17,2)   |      7 | 2010-05-30 22:05:54.935016-04
 (17,3)   |      7 | 2010-05-30 22:05:59.325791-04
 (17,4)   |      7 | 2010-05-30 22:06:04.875426-04
 (17,5)   |      7 | 2010-05-30 22:06:12.30384-04
 (17,6)   |      7 | 2010-05-30 22:06:17.132685-04
 (17,7)   |      7 | 2010-05-30 22:06:19.537419-04
 (18,1)   |      3 | 2010-05-30 22:05:48.791994-04
 (18,2)   |      3 | 2010-05-30 22:05:55.695815-04
 (18,3)   |      3 | 2010-05-30 22:06:05.437768-04
 (18,4)   |      3 | 2010-05-30 22:06:07.648808-04
 (18,5)   |      3 | 2010-05-30 22:06:14.87233-04
 (18,6)   |      3 | 2010-05-30 22:06:16.676052-04
 (18,7)   |      3 | 2010-05-30 22:06:20.121767-04
 (18,8)   |      3 | 2010-05-30 22:06:20.989883-04
 (19,1)   |     15 | 2010-05-30 22:05:48.933515-04
 (19,2)   |     15 | 2010-05-30 22:05:53.694439-04
 (19,3)   |     15 | 2010-05-30 22:06:03.067453-04
 (19,4)   |     15 | 2010-05-30 22:06:04.767331-04
 (19,5)   |     15 | 2010-05-30 22:06:13.068965-04
 (20,1)   |     13 | 2010-05-30 22:05:55.206664-04
 (20,2)   |     13 | 2010-05-30 22:06:04.930362-04
 (20,3)   |     13 | 2010-05-30 22:06:13.271518-04
 (20,4)   |     13 | 2010-05-30 22:06:22.365863-04
 (20,5)   |     15 | 2010-05-30 22:06:22.587572-04
 (20,6)   |      5 | 2010-05-30 22:06:23.731535-04
 (20,7)   |      2 | 2010-05-30 22:06:24.080207-04
 (20,8)   |     16 | 2010-05-30 22:06:24.431722-04
 (20,9)   |     10 | 2010-05-30 22:06:26.629308-04
 (20,10)  |      5 | 2010-05-30 22:06:26.651286-04
 (20,11)  |     15 | 2010-05-30 22:06:28.219624-04
 (20,12)  |      7 | 2010-05-30 22:06:28.473442-04
 (20,13)  |     13 | 2010-05-30 22:06:29.284351-04
 (20,14)  |      2 | 2010-05-30 22:06:29.568963-04
 (20,15)  |     15 | 2010-05-30 22:06:30.201825-04
 (20,16)  |      3 | 2010-05-30 22:06:30.589735-04
 (20,17)  |     13 | 2010-05-30 22:06:31.109409-04
 (20,18)  |      2 | 2010-05-30 22:06:31.403439-04
 (20,19)  |     10 | 2010-05-30 22:06:31.775056-04
 (20,20)  |     15 | 2010-05-30 22:06:32.397709-04
 (20,21)  |     13 | 2010-05-30 22:06:32.88401-04
 (20,22)  |     13 | 2010-05-30 22:06:33.269569-04
 (20,23)  |      7 | 2010-05-30 22:06:33.787248-04
 (20,24)  |     16 | 2010-05-30 22:06:34.159114-04
 (20,25)  |     15 | 2010-05-30 22:06:34.52088-04
 (20,26)  |     10 | 2010-05-30 22:06:34.799399-04
 (20,27)  |      7 | 2010-05-30 22:06:36.344221-04
 (20,28)  |      7 | 2010-05-30 22:06:36.84367-04
 (20,29)  |      3 | 2010-05-30 22:06:37.068362-04
 (20,30)  |     15 | 2010-05-30 22:06:38.287501-04
 (20,31)  |      2 | 2010-05-30 22:06:39.575314-04
 (20,32)  |     13 | 2010-05-30 22:06:39.883381-04
 (20,33)  |      1 | 2010-05-30 22:06:41.952922-04
 (20,34)  |     16 | 2010-05-30 22:06:42.71706-04
 (20,35)  |      3 | 2010-05-30 22:06:43.27876-04
 (20,36)  |      7 | 2010-05-30 22:06:43.368793-04
 (20,37)  |     10 | 2010-05-30 22:06:44.046684-04
 (20,38)  |     15 | 2010-05-30 22:06:44.296535-04
 (20,39)  |      2 | 2010-05-30 22:06:44.367201-04
 (20,40)  |     10 | 2010-05-30 22:06:46.807453-04
 (20,41)  |     15 | 2010-05-30 22:06:46.997143-04
 (20,42)  |     13 | 2010-05-30 22:06:47.393655-04
 (20,43)  |      1 | 2010-05-30 22:06:49.074983-04
 (20,44)  |      3 | 2010-05-30 22:06:51.558104-04
 (20,45)  |     16 | 2010-05-30 22:06:52.025233-04
 (20,46)  |     16 | 2010-05-30 22:06:52.143461-04
 (20,47)  |     10 | 2010-05-30 22:06:52.281195-04
 (20,48)  |     15 | 2010-05-30 22:06:52.375523-04
 (20,49)  |      7 | 2010-05-30 22:06:52.867119-04
 (20,50)  |     13 | 2010-05-30 22:06:53.741817-04
 (20,51)  |      6 | 2010-05-30 22:06:54.624369-04
 (20,52)  |     16 | 2010-05-30 22:06:54.947188-04
 (20,53)  |     13 | 2010-05-30 22:06:55.307961-04
 (20,54)  |      3 | 2010-05-30 22:06:55.315587-04
 (20,55)  |     15 | 2010-05-30 22:06:55.81127-04
 (20,56)  |      1 | 2010-05-30 22:06:58.550602-04
 (20,57)  |     16 | 2010-05-30 22:06:58.704792-04
 (20,58)  |     10 | 2010-05-30 22:06:58.785682-04
 (20,59)  |     17 | 2010-05-30 22:06:58.838312-04
 (20,60)  |      7 | 2010-05-30 22:07:00.810356-04
 (20,61)  |     16 | 2010-05-30 22:07:02.215049-04
 (20,62)  |     18 | 2010-05-30 22:07:02.786712-04
 (20,63)  |      3 | 2010-05-30 22:07:02.804707-04
 (20,64)  |      6 | 2010-05-30 22:07:02.880215-04
 (20,65)  |      7 | 2010-05-30 22:07:04.391959-04
 (20,66)  |      7 | 2010-05-30 22:07:04.465536-04
 (20,67)  |     15 | 2010-05-30 22:07:05.132527-04
 (20,68)  |      1 | 2010-05-30 22:07:05.280611-04
 (20,69)  |     15 | 2010-05-30 22:07:07.476944-04
 (20,70)  |      7 | 2010-05-30 22:07:07.858762-04
 (20,71)  |     10 | 2010-05-30 22:07:08.304321-04
 (20,72)  |     18 | 2010-05-30 22:07:08.433794-04
 (20,73)  |      6 | 2010-05-30 22:07:08.865215-04
 (20,74)  |     10 | 2010-05-30 22:07:09.303176-04
 (20,75)  |      7 | 2010-05-30 22:07:09.737608-04
 (20,76)  |     16 | 2010-05-30 22:07:10.470157-04
 (20,77)  |      3 | 2010-05-30 22:07:10.641557-04
 (20,78)  |      6 | 2010-05-30 22:07:10.648976-04
 (20,79)  |      1 | 2010-05-30 22:07:11.16398-04
 (20,80)  |     18 | 2010-05-30 22:07:11.431533-04
 (20,81)  |     18 | 2010-05-30 22:07:12.692684-04
 (20,82)  |     16 | 2010-05-30 22:07:12.74969-04
 (20,83)  |     10 | 2010-05-30 22:07:14.210497-04
 (20,84)  |      1 | 2010-05-30 22:07:15.977093-04
 (20,85)  |     18 | 2010-05-30 22:07:17.151924-04
 (20,86)  |     15 | 2010-05-30 22:07:17.217928-04
 (20,87)  |      1 | 2010-05-30 22:07:17.410405-04
 (20,88)  |     16 | 2010-05-30 22:07:18.210138-04
 (20,89)  |      7 | 2010-05-30 22:07:18.457819-04
 (20,90)  |      3 | 2010-05-30 22:07:19.113064-04
 (20,91)  |      6 | 2010-05-30 22:07:20.415202-04
 (20,92)  |     10 | 2010-05-30 22:07:20.509796-04
 (20,93)  |     15 | 2010-05-30 22:07:20.775745-04
 (20,94)  |      1 | 2010-05-30 22:07:20.938108-04
 (20,95)  |      1 | 2010-05-30 22:07:21.970712-04
 (20,96)  |     18 | 2010-05-30 22:07:22.659728-04
 (20,97)  |      1 | 2010-05-30 22:07:22.919481-04
 (20,98)  |      7 | 2010-05-30 22:07:23.256774-04
 (20,99)  |     18 | 2010-05-30 22:07:23.338927-04
 (20,100) |     10 | 2010-05-30 22:07:23.983037-04
 (20,101) |      1 | 2010-05-30 22:07:25.203907-04
 (20,102) |      1 | 2010-05-30 22:07:25.322318-04
 (20,103) |      1 | 2010-05-30 22:07:25.751673-04
 (20,104) |      3 | 2010-05-30 22:07:25.866868-04
 (20,105) |     16 | 2010-05-30 22:07:26.116402-04
 (20,106) |     10 | 2010-05-30 22:07:26.611058-04
 (20,107) |     16 | 2010-05-30 22:07:27.869843-04
 (20,108) |     18 | 2010-05-30 22:07:27.930089-04
 (20,109) |     15 | 2010-05-30 22:07:28.287146-04
 (20,110) |      1 | 2010-05-30 22:07:28.401998-04
 (20,111) |     16 | 2010-05-30 22:07:28.471901-04
 (20,112) |      6 | 2010-05-30 22:07:28.912135-04
 (20,113) |      1 | 2010-05-30 22:07:29.652131-04
 (20,114) |      1 | 2010-05-30 22:07:29.758991-04
 (20,115) |      1 | 2010-05-30 22:07:31.091658-04
 (20,116) |     15 | 2010-05-30 22:07:31.246403-04
 (20,117) |     18 | 2010-05-30 22:07:31.860414-04
 (20,118) |      1 | 2010-05-30 22:07:32.025975-04
 (20,119) |     16 | 2010-05-30 22:07:32.159433-04
 (20,120) |      7 | 2010-05-30 22:07:32.452886-04
 (20,121) |      7 | 2010-05-30 22:07:33.229635-04
 (20,122) |      1 | 2010-05-30 22:07:33.356003-04
 (20,123) |      3 | 2010-05-30 22:07:33.969782-04
 (20,124) |      1 | 2010-05-30 22:07:34.101896-04
 (20,125) |      1 | 2010-05-30 22:07:36.181644-04
 (20,126) |      3 | 2010-05-30 22:07:36.855136-04
 (20,127) |      3 | 2010-05-30 22:07:37.039873-04
 (20,128) |     16 | 2010-05-30 22:07:37.167042-04
 (20,129) |      1 | 2010-05-30 22:07:37.424978-04
 (20,130) |     15 | 2010-05-30 22:07:37.926044-04
 (20,131) |      6 | 2010-05-30 22:07:37.952489-04
 (20,132) |     16 | 2010-05-30 22:07:38.726096-04
 (20,133) |      1 | 2010-05-30 22:07:39.951693-04
 (20,134) |      1 | 2010-05-30 22:07:40.011907-04
 (20,135) |     18 | 2010-05-30 22:07:40.049167-04
 (20,136) |      1 | 2010-05-30 22:07:40.402348-04
 (21,1)   |      1 | 2010-05-30 22:07:41.032789-04
 (21,2)   |      1 | 2010-05-30 22:07:48.666174-04
 (22,1)   |      7 | 2010-05-30 22:07:42.41283-04
 (22,2)   |      7 | 2010-05-30 22:07:42.612303-04
 (22,3)   |      7 | 2010-05-30 22:07:50.427345-04
 (22,4)   |      7 | 2010-05-30 22:07:58.255948-04
 (23,1)   |      1 | 2010-05-30 22:07:43.145863-04
 (23,2)   |      1 | 2010-05-30 22:07:44.931314-04
 (23,3)   |      1 | 2010-05-30 22:07:53.533069-04
 (23,4)   |      1 | 2010-05-30 22:07:55.065667-04
 (24,1)   |      6 | 2010-05-30 22:07:43.864764-04
 (24,2)   |      6 | 2010-05-30 22:07:53.725297-04
 (24,3)   |      6 | 2010-05-30 22:07:59.040013-04
 (25,1)   |      1 | 2010-05-30 22:07:44.369411-04
 (25,2)   |      1 | 2010-05-30 22:07:47.526095-04
 (25,3)   |      1 | 2010-05-30 22:07:50.876715-04
 (25,4)   |      1 | 2010-05-30 22:07:57.394293-04
 (25,5)   |      1 | 2010-05-30 22:07:59.541561-04
 (26,1)   |     15 | 2010-05-30 22:07:45.956699-04
 (26,2)   |     15 | 2010-05-30 22:07:47.204866-04
 (26,3)   |     15 | 2010-05-30 22:07:52.953162-04
 (27,1)   |      3 | 2010-05-30 22:07:46.005272-04
 (27,2)   |      3 | 2010-05-30 22:07:48.432756-04
 (27,3)   |      3 | 2010-05-30 22:07:50.133422-04
 (27,4)   |      3 | 2010-05-30 22:07:57.679767-04
 (28,1)   |     19 | 2010-05-30 22:07:46.619672-04
 (28,2)   |     19 | 2010-05-30 22:07:47.432573-04
 (28,3)   |     19 | 2010-05-30 22:07:49.967202-04
 (29,1)   |     18 | 2010-05-30 22:07:47.298256-04
 (29,2)   |     18 | 2010-05-30 22:07:51.845929-04
 (30,1)   |     20 | 2010-05-30 22:07:59.062775-04
(541 rows)

LOG:  database system was shut down at 2010-05-30 17:32:38 EDT
LOG:  autovacuum launcher started
LOG:  database system is ready to accept connections
LOG:  received SIGHUP, reloading configuration files
2010-05-30 22:01:54.698 EDT 6405 LOG:  parameter "log_line_prefix" changed to "%m %p "
2010-05-30 22:01:54.698 EDT 6405 LOG:  parameter "log_autovacuum_min_duration" changed to "0"
2010-05-30 22:03:21.846 EDT 8713 LOG:  automatic analyze of table "sqlsim.public.auction" system usage: CPU 0.00s/0.00u
secelapsed 0.03 sec 
2010-05-30 22:03:21.860 EDT 8713 LOG:  automatic analyze of table "sqlsim.public.bid" system usage: CPU 0.00s/0.00u sec
elapsed0.00 sec 
2010-05-30 22:04:21.857 EDT 8720 LOG:  automatic analyze of table "sqlsim.public.auction" system usage: CPU 0.00s/0.00u
secelapsed 0.02 sec 
2010-05-30 22:04:21.871 EDT 8720 LOG:  automatic analyze of table "sqlsim.public.bid" system usage: CPU 0.00s/0.00u sec
elapsed0.00 sec 
2010-05-30 22:05:21.869 EDT 8726 LOG:  automatic analyze of table "sqlsim.public.auction" system usage: CPU 0.00s/0.00u
secelapsed 0.02 sec 
2010-05-30 22:05:21.884 EDT 8726 LOG:  automatic analyze of table "sqlsim.public.bid" system usage: CPU 0.00s/0.00u sec
elapsed0.00 sec 
2010-05-30 22:06:21.881 EDT 8733 LOG:  automatic analyze of table "sqlsim.public.auction" system usage: CPU 0.00s/0.00u
secelapsed 0.02 sec 
2010-05-30 22:06:21.894 EDT 8733 LOG:  automatic analyze of table "sqlsim.public.bid" system usage: CPU 0.00s/0.00u sec
elapsed0.00 sec 
2010-05-30 22:07:21.895 EDT 8740 LOG:  automatic analyze of table "sqlsim.public.auction" system usage: CPU 0.00s/0.00u
secelapsed 0.02 sec 
2010-05-30 22:07:21.910 EDT 8740 LOG:  automatic analyze of table "sqlsim.public.bid" system usage: CPU 0.00s/0.00u sec
elapsed0.00 sec 
2010-05-30 22:08:21.908 EDT 8753 LOG:  automatic analyze of table "sqlsim.public.auction" system usage: CPU 0.00s/0.00u
secelapsed 0.03 sec 

On Sun, May 30, 2010 at 10:42 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> pretty clear what is going on.  See the logic in
> RelationGetBufferForTuple, and note that at no time do we have any FSM
> data for the bid table:

Is this because, in the absence of updates or deletes, we never vacuum it?

> 4. Now, all the backends again decide to try to insert into the last
> available block.  So everybody jams into the partly-filled block 10,
> until it gets filled.

Would it be (a) feasible and (b) useful to inject some entropy into this step?

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise Postgres Company

Tom Lane <tgl@sss.pgh.pa.us> wrote:

> 3. After awhile, autovacuum notices all the insert activity and kicks
> off an autoanalyze on the bid table.  When committed, this forces a
> relcache flush for each other backend's relcache entry for "bid".
> In particular, the smgr targblock gets reset.
> 
> 4. Now, all the backends again decide to try to insert into the last
> available block.  So everybody jams into the partly-filled block 10,
> until it gets filled.

The autovacuum process runs only analyze, but does not run vacuum at 3
because the workload is insert-only. Partially filled pages are never
tracked by freespace map. We could re-run an autovacuum if we saw the
report from the autoanalyze that says the table is low-density,
but the additional vacuum might be overhead in other cases.

> The obvious thing to do about this would be to not reset targblock
> on receipt of a relcache flush event

Even if we don't reset targblock, can we solve the issue when clients
connect and disconnect for each insert? New backends only check the end
of the table, and extend it as same as this case. If we are worrying
about the worst caase, we might need to track newly added pages with
freespace map. Of course we can ignore the case because frequent
connections and disconnections should be always avoided.

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

Robert Haas <robertmhaas@gmail.com> writes:
> On Sun, May 30, 2010 at 10:42 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> pretty clear what is going on. �See the logic in
>> RelationGetBufferForTuple, and note that at no time do we have any FSM
>> data for the bid table:

> Is this because, in the absence of updates or deletes, we never vacuum it?

Right.

>> 4. Now, all the backends again decide to try to insert into the last
>> available block. �So everybody jams into the partly-filled block 10,
>> until it gets filled.

> Would it be (a) feasible and (b) useful to inject some entropy into this step?

Maybe, but at least in this case, the insert rate is not fast enough
that contention for the block is worth worrying about.  IMO this isn't
the part of the cycle that needs fixed.

I guess another path to a fix might be to allow the backends to record
new pages in the FSM immediately at creation.  That might result in more
insert contention, but it'd avoid losing track of the free space
permanently, which is what is happening here (unless something happens
to cause a vacuum).  One reason the current code doesn't do that is that
the old in-memory FSM couldn't efficiently support retail insertion of
single-page data, but the new FSM code hasn't got a problem with that.
        regards, tom lane

On Mon, May 31, 2010 at 3:42 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> note that at no time do we have any FSM
> data for the bid table:
>
>
> 3. After awhile, autovacuum notices all the insert activity and kicks
> off an autoanalyze on the bid table.  When committed, this forces a
> relcache flush for each other backend's relcache entry for "bid".
> In particular, the smgr targblock gets reset.

This is an analyze-only scan? Why does analyze need to issue a
relcache flush? Maybe we only need to issue one for an actual vacuum
which would also populate the fsm?


--
greg

Greg Stark <gsstark@mit.edu> writes:
> This is an analyze-only scan? Why does analyze need to issue a
> relcache flush?

Directly: to cause other backends to pick up the updated pg_class row
(with new relpages/reltuples data).

Indirectly: to cause cached plans for the rel to be invalidated,
so that they can get replanned with updated pg_statistic entries.

So we can't just not have a relcache flush here.  However, we
might be able to decouple targblock reset from the rest of it.
In particular, now that there's a distinction between smgr flush
and relcache flush, maybe we could associate targblock reset with
smgr flush (only) and arrange to not flush the smgr level during
ANALYZE --- basically, smgr flush would only be needed when truncating
or reassigning the relfilenode.  I think this might work out nicely but
haven't chased the details.
        regards, tom lane

I wrote:
> In particular, now that there's a distinction between smgr flush
> and relcache flush, maybe we could associate targblock reset with
> smgr flush (only) and arrange to not flush the smgr level during
> ANALYZE --- basically, smgr flush would only be needed when truncating
> or reassigning the relfilenode.  I think this might work out nicely but
> haven't chased the details.

I looked into that a bit more and decided that it'd be a ticklish
change: the coupling between relcache and smgr cache is pretty tight,
and there just isn't any provision for having an smgr cache entry live
longer than its owning relcache entry.  Even if we could fix it to
work reliably, this approach does nothing for the case where a backend
actually exits after filling just part of a new page, as noted by
Takahiro-san.

The next most promising fix is to have RelationGetBufferForTuple tell
the FSM about the new page immediately on creation.  I made a draft
patch for that (attached).  It fixes Michael's scenario nicely ---
all pages get filled completely --- and a simple test with pgbench
didn't reveal any obvious change in performance.  However there is
clear *potential* for performance loss, due to both the extra FSM
access and the potential for increased contention because of multiple
backends piling into the same new page.  So it would be good to do
some real performance testing on insert-heavy scenarios before we
consider applying this.  Any volunteers?

Note: patch is against HEAD but should work in 8.4, if you reverse out
the use of the rd_targblock access macros.

            regards, tom lane

Index: src/backend/access/heap/hio.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/access/heap/hio.c,v
retrieving revision 1.78
diff -c -r1.78 hio.c
*** src/backend/access/heap/hio.c    9 Feb 2010 21:43:29 -0000    1.78
--- src/backend/access/heap/hio.c    31 May 2010 20:44:29 -0000
***************
*** 354,384 ****
       * is empty (this should never happen, but if it does we don't want to
       * risk wiping out valid data).
       */
      page = BufferGetPage(buffer);

      if (!PageIsNew(page))
          elog(ERROR, "page %u of relation \"%s\" should be empty but is not",
!              BufferGetBlockNumber(buffer),
!              RelationGetRelationName(relation));

      PageInit(page, BufferGetPageSize(buffer), 0);

!     if (len > PageGetHeapFreeSpace(page))
      {
          /* We should not get here given the test at the top */
          elog(PANIC, "tuple is too big: size %lu", (unsigned long) len);
      }

      /*
       * Remember the new page as our target for future insertions.
-      *
-      * XXX should we enter the new page into the free space map immediately,
-      * or just keep it for this backend's exclusive use in the short run
-      * (until VACUUM sees it)?    Seems to depend on whether you expect the
-      * current backend to make more insertions or not, which is probably a
-      * good bet most of the time.  So for now, don't add it to FSM yet.
       */
!     RelationSetTargetBlock(relation, BufferGetBlockNumber(buffer));

      return buffer;
  }
--- 354,388 ----
       * is empty (this should never happen, but if it does we don't want to
       * risk wiping out valid data).
       */
+     targetBlock = BufferGetBlockNumber(buffer);
      page = BufferGetPage(buffer);

      if (!PageIsNew(page))
          elog(ERROR, "page %u of relation \"%s\" should be empty but is not",
!              targetBlock, RelationGetRelationName(relation));

      PageInit(page, BufferGetPageSize(buffer), 0);

!     pageFreeSpace = PageGetHeapFreeSpace(page);
!     if (len > pageFreeSpace)
      {
          /* We should not get here given the test at the top */
          elog(PANIC, "tuple is too big: size %lu", (unsigned long) len);
      }

      /*
+      * If using FSM, mark the page in FSM as having whatever amount of
+      * free space will be left after our insertion.  This is needed so that
+      * the free space won't be forgotten about if this backend doesn't use
+      * it up before exiting or flushing the rel's relcache entry.
+      */
+     if (use_fsm)
+         RecordPageWithFreeSpace(relation, targetBlock, pageFreeSpace - len);
+
+     /*
       * Remember the new page as our target for future insertions.
       */
!     RelationSetTargetBlock(relation, targetBlock);

      return buffer;
  }

Tom Lane wrote:
> I wrote:
> > In particular, now that there's a distinction between smgr flush
> > and relcache flush, maybe we could associate targblock reset with
> > smgr flush (only) and arrange to not flush the smgr level during
> > ANALYZE --- basically, smgr flush would only be needed when truncating
> > or reassigning the relfilenode.  I think this might work out nicely but
> > haven't chased the details.
> 
> I looked into that a bit more and decided that it'd be a ticklish
> change: the coupling between relcache and smgr cache is pretty tight,
> and there just isn't any provision for having an smgr cache entry live
> longer than its owning relcache entry.  Even if we could fix it to
> work reliably, this approach does nothing for the case where a backend
> actually exits after filling just part of a new page, as noted by
> Takahiro-san.
> 
> The next most promising fix is to have RelationGetBufferForTuple tell
> the FSM about the new page immediately on creation.  I made a draft
> patch for that (attached).  It fixes Michael's scenario nicely ---
> all pages get filled completely --- and a simple test with pgbench
> didn't reveal any obvious change in performance.  However there is
> clear *potential* for performance loss, due to both the extra FSM
> access and the potential for increased contention because of multiple
> backends piling into the same new page.  So it would be good to do
> some real performance testing on insert-heavy scenarios before we
> consider applying this.  Any volunteers?
> 
> Note: patch is against HEAD but should work in 8.4, if you reverse out
> the use of the rd_targblock access macros.

Is this something we want to address or should I just add it to the
TODO?

--  Bruce Momjian  <bruce@momjian.us>        http://momjian.us EnterpriseDB
http://enterprisedb.com
 + It's impossible for everything to be true. +

Tom Lane wrote:
> I wrote:
> > In particular, now that there's a distinction between smgr flush
> > and relcache flush, maybe we could associate targblock reset with
> > smgr flush (only) and arrange to not flush the smgr level during
> > ANALYZE --- basically, smgr flush would only be needed when truncating
> > or reassigning the relfilenode.  I think this might work out nicely but
> > haven't chased the details.
> 
> I looked into that a bit more and decided that it'd be a ticklish
> change: the coupling between relcache and smgr cache is pretty tight,
> and there just isn't any provision for having an smgr cache entry live
> longer than its owning relcache entry.  Even if we could fix it to
> work reliably, this approach does nothing for the case where a backend
> actually exits after filling just part of a new page, as noted by
> Takahiro-san.
> 
> The next most promising fix is to have RelationGetBufferForTuple tell
> the FSM about the new page immediately on creation.  I made a draft
> patch for that (attached).  It fixes Michael's scenario nicely ---
> all pages get filled completely --- and a simple test with pgbench
> didn't reveal any obvious change in performance.  However there is
> clear *potential* for performance loss, due to both the extra FSM
> access and the potential for increased contention because of multiple
> backends piling into the same new page.  So it would be good to do
> some real performance testing on insert-heavy scenarios before we
> consider applying this.  Any volunteers?

I have added this TODO:
Allow concurrent inserts to use recently created pages rather thancreating new ones    *
http://archives.postgresql.org/pgsql-hackers/2010-05/msg00853.php
 

--  Bruce Momjian  <bruce@momjian.us>        http://momjian.us EnterpriseDB
http://enterprisedb.com
 + It's impossible for everything to be true. +