Date: Wed, 1 Apr 2020 00:45:37 +0200
From: Tomas Vondra <tomas.vondra@2ndquadrant.com>
To: James Coleman <jtc331@gmail.com>
Cc: Alvaro Herrera <alvherre@2ndquadrant.com>,
	Michael Paquier <michael@paquier.xyz>,
	Rafia Sabih <rafia.pghackers@gmail.com>,
	Peter Geoghegan <pg@bowt.ie>, Simon Riggs <simon@2ndquadrant.com>,
	Shaun Thomas <shaun.thomas@2ndquadrant.com>,
	Dmitry Dolgov <9erthalion6@gmail.com>,
	Alexander Korotkov <a.korotkov@postgrespro.ru>,
	Tom Lane <tgl@sss.pgh.pa.us>,
	PostgreSQL Developers <pgsql-hackers@lists.postgresql.org>,
	Andreas Karlsson <andreas@proxel.se>
Subject: Re: [PATCH] Incremental sort (was: PoC: Partial sort)
Message-ID: <20200331224537.gpmgeivxw6gh35hb@development>
References: 
 <CAAaqYe-rLqNBeCFq0Ruw4RUs5h1xbO2B1BGnjLq0k5Sw3a2gTg@mail.gmail.com>
 <CAAaqYe-M==BwbC47LeMM2HcUGHqCdynNMMyncrBa7t0AGzZGWQ@mail.gmail.com>
 <20200330014442.chqnwfmelm3ejsgr@development>
 <CAAaqYe__vp0QQHgUfiVe+NrcMpECfQgZO8iu2CEwVOcBgA+S0Q@mail.gmail.com>
 <20200330122426.wjdfpqiatv4ybui7@development>
 <CAAaqYe8hK3FpBRkAtTn1L_sETMUivoR=knoLf5by6Q7yLZnzTg@mail.gmail.com>
 <20200331011407.vwz3ektatgqyi6vy@development>
 <CAAaqYe8M-r4esHOg_46w3ojeUEB7KGZ4j2GAi6rLv0B9bHoiPg@mail.gmail.com>
 <20200331215340.bbbrccbehmjb7dbx@development>
 <CAAaqYe-KHM=AL6dCWKQgjHYk2JfTDXOZMLWa3seOJnJrhRNukQ@mail.gmail.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="jips45g6xtf5fou6"
Content-Disposition: inline
In-Reply-To: 
 <CAAaqYe-KHM=AL6dCWKQgjHYk2JfTDXOZMLWa3seOJnJrhRNukQ@mail.gmail.com>
Precedence: bulk


--jips45g6xtf5fou6
Content-Type: text/plain; charset=us-ascii; format=flowed
Content-Disposition: inline

On Tue, Mar 31, 2020 at 06:00:00PM -0400, James Coleman wrote:
>On Tue, Mar 31, 2020 at 5:53 PM Tomas Vondra
><tomas.vondra@2ndquadrant.com> wrote:
>>
>> On Tue, Mar 31, 2020 at 02:23:15PM -0400, James Coleman wrote:
>> >On Mon, Mar 30, 2020 at 9:14 PM Tomas Vondra
>> ><tomas.vondra@2ndquadrant.com> wrote:
>> >>
>> >> The main thing I've been working on today is benchmarking how this
>> >> affects planning. And I'm seeing a regression that worries me a bit,
>> >> unfortunately.
>> >>
>> >> The test I'm doing is pretty simple - build a small table with a bunch
>> >> of columns:
>> >>
>> >>    create table t (a int, b int, c int, d int, e int, f int, g int);
>> >>
>> >>    insert into t select 100*random(), 100*random(), 100*random(),
>> >>      100*random(), 100*random(), 100*random(), 100*random()
>> >>    from generate_series(1,100000) s(i);
>> >>
>> >> and then a number of indexes on subsets of up to 3 columns, as generated
>> >> using the attached build-indexes.py script. And then run a bunch of
>> >> explains (so no actual execution) sorting the data by at least 4 columns
>> >> (to trigger incremental sort paths), measuring timing of the script.
>> >>
>> >> I did a bunch of runs on current master and v46 with incremental sort
>> >> disabled and enabled, and the results look like this:
>> >>
>> >>      master       off        on
>> >>      --------------------------
>> >>      34.609    37.463    37.729
>> >>
>> >> which means about 8-9% regression with incremental sort. Of course, this
>> >> is only for planning time, for execution the impact is going to be much
>> >> smaller. But it's still a bit annoying.
>> >>
>> >> I've suspected this might be either due to the add_partial_path changes
>> >> or the patch adding incremental sort to additional places, so I tested
>> >> those parts individually and the answer is no - add_partial_path changes
>> >> have very small impact (~1%, which might be noise). The regression comes
>> >> mostly from the 0002 part that adds incremental sort. At least in this
>> >> particular test - different tests might behave differently, of course.
>> >>
>> >> The annoying bit is that the overhead does not disappear after disabling
>> >> incremental sort. That suggests this is not merely due to considering
>> >> and creating higher number of paths, but due to something that happens
>> >> before we even look at the GUC ...
>> >>
>> >> I think I've found one such place - if you look at compare_pathkeys, it
>> >> has this check right before the forboth() loop:
>> >>
>> >>      if (keys1 == keys2)
>> >>          return PATHKEYS_EQUAL;
>> >>
>> >> But with incremental sort we don't call pathkeys_contained_in, we call
>> >> pathkeys_common_contained_in instead. And that does not call
>> >> compare_pathkeys and does not have the simple equality check. Adding
>> >> the following check seems to cut the overhead in half, which is nice:
>> >>
>> >>      if (keys1 == keys2)
>> >>      {
>> >>          *n_common = list_length(keys1);
>> >>         return true;
>> >>      }
>> >>
>> >> Not sure where the rest of the regression comes from yet.
>> >
>> >I noticed in the other function we also optimize by checking if either
>> >keys list is NIL, so I tried adding that, and it might have made a
>> >minor difference, but it's hard to tell as it was under 1%.
>> >
>>
>> Which other function? I don't see this optimization in compare_pathkeys,
>> that only checks key1/key2 after the forboth loop, but that's something
>> different.
>
>pathkeys_useful_for_ordering checks both inputs.
>
>> I may be wrong, but my guess would be that this won't save much, because
>> the loop should terminate immediately. The whole point is not to loop
>> over possibly many pathkeys when we know it's exactly the same pathkeys
>> list (same pointer). When one of the lists is NIL the loop should
>> terminate right away ...
>>
>> >I also ran perf with a slightly modified version of your test that
>> >uses psql, and after the above changes was seeing something like a
>> >3.5% delta between master and this patch series. Nothing obvious in
>> >the perf report though.
>> >
>>
>> Yeah, I don't think there's anything obviously more expensive.
>>
>> >This test is intended to be somewhat worst case, no? At what point do
>> >we consider the trade-off worth it (given that it's not plausible to
>> >have zero impact)?
>> >
>>
>> Yes, more or less. It was definitely designed to do that - it merely
>> plans the query (no execution), with many applicable indexes etc. It's
>> definitely true that once the exection starts to take more time, the
>> overhead will get negligible. Same for reducing number of indexes.
>>
>> And of course, for queries that can benefit from incremental sort, the
>> speedup is likely way larger than this.
>>
>> In general, I think it'd be naive that we can make planner smarter with
>> no extra overhead spent on planning, and we can never accept patches
>> adding even tiny overhead. With that approach we'd probably end up with
>> a trivial planner that generates just a single query plan, because
>> that's going to be the fastest planner. A realistic approach needs to
>> consider both the planning and execution phase, and benefits of this
>> patch seem to be clear - if you have queries that do benefit from it.
>>
>> Let's try to minimize the overhead a bit more, and then we'll see.
>
>Any thoughts you have already on an approach for this?
>

