Received: from malur.postgresql.org ([217.196.149.56])
 by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from
 <pgsql-performance-owner+M50245=pgsql-performance-ar@postgresql.org>)
 id 1V4yJb-0001xF-FC
 for pgsql-performance@arkaria.postgresql.org; Thu, 01 Aug 2013 19:13:35 +0000
Received: from localhost ([127.0.0.1] helo=postgresql.org)
 by malur.postgresql.org with smtp (Exim 4.80) (envelope-from
 <pgsql-performance-owner+M50245=pgsql-performance-ar@postgresql.org>)
 id 1V4yJa-0000be-SU
 for pgsql-performance@arkaria.postgresql.org; Thu, 01 Aug 2013 19:13:34 +0000
Received: from makus.postgresql.org ([2001:4800:7903:4::125])
 by malur.postgresql.org with esmtp (Exim 4.80)
 (envelope-from <eshkinkot@gmail.com>) id 1V4yJZ-0000bY-Vf
 for pgsql-performance@postgresql.org; Thu, 01 Aug 2013 19:13:34 +0000
Received: from mail-la0-x236.google.com ([2a00:1450:4010:c03::236])
 by makus.postgresql.org with esmtp (Exim 4.80)
 (envelope-from <eshkinkot@gmail.com>) id 1V4yJX-0007Z5-Eh
 for pgsql-performance@postgresql.org; Thu, 01 Aug 2013 19:13:33 +0000
Received: by mail-la0-f54.google.com with SMTP id ea20so1734166lab.27
 for <pgsql-performance@postgresql.org>; Thu, 01 Aug 2013 12:13:28 -0700 (PDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113;
 h=from:to:cc:subject:references:date:in-reply-to:message-id
 :user-agent:mime-version:content-type;
 bh=lx7oXgri8aF7snGpnvU2aahL6cvMZJTQFqNhQEW5RcU=;
 b=dLISLrYc5p7S0Cfca3WptjxcsnOEy+qDQHf2sNFI30/dmEBephqrd9cIqhTPOUGr3O
 G2oEGP4M4xAVFeq9Ifo0VnXONWrawoZGOTWx10nreld0zBgcKwFgYV7D2DUIYpG+PIga
 E5eEbaOIhTZZyD7nsvH3Sg+AboUwFdX5MnP+hlQRj+k+bmoqU0dK2omC/USsTFj5WqOI
 eMdzK54Bts9Qf1p9yIJpU4vOWKm+dFi1SOBzhmUeMIQTrFhY9M24hqJ+X1JqN5Ia+mxi
 oSFm5XnrZFWYrV3ejunVMq1WEq22cHigL1OQrlhRDVMoTnOWctkpCUBpTIaYBMZwf6kX
 cidQ==
X-Received: by 10.112.75.194 with SMTP id e2mr2060697lbw.19.1375384408929;
 Thu, 01 Aug 2013 12:13:28 -0700 (PDT)
Received: from seb.koffice.internal (koffice.avito.ru. [195.151.206.25])
 by mx.google.com with ESMTPSA id b8sm1789244lah.0.2013.08.01.12.13.27
 for <multiple recipients>
 (version=TLSv1.2 cipher=RC4-SHA bits=128/128);
 Thu, 01 Aug 2013 12:13:28 -0700 (PDT)
From: Sergey Burladyan <eshkinkot@gmail.com>
To: Jeff Janes <jeff.janes@gmail.com>
Cc: "pgsql-performance\@postgresql.org" <pgsql-performance@postgresql.org>
Subject: Re: Looks like merge join planning time is too big, 55 seconds
References: 
 <CAJ2ymdjK-+LZHFY+cskRq98c_4F1PEfveOVNbNGpWL0Pczy5Ew@mail.gmail.com>
 <8761vpwid4.fsf@seb.koffice.internal>
 <CAMkU=1zyWZEC0YfQ0D4obWWHZqcLoLApUzf-f2+LOVH2ib=s_g@mail.gmail.com>
Date: Thu, 01 Aug 2013 23:13:26 +0400
In-Reply-To: 
 <CAMkU=1zyWZEC0YfQ0D4obWWHZqcLoLApUzf-f2+LOVH2ib=s_g@mail.gmail.com>
 (Jeff Janes's message of "Thu, 1 Aug 2013 11:23:54 -0700")
Message-ID: <87li4lusvd.fsf@seb.koffice.internal>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/24.3 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain
X-Pg-Spam-Score: -2.0 (--)
List-Archive: <http://archives.postgresql.org/pgsql-performance>
List-Help: <mailto:majordomo@postgresql.org?body=help>
List-ID: <pgsql-performance.postgresql.org>
List-Owner: <mailto:pgsql-performance-owner@postgresql.org>
List-Post: <mailto:pgsql-performance@postgresql.org>
List-Subscribe: <mailto:majordomo@postgresql.org?body=sub%20pgsql-performance>
List-Unsubscribe: 
 <mailto:majordomo@postgresql.org?body=unsub%20pgsql-performance>
X-Mailing-List: pgsql-performance
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

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



-- 
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance