Re: Looks like merge join planning time is too big, 55 seconds - Mailing list pgsql-performance

From Sergey Burladyan
Subject Re: Looks like merge join planning time is too big, 55 seconds
Date
Msg-id 87li4lusvd.fsf@seb.koffice.internal
Whole thread Raw
In response to Re: Looks like merge join planning time is too big, 55 seconds  (Jeff Janes <jeff.janes@gmail.com>)
Responses Re: Looks like merge join planning time is too big, 55 seconds
List pgsql-performance
Jeff Janes <jeff.janes@gmail.com> writes:

> I'd use strace to find what file handle is being read and written, and
> lsof to figure out what file that is.

I use strace, it is more read then write:
$ cut -d '(' -f 1 /var/tmp/pg.trace | sort | uniq -c | sort -n
     49 select
    708 close
   1021 open
   7356 write
 212744 read
 219650 lseek

top reads:
7859 read(150 open("base/16444/17685.129", O_RDWR|O_CREAT, 0600) = 150
9513 read(149 open("base/16444/17685.128", O_RDWR|O_CREAT, 0600) = 149
10529 read(151 open("base/16444/17685.130", O_RDWR|O_CREAT, 0600) = 151
12155 read(152 open("base/16444/17685.131", O_RDWR|O_CREAT, 0600) = 152
12768 read(154 open("base/16444/17685.133", O_RDWR|O_CREAT, 0600) = 154
16210 read(153 open("base/16444/17685.132", O_RDWR|O_CREAT, 0600) = 153

it is 'items' table:
select relname from pg_class where relfilenode = 17685;
 relname
---------
 items

each read is 8192 bytes, so for EXPLAIN query with two simple index scan, *without* ANALYZE postgres
read (7859 + 9513 + 10529 + 12155 + 12768 + 16210) * 8192 = 565 526 528 bytes from it.

> It looks like it is more write than read, which does seem strange.

Why it read something for simple EXPLAIN, without real executing query? :-)

> Any chance you can create a self-contained test case?

I think I cannot do this, it is ~1 Tb heavily load database. This is at standby server.

PS: two strace for quick and slow explain:

explain
select i.item_id from items i
where item_id = 169946840

$ cut -d '(' -f 1 /var/tmp/pg-all-normal.trace | sort | uniq -c
    313 lseek
    308 open
      2 read
     13 recvfrom
      6 sendto

explain
select i.item_id, u.user_id from items i
left join users u on u.user_id = i.user_id
where item_id = 169946840

$ cut -d '(' -f 1 /var/tmp/pg-all-slow.trace | sort | uniq -c
    963 close
      1 fsync
5093393 lseek
    925 open
6004995 read
     14 recvfrom
      1 rt_sigreturn
      9 select
   4361 semop
      7 sendto
      1 --- SIGUSR1
 685605 write



pgsql-performance by date:

Previous
From: Jeff Janes
Date:
Subject: Re: Looks like merge join planning time is too big, 55 seconds
Next
From: Jeff Janes
Date:
Subject: Re: Performance bug in prepared statement binding in 9.2?