That very much depends on what may be causing the problem. I have two
hypotheses, at the moment.

Based on the profiles I've seen so far, there does not seem to be any
function that suddenly got slower. That probably implies we're simply
generating more paths than before, which means more allocation, mode
add_path calls etc. It's not clear to me why would this happen even with
enable_incrementalsort=off, though.

Or maybe some of the structs got larger and need more cachelines? That
would affect performance even with the GUC set to off. But the perf stat
data also don't show anything particularly revealing. I'm using this:

   perf stat -e L1-dcache-loads,L1-dcache-load-misses,L1-dcache-stores,\
                dTLB-loads,dTLB-load-misses,dTLB-prefetch-misses,\
	       LLC-loads,LLC-load-misses,LLC-stores,LLC-prefetches,\
	       cycles,instructions,cache-references,cache-misses,'
	       bus-cycles,raw_syscalls:sys_enter -p $PID

An example output (for master and patched branch) is attached, but I
don't see anything obviously worse (there is some variance, of course).


regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

--jips45g6xtf5fou6
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename="perfstat.txt"

master
-----------------------------------------------------------------------------------------------
    35,765,095,847      L1-dcache-loads                                               (60.73%)
     1,761,627,379      L1-dcache-load-misses     #    4.93% of all L1-dcache hits    (68.62%)
    23,707,144,426      L1-dcache-stores                                              (76.40%)
    36,049,977,992      dTLB-loads                                                    (76.53%)
       119,985,744      dTLB-load-misses          #    0.33% of all dTLB cache hits   (76.46%)
   <not supported>      dTLB-prefetch-misses                                        
       862,291,225      LLC-loads                                                     (61.60%)
   <not supported>      LLC-load-misses                                             
       214,187,538      LLC-stores                                                    (62.01%)
       324,390,385      LLC-prefetches                                                (15.59%)
   124,688,872,086      cycles                                                        (23.38%)
   125,720,003,254      instructions              #    1.01  insn per cycle         
                                                  #    0.00  stalled cycles per insn  (31.02%)
     3,027,178,206      cache-references                                              (38.40%)
            53,245      cache-misses              #    0.002 % of all cache refs      (45.68%)
     3,391,913,360      bus-cycles                                                    (53.26%)
         6,928,207      raw_syscalls:sys_enter                                      

      51.003463352 seconds time elapsed

patched
-----------------------------------------------------------------------------------------------
    36,275,366,749      L1-dcache-loads                                               (59.90%)
     1,810,707,151      L1-dcache-load-misses     #    4.99% of all L1-dcache hits    (68.00%)
    23,947,408,537      L1-dcache-stores                                              (76.04%)
    36,554,434,020      dTLB-loads                                                    (77.09%)
       126,857,791      dTLB-load-misses          #    0.35% of all dTLB cache hits   (77.99%)
   <not supported>      dTLB-prefetch-misses                                        
       881,835,712      LLC-loads                                                     (63.52%)
   <not supported>      LLC-load-misses                                             
       223,210,875      LLC-stores                                                    (62.54%)
       334,866,329      LLC-prefetches                                                (14.01%)
   128,919,071,020      cycles                                                        (21.24%)
   127,628,370,525      instructions              #    0.99  insn per cycle         
                                                  #    0.00  stalled cycles per insn  (28.83%)
     3,106,611,147      cache-references                                              (36.48%)
            37,956      cache-misses              #    0.001 % of all cache refs      (44.27%)
     3,508,937,982      bus-cycles                                                    (52.09%)
         6,839,416      raw_syscalls:sys_enter                                      

      52.003477010 seconds time elapsed

--jips45g6xtf5fou6--