Thread: Primary key index suddenly became very slow
Hi,
Question:
What may cause a primary key index to suddenly become very slow? Index scan for single row taking 2-3 seconds. A manual vacuum resolved the problem.
Background:
We have a simple table ‘KONTO’ with about 600k rows.
Column | Type | Modifiers
------------------------------+-----------------------------+---------------
id | bigint | not null
...
Indexes:
"konto_pk" PRIMARY KEY, btree (id)
...
Over the weekend we experienced that lookups using the primary key index (‘konto_pk’) became very slow, in the region 2-3s for fetching a single record:
QUERY PLAN
Index Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.052..2094.549 rows=1 loops=1)
Index Cond: (id = 2121172829)
Planning time: 0.376 ms
Execution time: 2094.585 ms
After a manual Vacuum the execution time is OK:
QUERY PLAN
Index Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.037..2.876 rows=1 loops=1)
Index Cond: (id = 2121172829)
Planning time: 0.793 ms
Execution time: 2.971 ms
So things are working OK again, but we would like to know what may cause such a degradation of the index scan, to avoid this happening again? (We are using Postgresql version 9.4.4)
Regards,
Gustav
Additional information:
The problematic row has likely received many hot updates (100k+). Could this be a likely explanation for the high execution time?
Regards,
Gustav
On Feb 8, 2016, at 10:45 AM, Gustav Karlsson <gustav.karlsson@bekk.no> wrote:Hi,Question:What may cause a primary key index to suddenly become very slow? Index scan for single row taking 2-3 seconds. A manual vacuum resolved the problem.Background:We have a simple table ‘KONTO’ with about 600k rows.Column | Type | Modifiers------------------------------+-----------------------------+---------------id | bigint | not null...Indexes:"konto_pk" PRIMARY KEY, btree (id)...Over the weekend we experienced that lookups using the primary key index (‘konto_pk’) became very slow, in the region 2-3s for fetching a single record:QUERY PLANIndex Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.052..2094.549 rows=1 loops=1)Index Cond: (id = 2121172829)Planning time: 0.376 msExecution time: 2094.585 msAfter a manual Vacuum the execution time is OK:QUERY PLANIndex Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.037..2.876 rows=1 loops=1)Index Cond: (id = 2121172829)Planning time: 0.793 msExecution time: 2.971 msSo things are working OK again, but we would like to know what may cause such a degradation of the index scan, to avoid this happening again? (We are using Postgresql version 9.4.4)Regards,Gustav
El lun, 08-02-2016 a las 10:04 +0000, Gustav Karlsson escribió:
Additional information:The problematic row has likely received many hot updates (100k+). Could this be a likely explanation for the high execution time?
Could you check if autovacuum is doing its job with this query:
select * from pg_stat_user_tables where relname='konto' , is it last_autovaccum and last_autoanalyze recent ?
if you don't reduce n_dead_tup in a short time after the bulk process of hot update, it will be a explanation, and also a "idle in transaction" connection could cause it.
This link: https://brandur.org/postgres-queues could help you.
Regards,GustavOn Feb 8, 2016, at 10:45 AM, Gustav Karlsson <gustav.karlsson@bekk.no> wrote:Hi,Question:What may cause a primary key index to suddenly become very slow? Index scan for single row taking 2-3 seconds. A manual vacuum resolved the problem.Background:We have a simple table ‘KONTO’ with about 600k rows.Column | Type | Modifiers------------------------------+-----------------------------+---------------id | bigint | not null...Indexes:"konto_pk" PRIMARY KEY, btree (id)...Over the weekend we experienced that lookups using the primary key index (‘konto_pk’) became very slow, in the region 2-3s for fetching a single record:QUERY PLANIndex Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.052..2094.549 rows=1 loops=1)Index Cond: (id = 2121172829)Planning time: 0.376 msExecution time: 2094.585 msAfter a manual Vacuum the execution time is OK:QUERY PLANIndex Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.037..2.876 rows=1 loops=1)Index Cond: (id = 2121172829)Planning time: 0.793 msExecution time: 2.971 msSo things are working OK again, but we would like to know what may cause such a degradation of the index scan, to avoid this happening again? (We are using Postgresql version 9.4.4)Regards,Gustav
On Mon, Feb 8, 2016 at 9:04 PM, Gustav Karlsson <gustav.karlsson@bekk.no> wrote:
Additional information:The problematic row has likely received many hot updates (100k+). Could this be a likely explanation for the high execution time?
Query immediately after the bulk updates before VACUUM will take longer time. Since the VACUUM might have cleared the dead tuples and might have updated the hint-bits, the query's execution time has become much better.
As the updates are hot, you may not need to consider other factors like, table size growth and if the indexes have grown in size.
Regards,
Venkata B N
Fujitsu Australia
On Feb 8, 2016, at 10:45 AM, Gustav Karlsson <gustav.karlsson@bekk.no> wrote:Hi,Question:What may cause a primary key index to suddenly become very slow? Index scan for single row taking 2-3 seconds. A manual vacuum resolved the problem.Background:We have a simple table ‘KONTO’ with about 600k rows.Column | Type | Modifiers------------------------------+-----------------------------+---------------id | bigint | not null...Indexes:"konto_pk" PRIMARY KEY, btree (id)...Over the weekend we experienced that lookups using the primary key index (‘konto_pk’) became very slow, in the region 2-3s for fetching a single record:QUERY PLANIndex Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.052..2094.549 rows=1 loops=1)Index Cond: (id = 2121172829)Planning time: 0.376 msExecution time: 2094.585 msAfter a manual Vacuum the execution time is OK:QUERY PLANIndex Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.037..2.876 rows=1 loops=1)Index Cond: (id = 2121172829)Planning time: 0.793 msExecution time: 2.971 msSo things are working OK again, but we would like to know what may cause such a degradation of the index scan, to avoid this happening again? (We are using Postgresql version 9.4.4)Regards,Gustav