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 1iurwU-0007ui-Ll for pgsql-hackers@arkaria.postgresql.org; Fri, 24 Jan 2020 05:55:43 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1iurwT-0001d3-Gv for pgsql-hackers@arkaria.postgresql.org; Fri, 24 Jan 2020 05:55:41 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1iurwS-0001cw-TW for pgsql-hackers@lists.postgresql.org; Fri, 24 Jan 2020 05:55:41 +0000 Received: from mail-yb1-xb2c.google.com ([2607:f8b0:4864:20::b2c]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1iurwQ-0002Du-3K for pgsql-hackers@lists.postgresql.org; Fri, 24 Jan 2020 05:55:39 +0000 Received: by mail-yb1-xb2c.google.com with SMTP id k15so407122ybd.10 for ; Thu, 23 Jan 2020 21:55:37 -0800 (PST) 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=zGlL7M0HwCv2fMFephO+izBaY/fGLQiwTUYFoSw72yQ=; b=CtOrJF590z9If6hHxzJur/95JYch4s8EbLKc8foG4GOnkkoGyHAvbwmYifivpoJqqy /vg1PQnGuvfQTbFF7ah8srfRRRaZOIYjRwdPFEyMgvWFX/5Cj0RCaskfBOgDWwT1Xsmy Cyj1Z7xgRvU+6MSQ+I63fZSF4r7Ocn9YQ+eqxfxTPypWfSJ/0ogCU8ql05yszEjYAVkS nPZIBFnIx3hN5y/r6B6WMCYbGrN055Z4TLG80kjwT3tl/W7M27418g2QOkKnZiuHoGyH XFwg9FH5750CdtY75ezxx+xvo0ameg6dlG3+mEd5dLCjPbps+vCRIuJiPu20VZi/Es82 mHUA== 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=zGlL7M0HwCv2fMFephO+izBaY/fGLQiwTUYFoSw72yQ=; b=FHjTPwFZQbQU7auznw5Apk93tweJb17hUU31yR4UqSuZjz9pVGvN/ToeDk+2wrLKZR s2Bazc/s2UpC1Mff2fseBzJxj+KxVanpORw0bo4aZff0aGWIWWq8DVRrpESBQkvUAMHh IFsCMH3qmjJHmFS6lw1iI/4QkZGXUeOSb/GwHqkxE7xRAwKxPw+c8INXoWpsQh8/DCa4 CAEmkBU0VhKGWsSnc960QXSgRYitU0b0lYfHslF71330Zt9MgczSJC93H54XwynqjVvJ bBJaSfG8DNsuSqn7FuR+YPV84oYCYR12VKEpIjkLNcf1eGJB7l7yXLP4Vh0WqX09dHIq HD5Q== X-Gm-Message-State: APjAAAUK+PUyYv/EqVvo4jmO7Wbekg/N16sshc08VTS9rhutcxTE/qKv 4gQ4SXByCMlLP9t0oc+cYQ8nMw== X-Google-Smtp-Source: APXvYqzNeyHwvCx8UhZBLAxTKBLfyfTvCek36kNjQCT+Z/a/PbPBbJXtnnsvBE8E7SwXqm3rde0oDQ== X-Received: by 2002:a25:e703:: with SMTP id e3mr1150244ybh.55.1579845336434; Thu, 23 Jan 2020 21:55:36 -0800 (PST) Received: from pryzbyj (charmander.telsasoft.com. [50.244.222.1]) by smtp.gmail.com with ESMTPSA id q62sm1904147ywg.76.2020.01.23.21.55.35 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Thu, 23 Jan 2020 21:55:35 -0800 (PST) Received: by pryzbyj (Postfix, from userid 1000) id 4A1018009F4; Thu, 23 Jan 2020 23:55:34 -0600 (CST) Date: Thu, 23 Jan 2020 23:55:34 -0600 From: Justin Pryzby To: Julien Rouhaud Cc: Andres Freund , pgsql-hackers@lists.postgresql.org Subject: Re: BUG #16109: Postgres planning time is high across version (Expose buffer usage during planning in EXPLAIN) Message-ID: <20200124055534.GM13621@telsasoft.com> References: <16109-26a1a88651e90608@postgresql.org> <20191112205506.rvadbx2dnku3paaw@alap3.anarazel.de> 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 Wed, Nov 13, 2019 at 11:39:04AM +0100, Julien Rouhaud wrote: > (moved to -hackers) > > On Tue, Nov 12, 2019 at 9:55 PM Andres Freund wrote: > > > > This last point is more oriented towards other PG developers: I wonder > > if we ought to display buffer statistics for plan time, for EXPLAIN > > (BUFFERS). That'd surely make it easier to discern cases where we > > e.g. access the index and scan a lot of the index from cases where we > > hit some CPU time issue. We should easily be able to get that data, I > > think, we already maintain it, we'd just need to compute the diff > > between pgBufferUsage before / after planning. > > That would be quite interesting to have. I attach as a reference a > quick POC patch to implement it: +1 + result.shared_blks_hit = stop->shared_blks_hit - start->shared_blks_hit; + result.shared_blks_read = stop->shared_blks_read - start->shared_blks_read; + result.shared_blks_dirtied = stop->shared_blks_dirtied - + start->shared_blks_dirtied; [...] I think it would be more readable and maintainable using a macro: #define CALC_BUFF_DIFF(x) result.##x = stop->##x - start->##x CALC_BUFF_DIFF(shared_blks_hit); CALC_BUFF_DIFF(shared_blks_read); CALC_BUFF_DIFF(shared_blks_dirtied); ... #undefine CALC_BUFF_DIFF