Re: Confusion and Questions about blocks read - Mailing list 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