Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1i8ue2-0004lJ-DE for pgsql-performance@arkaria.postgresql.org; Fri, 13 Sep 2019 23:06:26 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1i8udz-0007YJ-2G for pgsql-performance@arkaria.postgresql.org; Fri, 13 Sep 2019 23:06:23 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1i8udy-0007Xy-P4 for pgsql-performance@lists.postgresql.org; Fri, 13 Sep 2019 23:06:22 +0000 Received: from mail-io1-xd42.google.com ([2607:f8b0:4864:20::d42]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1i8udw-0000nF-Dx for pgsql-performance@lists.postgresql.org; Fri, 13 Sep 2019 23:06:22 +0000 Received: by mail-io1-xd42.google.com with SMTP id m11so66206683ioo.0 for ; Fri, 13 Sep 2019 16:06:19 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=telsasoft-com.20150623.gappssmtp.com; s=20150623; h=date:from:to:cc:subject:message-id:references:mime-version :content-disposition:in-reply-to:user-agent; bh=nfJHKx0i9aTWRi0YA/KqUFKL4cNgqnhY2pI8GHwG6b0=; b=nB79+9kyxMxOHjeHCoAOxuEw76jCcFafa+HtugHdIPNl9rCXNQje4RNFJ8KAp05xQ+ fW42XLeJK/m+dhGKc8C1Y9oy7hg0709L36fqXRwf/nHqv/7AwynYRo+6IG0qqA9x/G3N CLIebc1I07QNZ7fD0w8Gh1PuClBxJyOJbREfRLEMKaMO0RhDvqFYUqWGXr90zLOIze8k trkhcycKYjNdiwavqgOM8TeLVQpsGYoAqkhybZiRbJ7MzyXchYSttTvK45sdq1YTKE4e u/P9nwEEnxMI6Q8z2gk1H68nes7JpL46K3B05/1nSkzb2YwrmmwO8ii2jaToBgJJMeS5 0ZvQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:date:from:to:cc:subject:message-id:references :mime-version:content-disposition:in-reply-to:user-agent; bh=nfJHKx0i9aTWRi0YA/KqUFKL4cNgqnhY2pI8GHwG6b0=; b=f23m+D2mXoTVU2Yomb/+mjXihi6fNu4/P46IoureExJy8ieAoCeUXSl/JKuwHbfeNb r0mJxIZLLSwEN7JfmYBnM6F7UB4l5ipDU/3MpzqHG26+86Zf/zGUcxwgOyaI9odaHyip BSnfy7yBcnyB8dWow6hk7OVNRme854JH4NCJ3/tTX4pGIKns8a4zZbWep+fx3LKqxKZk FYByIkhl2/oSXddJ7vIgTtEuWwoc9gLr2SmglR+W5Vhx7HW8J6gCsGiVJEwQ5tel9dAu myqViIYWAnGOnCgCPY9Xet6InPeqcW0MWFleb9oircEdj2VghcJbQPfIw2VDtR28F6il Qmfg== X-Gm-Message-State: APjAAAW4oi9eVqzg70VNxWQEZ3me+BRXGAyasUIuXMiH31nIGixZ5F+t 8C4BBY+LvqaX2XdE3zp/qlhWYA== X-Google-Smtp-Source: APXvYqxjaEa4FL+o/Gixe3yo26Xyr+9GPZwnr74BHLRq7LqmANxXgPllByTN8wuEV+nDKSggUvu+ZQ== X-Received: by 2002:a02:16c5:: with SMTP id a188mr1330658jaa.106.1568415977535; Fri, 13 Sep 2019 16:06:17 -0700 (PDT) Received: from pryzbyj (charmander.telsasoft.com. [50.244.222.1]) by smtp.gmail.com with ESMTPSA id l186sm54068495ioa.54.2019.09.13.16.06.16 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Fri, 13 Sep 2019 16:06:16 -0700 (PDT) Received: by pryzbyj (Postfix, from userid 1000) id E677E800C28; Fri, 13 Sep 2019 18:06:15 -0500 (CDT) Date: Fri, 13 Sep 2019 18:06:15 -0500 From: Justin Pryzby To: Amarendra Konda Cc: pgsql-performance@lists.postgresql.org Subject: Re: Query execution time Vs Cost Message-ID: <20190913230615.GB22849@telsasoft.com> References: MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.5.24 (2015-08-30) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk On Fri, Sep 13, 2019 at 04:38:50PM +0530, Amarendra Konda wrote: > As part of one query tuning, it was observed that query execution time was > more even though cost was decreased. .. > May i know the reason behind in increase in response time, even though cost > was reduced by 6.4 times. The "cost" is postgres model for how expensive a plan will be, based on table statistics, and parameters like seq/rand_page_cost, etc. It's an imperfect model and not exact. > *Initial Query* > > => explain(analyze,buffers,costs) SELECT ku.user_id > > FROM konotor_user ku > > LEFT JOIN agent_details ad > > ON ku.user_id = ad.user_id > > WHERE ku.app_id = '12132818272260' > > AND (ku.user_type = 1 OR ku.user_type = 2) > > AND (ad.deleted isnull OR ad.deleted = 0) > > AND ku.user_id NOT IN ( > > SELECT gu.user_id > > FROM group_user gu > > INNER JOIN groups > > ON gu.group_id = groups.group_id > > AND app_id = ku.app_id > > WHERE gu.user_id = ku.user_id > > AND groups.app_id = ku.app_id > > AND groups.deleted = false); It seems to me the major difference is in group_user JOIN groups. In the fast query, it did > -> Index Only Scan using uk_groupid_userid on group_user gu (cost=0.29..8.30 rows=1 width=16) (actual time=0.001..0.001 rows=0 loops=15832) > Index Cond: ((group_id = groups.group_id) AND (user_id = ku.user_id)) > Heap Fetches: 455 > Buffers: shared hit=32210 => 15832*0.001sec = 15ms In the slow query it did: > -> Index Only Scan using uk_groupid_userid on group_user gu (cost=0.29..115.12 rows=2 width=16) (actual time=0.135..0.135 rows=1 loops=785) > Index Cond: (user_id = ku.user_id) > Heap Fetches: 456 > Buffers: shared hit=45529 => 785*0.115sec = 90ms It scanned using non-leading columns of index, so it took 6x longer even though it did 20x fewer loops. Also it did 456 heap fetches (which were probably nonsequential). Vacuuming the table will probably help; if so, you should consider setting parameter to encourage more frequent autovacuums: | ALTER TABLE group_user SET (AUTOVACUUM_VACUUM_SCALE_FACTOR=0.005); Justin