Re: Re: Heaps of read() syscalls by the postmaster

Hi,

short add-on:

> The table has been created (via Perl) thusly:
> [...]

and then 300000 records have been inserted, with unique values of 'id'
of course, before doing the updates I mentioned in my previous post. The
backend does 500 read() calls each INSERT, too, which is equally dog-slow.
Trace of testing program's send() calls:

08:59:20.367593 send(3, "Qinsert into bench1 (id,id2,id3,dummy1) values
(2730,2730,2730,\'ABCDEFGHIJ\')\0", 77, 0) = 77
08:59:20.416391 send(3, "Qinsert into bench1 (id,id2,id3,dummy1) values
(2731,2731,2731,\'ABCDEFGHIJ\')\0", 77, 0) = 77
08:59:20.457082 send(3, "Qinsert into bench1 (id,id2,id3,dummy1) values
(2732,2732,2732,\'ABCDEFGHIJ\')\0", 77, 0) = 77
08:59:20.497766 send(3, "Qinsert into bench1 (id,id2,id3,dummy1) values
(2733,2733,2733,\'ABCDEFGHIJ\')\0", 77, 0) = 77
08:59:20.538928 send(3, "Qinsert into bench1 (id,id2,id3,dummy1) values
(2734,2734,2734,\'ABCDEFGHIJ\')\0", 77, 0) = 77

Trace summary of the server while doing this:

$ sudo strace -c -p 27264
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
84.77 1.224299 60 20301 read
10.90 0.157477 8 20573 lseek
3.30 0.047625 1058 45 recv
0.69 0.009914 54 182 write
0.22 0.003168 70 45 send
0.07 0.000955 21 45 45 ioctl
0.06 0.000899 20 45 time
------ ----------- ----------- --------- --------- ----------------
100.00 1.444337 41236 45 total

i.e., 450 or so read() calls per request, apparently serially scannign
for somethign or other:

$ strace -e lseek -p -pid-of-postmaster
lseek(13, 0, SEEK_SET) = 0
lseek(13, 8192, SEEK_SET) = 8192
lseek(13, 16384, SEEK_SET) = 16384
lseek(13, 24576, SEEK_SET) = 24576
lseek(13, 32768, SEEK_SET) = 32768
lseek(13, 40960, SEEK_SET) = 40960
lseek(13, 49152, SEEK_SET) = 49152
lseek(13, 57344, SEEK_SET) = 57344
lseek(13, 65536, SEEK_SET) = 65536
lseek(13, 73728, SEEK_SET) = 73728
lseek(13, 81920, SEEK_SET) = 81920
lseek(13, 90112, SEEK_SET) = 90112
lseek(13, 98304, SEEK_SET) = 98304
lseek(13, 106496, SEEK_SET) = 106496
lseek(13, 114688, SEEK_SET) = 114688

I think you'll agree that this kind of query is supposed to use an index.
test=> explain select * from bench1 where id = 123;
NOTICE: QUERY PLAN:

Index Scan using bench1_index_ on bench1 (cost=0.00..8.14 rows=10 width=24)

EXPLAIN
test=> explain insert into bench1 (id,id2,id3,dummy1) values
test-> (2730,2730,2730,'ABCDEFGHIJ');
NOTICE: QUERY PLAN:

Result (cost=0.00..0.00 rows=0 width=0)

EXPLAIN
test=>

Hmmm... what, no query plan at all???

--
Matthias Urlichs | noris network GmbH | smurf(at)noris(dot)de | ICQ: 20193661
The quote was selected randomly. Really. | http://smurf.noris.de/
--
Many changes of mind and mood; do not hesitate too long.