slow prepare, lots of semop calls.

From: David Kerr <dmk(at)mr-paradox(dot)net>
To: pgsql-performance(at)postgresql(dot)org
Subject: slow prepare, lots of semop calls.
Date: 2012-07-13 06:51:22
Message-ID: 20120713065122.GA45804@mr-paradox.net
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

I think my original post here might have gotten caught in a spamtrap, so re-trying, I apologize if it ends
up being a duplicate.

I also forgot to mention that I'm on PG9.1.1 / RHEL 6.2 x64

I believe this is the reason for the behavior i was seeing in this post as well.
http://archives.postgresql.org/pgsql-performance/2012-07/msg00035.php

---
Periodically when restarting my database I find that my PREAPRE time goes through the roof.

This query usually runs in a few ms total. After a recent database restart I find that it's up to 8 seconds
consistantly just to PREPARE.

Even EXPLAIN ends up taking time.

psql -f tt.sql a
Pager usage is off.
Timing is on.
PREPARE
Time: 7965.808 ms
[...]
(1 row)
Time: 1.147 ms

I did an strace on the backend and saw the below.. it seems like there is a problem with grabbing
a semaphore?

strace -p 2826
Process 2826 attached - interrupt to quit
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
[snip 1000s of lines]
select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout)
[snip 1000s of lines]
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(21069900, {{10, 1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
semop(20709441, {{5, -1, 0}}, 1) = 0
brk(0x1207000) = 0x1207000
brk(0x1229000) = 0x1229000
brk(0x124a000) = 0x124a000
mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac9c6b95000
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 934, MSG_NOSIGNAL, NULL, 0) = -1 ENOTCONN (Transport endpoint is not connected)
close(8) = 0
socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 8
connect(8, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 934, MSG_NOSIGNAL, NULL, 0) = 934
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 61, MSG_NOSIGNAL, NULL, 0) = 61
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 89, MSG_NOSIGNAL, NULL, 0) = 89
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 172, MSG_NOSIGNAL, NULL, 0) = 172
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 96, MSG_NOSIGNAL, NULL, 0) = 96
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 157, MSG_NOSIGNAL, NULL, 0) = 157
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 106, MSG_NOSIGNAL, NULL, 0) = 106
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 185, MSG_NOSIGNAL, NULL, 0) = 185
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 93, MSG_NOSIGNAL, NULL, 0) = 93
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 143, MSG_NOSIGNAL, NULL, 0) = 143
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 176, MSG_NOSIGNAL, NULL, 0) = 176
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 168, MSG_NOSIGNAL, NULL, 0) = 168
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 53, MSG_NOSIGNAL, NULL, 0) = 53
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 100, MSG_NOSIGNAL, NULL, 0) = 100
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 96, MSG_NOSIGNAL, NULL, 0) = 96
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 96, MSG_NOSIGNAL, NULL, 0) = 96
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 160, MSG_NOSIGNAL, NULL, 0) = 160
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 98, MSG_NOSIGNAL, NULL, 0) = 98
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 85, MSG_NOSIGNAL, NULL, 0) = 85
sendto(8, "<134>Jul 13 00:21:55 postgres[28"..., 53, MSG_NOSIGNAL, NULL, 0) = 53
sendto(7, "\2\0\0\0\300\3\0\0\3(at)\0\0\t\0\0\0\1\0\0\0\0\0\0\0007\n\0\0t_sc"..., 960, 0, NULL, 0) = 960
sendto(7, "\2\0\0\0\300\3\0\0\3(at)\0\0\t\0\0\0\0\0\0\0\0\0\0\0w\n\0\0t_sc"..., 960, 0, NULL, 0) = 960
sendto(7, "\2\0\0\0\300\3\0\0\3(at)\0\0\t\0\0\0\0\0\0\0\0\0\0\0009\n\0\0t_sc"..., 960, 0, NULL, 0) = 960
sendto(7, "\2\0\0\0\300\3\0\0\3(at)\0\0\t\0\0\0\0\0\0\0\0\0\0\0M\354\0\0t_sc"..., 960, 0, NULL, 0) = 960
sendto(7, "\2\0\0\0 \2\0\0\3(at)\0\0\5\0\0\0\0\0\0\0\0\0\0\0;\n\0\0t_sc"..., 544, 0, NULL, 0) = 544
sendto(7, "\2\0\0\0\350\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\275\4\0\0\0\0\0\0"..., 232, 0, NULL, 0) = 232
sendto(9, "C\0\0\0\fPREPARE\0Z\0\0\0\5I", 19, 0, NULL, 0) = 19
recvfrom(9, "Q\0\0\0\35execute x(1396, 580358);\0", 8192, 0, NULL, NULL) = 30
lseek(18, 0, SEEK_END) = 760832000
lseek(167, 0, SEEK_END) = 8192
lseek(18, 0, SEEK_END) = 760832000
lseek(167, 0, SEEK_END) = 8192
sendto(9, "T\0\0\0025\0\23col_0_0_\0\0\1\t\263\0\2\0\0\0\31\377\377\377\377\377\377"..., 805, 0, NULL, 0) = 805
recvfrom(9, "X\0\0\0\4", 8192, 0, NULL, NULL) = 5
sendto(7, "\2\0\0\0\300\3\0\0\3(at)\0\0\t\0\0\0\1\0\0\0\0\0\0\0007\355\0\0\0\0\0\0"..., 960, 0, NULL, 0) = 960
sendto(7, "\2\0\0\0P\1\0\0\3(at)\0\0\3\0\0\0\0\0\0\0\0\0\0\0\337\373\0\0\0\0\0\0"..., 336, 0, NULL, 0) = 336
exit_group(0) = ?
Process 2826 detached

I checked my semaphores at the os level
ipcs -s|grep postgres| wc -l
54

they all look like:

0x00eb7970 21168207 postgres 600 17
0x00eb7971 21200976 postgres 600 17
0x00eb7972 21233745 postgres 600 17
0x00eb7973 21266514 postgres 600 17
0x00eb7974 21299283 postgres 600 17
0x00eb7975 21332052 postgres 600 17
0x00eb7976 21364821 postgres 600 17

When i restart the DB again things are happy:
psql -f tt.sql a
Pager usage is off.
Timing is on.
PREPARE
Time: 253.850 ms
[...]
(1 row)

Time: 0.891 ms

Any ideas?

Thanks

Browse pgsql-performance by date

  From Date Subject
Next Message Stanislaw Pankevich 2012-07-13 07:50:53 Re: PostgreSQL db, 30 tables with number of rows < 100 (not huge) - the fastest way to clean each non-empty table and reset unique identifier column of empty ones.
Previous Message Jeff Janes 2012-07-13 04:55:22 Re: [PERFORM] DELETE vs TRUNCATE explanation