Feedback-ID: id4a34324:Fastmail
Date: Mon, 8 May 2023 12:11:17 -0700
From: Andres Freund <andres@anarazel.de>
To: Alexander Lakhin <exclusion@gmail.com>,
	Michael Paquier <michael.paquier@gmail.com>
Cc: MARK CALLAGHAN <mdcallag@gmail.com>, pgsql-hackers@lists.postgresql.org
Subject: Re: benchmark results comparing versions 15.2 and 16
Message-ID: <20230508191117.v6475ip6hxpwukss@awork3.anarazel.de>
References: <CAFbpF8N4bVFZ+eyWFj_+fZXZFSayk2kJVtZnouUVKGHudiDrSw@mail.gmail.com>
 <b32bed1b-0746-9b20-1472-4bdc9ca66d52@gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <b32bed1b-0746-9b20-1472-4bdc9ca66d52@gmail.com>
Archived-At: <https://www.postgresql.org/message-id/20230508191117.v6475ip6hxpwukss%40awork3.anarazel.de>
Precedence: bulk

Hi,

On 2023-05-08 16:00:01 +0300, Alexander Lakhin wrote:
> This difference is confirmed by multiple test runs. `git bisect` for this
> regression pointed at f193883fc.

I can reproduce a significant regression due to f193883fc of a workload just
running
SELECT CURRENT_TIMESTAMP;

A single session running it on my workstation via pgbench -Mprepared gets
before:
tps = 89359.128359 (without initial connection time)
after:
tps = 83843.585152 (without initial connection time)

Obviously this is an extreme workload, but that nevertheless seems too large
to just accept...


Michael, the commit message notes that there were no measured performance
regression - yet I see one in a trivial test. What were you measuring?


I'm a bit surprised by the magnitude of the regression, but it's not
surprising that there is a performance effect. You're replacing something that
doesn't go through the whole generic function rigamarole, and replace it with
something that does...

Looking at two perf profiles, the biggest noticable difference is

Before:

-    5.51%     0.13%  postgres  postgres  [.] ExecInitResult
   - 5.38% ExecInitResult
      + 2.29% ExecInitResultTupleSlotTL
      - 2.22% ExecAssignProjectionInfo
         - 2.19% ExecBuildProjectionInfo
              0.47% ExecReadyInterpretedExpr
            - 0.43% ExecInitExprRec
               - 0.10% palloc
                    AllocSetAlloc.localalias (inlined)
            + 0.32% expression_tree_walker_impl.localalias (inlined)
            + 0.28% get_typlen
              0.09% ExecPushExprSlots
            + 0.06% MemoryContextAllocZeroAligned
            + 0.04% MemoryContextAllocZeroAligned
              0.02% exprType.localalias (inlined)
      + 0.41% ExecAssignExprContext
      + 0.35% MemoryContextAllocZeroAligned
        0.11% ExecInitQual.localalias (inlined)
   + 0.11% _start
   + 0.02% 0x55b89c764d7f

After:

-    6.57%     0.17%  postgres  postgres  [.] ExecInitResult
   - 6.40% ExecInitResult
      - 3.00% ExecAssignProjectionInfo
         - ExecBuildProjectionInfo
            - 0.91% ExecInitExprRec
               - 0.65% ExecInitFunc
                    0.23% fmgr_info_cxt_security
                  + 0.18% palloc0
                  + 0.07% object_aclcheck
                    0.04% fmgr_info
                 0.05% check_stack_depth
               + 0.05% palloc
            + 0.58% expression_tree_walker_impl.localalias (inlined)
            + 0.55% get_typlen
              0.37% ExecReadyInterpretedExpr
            + 0.11% MemoryContextAllocZeroAligned
              0.09% ExecPushExprSlots
              0.04% exprType.localalias (inlined)
      + 2.77% ExecInitResultTupleSlotTL
      + 0.50% ExecAssignExprContext
      + 0.09% MemoryContextAllocZeroAligned
        0.05% ExecInitQual.localalias (inlined)
   + 0.10% _start

I.e. we spend more time building the expression state for expression
evaluation, because we now go through the generic ExecInitFunc(), instead of
something dedicated. We also now need to do permission checking etc.


I don't think that's the entirety of the regression...

Greetings,

Andres Freund