Very long execution time of "select nextval('..');"

From: mljv(at)planwerk6(dot)de
To: pgsql-general(at)postgresql(dot)org
Subject: Very long execution time of "select nextval('..');"
Date: 2008-01-27 10:51:32
Message-ID: 200801271151.32119.mljv@planwerk6.de
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Hi,

we run postgresql-8.1 on a dedicated debian box 64bit, dual-core CPU, 8GB RAM,
RAID-1.

We select our primary keys with select nextval before we actually insert a
record. In my logs i print every statement which takes longer than 250ms

there are lots of values fetched each day with nextval, but i have about 20-50
statements each day which take up to 17 seconds(!):

LOG: duration: 12636.746 ms statement: EXECUTE <unnamed> [PREPARE: select
nextval ('member_id_seq')]

[it is always the same statement so i just show some numbers:
LOG: duration: 4000.991 ms ...
LOG: duration: 2994.532 ms ...
LOG: duration: 611.167 ms ...
LOG: duration: 17072.196 ms
LOG: duration: 16570.860 ms
LOG: duration: 14816.153 ms
LOG: duration: 265.855 ms
LOG: duration: 1238.361 ms

...
there are about 50 commands per day like this taking longer than 250ms.

i have no idea why something like nextval() can take longer than 1ms.

and if i do it manually it shows up like this:
select nextval ('member_id_seq');
nextval
---------
569304
(1 row)

Time: 0.651 ms

Unfortunatly i can not tell at which time this happens as the log doesn't
show the time of day.

As it is a web application everything above 250ms is not acceptable. Something
like 17seconds (!) is like not working at all.

i observe my server with munin and the load of the server is at the maximum
about 0.5.

Can this be related to the autovacuum process, which we run every 50 minutes?

It seems that something is blocked. But i thought that nextval is never
blocked by anyhing else.

now i looked at some stats
select blks_read, blks_hit from pg_statio_user_sequences;
( i dropped names and relids as they are not important.)

blks_read | blks_hit
-----------+----------
2 | 0
22 | 125
14 | 142
2 | 0
14 | 0
43 | 498
27 | 24
34 | 0
25 | 12
55 | 55
8 | 17
2 | 0
14 | 0
34 | 0
2 | 0
33 | 539
58 | 25
59 | 53
34 | 0
2 | 0
2 | 0
39 | 135
2 | 0
38 | 4
34 | 0
2 | 0
14 | 0
15 | 131
23 | 1223
22 | 147
1 | 2015
10 | 2
13 | 67
34 | 0
34 | 0
32 | 3610
46 | 590

I dont have any clue what is happening but something runs rather suboptimal.

Any help is very appreciated.

kind regards,
Janning

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Shane Ambler 2008-01-27 13:05:59 Re: Very long execution time of "select nextval('..');"
Previous Message Oleg Bartunov 2008-01-27 05:38:53 Re: tsearch2: stop words and stemming separate?