pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedSelect from sequence in slow query log
3+ messages / 2 participants
[nested] [flat]
* Select from sequence in slow query log
@ 2012-06-01 13:13 Chris Rimmer <chrisr@we7.com>
2012-06-01 13:47 ` Re: Select from sequence in slow query log Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 3+ messages in thread
From: Chris Rimmer @ 2012-06-01 13:13 UTC (permalink / raw)
To: pgsql-performance
While investigating some performance issues I have been looking at slow
queries logged to the postgresql.log file. A strange thing that I have
seen is a series of apparently very slow queries that just select from a
sequence. It is as if access to a sequence is blocked for many sessions and
then released as I get log entries like this appearing:
LOG: duration: 23702.553 ms execute <unnamed>: /* dynamic native SQL
query */ select nextval ('my_sequence') as nextval
LOG: duration: 23673.068 ms execute <unnamed>: /* dynamic native SQL
query */ select nextval ('my_sequence') as nextval
LOG: duration: 23632.729 ms execute <unnamed>: /* dynamic native SQL
query */ select nextval ('my_sequence') as nextval
....(Many similar lines)....
LOG: duration: 3055.057 ms execute <unnamed>: /* dynamic native SQL query
*/ select nextval ('my_sequence') as nextval
LOG: duration: 2377.621 ms execute <unnamed>: /* dynamic native SQL query
*/ select nextval ('my_sequence') as nextval
LOG: duration: 743.732 ms execute <unnamed>: /* dynamic native SQL query
*/ select nextval ('my_sequence') as nextval
The code is being executed via Hibernate, but using
Session.createSQLQuery(), so the SQL above appears in the source as above
(minus the comment) and not as part of any ORM magic. We are using
Postgresql 9.0.
This seems very strange to me. What could cause a sequence to be locked for
such a long time?
The sequence in question has cache set at 1. Would setting this higher make
any difference?
Thanks
Chris
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Select from sequence in slow query log
2012-06-01 13:13 Select from sequence in slow query log Chris Rimmer <chrisr@we7.com>
@ 2012-06-01 13:47 ` Tom Lane <tgl@sss.pgh.pa.us>
2012-06-01 15:41 ` Re: Select from sequence in slow query log Chris Rimmer <chrisr@we7.com>
0 siblings, 1 reply; 3+ messages in thread
From: Tom Lane @ 2012-06-01 13:47 UTC (permalink / raw)
To: Chris Rimmer <chrisr@we7.com>; +Cc: pgsql-performance
Chris Rimmer <chrisr@we7.com> writes:
> While investigating some performance issues I have been looking at slow
> queries logged to the postgresql.log file. A strange thing that I have
> seen is a series of apparently very slow queries that just select from a
> sequence. It is as if access to a sequence is blocked for many sessions and
> then released as I get log entries like this appearing:
> LOG: duration: 23702.553 ms execute <unnamed>: /* dynamic native SQL
> query */ select nextval ('my_sequence') as nextval
> LOG: duration: 23673.068 ms execute <unnamed>: /* dynamic native SQL
> query */ select nextval ('my_sequence') as nextval
> LOG: duration: 23632.729 ms execute <unnamed>: /* dynamic native SQL
> query */ select nextval ('my_sequence') as nextval
> ....(Many similar lines)....
That's pretty weird. What else is being done to that sequence? Is it
only the sequence ops that are slow, or does this happen at times when
everything else is slow too? Can you create a reproducible test case?
regards, tom lane
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Select from sequence in slow query log
2012-06-01 13:13 Select from sequence in slow query log Chris Rimmer <chrisr@we7.com>
2012-06-01 13:47 ` Re: Select from sequence in slow query log Tom Lane <tgl@sss.pgh.pa.us>
@ 2012-06-01 15:41 ` Chris Rimmer <chrisr@we7.com>
0 siblings, 0 replies; 3+ messages in thread
From: Chris Rimmer @ 2012-06-01 15:41 UTC (permalink / raw)
To: pgsql-performance
It looks like this effect only occurs in the middle of the night when there
is some kind of automated dump process going on and the system is under
higher than normal load. I haven't managed to reproduce them outside of
production, but since these oddities don't seem to show up during normal
operations, I'm not worrying too much about them now.
Thanks
Chris
On 1 June 2012 14:47, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Chris Rimmer <chrisr@we7.com> writes:
> > While investigating some performance issues I have been looking at slow
> > queries logged to the postgresql.log file. A strange thing that I have
> > seen is a series of apparently very slow queries that just select from a
> > sequence. It is as if access to a sequence is blocked for many sessions
> and
> > then released as I get log entries like this appearing:
>
> > LOG: duration: 23702.553 ms execute <unnamed>: /* dynamic native SQL
> > query */ select nextval ('my_sequence') as nextval
> > LOG: duration: 23673.068 ms execute <unnamed>: /* dynamic native SQL
> > query */ select nextval ('my_sequence') as nextval
> > LOG: duration: 23632.729 ms execute <unnamed>: /* dynamic native SQL
> > query */ select nextval ('my_sequence') as nextval
> > ....(Many similar lines)....
>
> That's pretty weird. What else is being done to that sequence? Is it
> only the sequence ops that are slow, or does this happen at times when
> everything else is slow too? Can you create a reproducible test case?
>
> regards, tom lane
>
>
^ permalink raw reply [nested|flat] 3+ messages in thread
end of thread, other threads:[~2012-06-01 15:41 UTC | newest]
Thread overview: 3+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2012-06-01 13:13 Select from sequence in slow query log Chris Rimmer <chrisr@we7.com>
2012-06-01 13:47 ` Tom Lane <tgl@sss.pgh.pa.us>
2012-06-01 15:41 ` Chris Rimmer <chrisr@we7.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox