Skip site navigation (1) Skip section navigation (2)

Re: Confusion and Questions about blocks read

From: "Alex Turner" <armtuk(at)gmail(dot)com>
To: "Tom Lane" <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Cc: "Pgsql-Performance ((E-mail))" <pgsql-performance(at)postgresql(dot)org>
Subject: Re: Confusion and Questions about blocks read
Date: 2006-09-22 21:38:23
Message-ID: 33c6269f0609221438s104e36a0sa2855a875469c96b@mail.gmail.com (view raw or flat)
Thread:
Lists: pgsql-performance
Ok - so I have another mystery:

I insert virtually the same rows into two different tables:

trend=# insert into fish select 2, nextval('result_entry_order_seq'),
property_id from property;
INSERT 0 59913
trend=# insert into result_entry select 0,
nextval('result_entry_order_seq'), property_id from property;
INSERT 0 59913
trend=#

but the stats show one as having written 20x as many blocks:

LOG:  statement: insert into fish select 2,
nextval('result_entry_order_seq'), property_id from property;
LOG:  QUERY STATISTICS
DETAIL:  ! system usage stats:
         !       2.098067 elapsed 0.807877 user 1.098833 system sec
         !       [23.875370 user 27.789775 sys total]
         !       0/0 [0/0] filesystem blocks in/out
         !       0/1 [5/62269] page faults/reclaims, 0 [0] swaps
         !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
         !       72/6 [18464/1126] voluntary/involuntary context switches
         ! buffer usage stats:
         !       Shared blocks:      79106 read,        420 written, buffer
hit rate = 79.39%
         !       Local  blocks:          0 read,          0 written, buffer
hit rate = 0.00%
         !       Direct blocks:          0 read,          0 written

LOG:  statement: insert into result_entry select 0,
nextval('result_entry_order_seq'), property_id from property;
LOG:  QUERY STATISTICS
DETAIL:  ! system usage stats:
!       16.963729 elapsed 3.533463 user 1.706740 system sec
!       [27.408833 user 29.497515 sys total]
!       0/0 [0/0] filesystem blocks in/out
!       0/1186 [5/63455] page faults/reclaims, 0 [0] swaps
!       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
!       59/139 [18525/1265] voluntary/involuntary context switches
! buffer usage stats:
!       Shared blocks:     100744 read,       7352 written, buffer hit rate
= 89.71%
!       Local  blocks:          0 read,          0 written, buffer hit rate
= 0.00%
!       Direct blocks:          0 read,          0 written

I understand the read blocks difference, the second had to check indexes
matching the foreign keys.


The table definitions are given below:

trend=# \d fish
           Table "public.fish"
       Column       |  Type   | Modifiers
--------------------+---------+-----------
 result_id          | bigint  |
 result_entry_order | bigint  |
 property_id        | integer |
Indexes:
    "fish_pkey" UNIQUE, btree (result_id, result_entry_order)

trend=# \d result_Entry
                                 Table "public.result_entry"
       Column       |  Type   |                          Modifiers
--------------------+---------+-----------
 result_id          | bigint  |
 result_entry_order | bigint  |
 property_id        | integer |
Indexes:
    "fish_pkey" UNIQUE, btree (result_id, result_entry_order)

The explain analyzes are kind of interesting:

trend=# explain analyze insert into fish select 2,
nextval('result_entry_order_seq'), property_id from property;
                                                   QUERY
PLAN
-----------------------------------------------------------------------------------------------------------------
 Seq Scan on property  (cost=0.00..79295.70 rows=59913 width=8) (actual
time=0.275..1478.681 rows=59913 loops=1)
 Total runtime: 2178.600 ms
(2 rows)

trend=# explain analyze insert into result_entry select 0,
nextval('result_entry_order_seq'), property_id from property;
                                                   QUERY
PLAN
-----------------------------------------------------------------------------------------------------------------
 Seq Scan on property  (cost=0.00..79295.70 rows=59913 width=8) (actual
time=0.118..1473.352 rows=59913 loops=1)
 Trigger for constraint result_entry_result_fk: time=2037.351 calls=59913
 Trigger for constraint result_entry_property_fk: time=8622.260 calls=59913
 Total runtime: 12959.716 ms
(4 rows)


I don't understand the time for the FK check given the size of the tables
they are checking against (and I understand it's the indexes, not the tables
that the actualy check is made):

trend=# select count(*) from result_cache;
 count
-------
     8
(1 row)

trend=#


trend=# select count(*) from property;
 count
-------
 59913
(1 row)

trend=#

The database was just re-indexed, and no changes beyond this insert were
made in that time and result_entry has recently been vacuumed.

Any insight would be greatly appreciated

Alex



On 9/22/06, Alex Turner <armtuk(at)gmail(dot)com> wrote:
>
> ahh.... good point
>
> Thanks
>
> On 9/22/06, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> >
> > "Alex Turner" <armtuk(at)gmail(dot)com> writes:
> > > Home come the query statistics showed that 229066 blocks where read
> > given
> > > that all the blocks in all the tables put together only total 122968?
> >
> > You forgot to count the indexes.  Also, the use of indexscans in the
> > mergejoins probably causes multiple re-reads of some table blocks,
> > depending on just what the physical ordering of the rows is.
> >
> >                         regards, tom lane
> >
>
>

In response to

pgsql-performance by date

Next:From: Arjen van der MeijdenDate: 2006-09-22 21:50:47
Subject: Re: Opteron vs. Xeon "benchmark"
Previous:From: Bucky JordanDate: 2006-09-22 21:18:24
Subject: Re: recommended benchmarks

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group