Re: Re: Heaps of read() syscalls by the postmaster - Mailing list pgsql-hackers

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
read10.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@noris.de  |  ICQ: 20193661
The quote was selected randomly. Really.       |        http://smurf.noris.de/
-- 
Many changes of mind and mood; do not hesitate too long.