Re: Confusion and Questions about blocks read

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
> >
>
>