Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eUNzu-00028p-Be for pgsql-committers@arkaria.postgresql.org; Thu, 28 Dec 2017 02:32:42 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eUNzt-0002SK-IE for pgsql-committers@arkaria.postgresql.org; Thu, 28 Dec 2017 02:32:41 +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_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1eUNzt-0002SA-Dl for pgsql-committers@lists.postgresql.org; Thu, 28 Dec 2017 02:32:41 +0000 Received: from sss.pgh.pa.us ([66.207.139.130]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1eUNzl-0003xL-Mg for pgsql-committers@postgresql.org; Thu, 28 Dec 2017 02:32:40 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.14.4/8.14.4) with ESMTP id vBS2WQ82030220; Wed, 27 Dec 2017 21:32:26 -0500 From: Tom Lane To: Thomas Munro cc: Andres Freund , pgsql-committers Subject: Re: pgsql: Add parallel-aware hash joins. In-reply-to: References: <20171221092940.gbxcszbzsr5khsfr@alap3.anarazel.de> <20171221095550.d3e7xhoakcowhu5b@alap3.anarazel.de> <20171222082203.fl6rpzlqnm4h7h6h@alap3.anarazel.de> Comments: In-reply-to Thomas Munro message dated "Tue, 26 Dec 2017 23:48:37 +1300" MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-ID: <30218.1514428346.1@sss.pgh.pa.us> Content-Transfer-Encoding: quoted-printable Date: Wed, 27 Dec 2017 21:32:26 -0500 Message-ID: <30219.1514428346@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk Thomas Munro writes: > I'll address the instability of the regression test output separately. If you're still looking for data on that --- prairiedog is able to reproduce the "multibatch =3D f" variant about one time in thirty. I modified the test case to print out the full EXPLAIN ANALYZE output rather than a heavily filtered version. Here's a typical successful run: ! explain analyze select length(max(s.t)) from wide left join (select id, coalesce(t, '') || '' as t from wide) = s using (id); ! QUERY= PLAN = ! ------------------------------------------------------------------------= ------------------------------------------------------------------------ ! Finalize Aggregate (cost=3D97.49..97.51 rows=3D1 width=3D4) (actual ti= me=3D409.330..409.331 rows=3D1 loops=3D1) ! -> Gather (cost=3D97.28..97.49 rows=3D2 width=3D32) (actual time=3D= 376.957..395.841 rows=3D3 loops=3D1) ! Workers Planned: 2 ! Workers Launched: 2 ! -> Partial Aggregate (cost=3D97.28..97.29 rows=3D1 width=3D32= ) (actual time=3D254.370..254.373 rows=3D1 loops=3D3) ! -> Parallel Hash Left Join (cost=3D23.23..88.88 rows=3D= 3360 width=3D32) (actual time=3D240.812..241.297 rows=3D1 loops=3D3) ! Hash Cond: (wide.id =3D wide_1.id) ! -> Parallel Seq Scan on wide (cost=3D0.00..15.29 = rows=3D529 width=3D4) (actual time=3D0.066..0.075 rows=3D1 loops=3D3) ! -> Parallel Hash (cost=3D16.61..16.61 rows=3D529 = width=3D36) (actual time=3D109.565..109.565 rows=3D1 loops=3D3) ! Buckets: 1024 (originally 2048) Batches: 8 (= originally 1) Memory Usage: 321kB ! -> Parallel Seq Scan on wide wide_1 (cost=3D= 0.00..16.61 rows=3D529 width=3D36) (actual time=3D2.989..7.218 rows=3D1 lo= ops=3D3) ! Planning time: 1.317 ms ! Execution time: 424.395 ms ! (13 rows) and here's a failing run: ! explain analyze select length(max(s.t)) from wide left join (select id, coalesce(t, '') || '' as t from wide) = s using (id); ! QUERY= PLAN = ! ------------------------------------------------------------------------= ------------------------------------------------------------------------- ! Finalize Aggregate (cost=3D97.49..97.51 rows=3D1 width=3D4) (actual ti= me=3D232.440..232.441 rows=3D1 loops=3D1) ! -> Gather (cost=3D97.28..97.49 rows=3D2 width=3D32) (actual time=3D= 225.738..226.744 rows=3D3 loops=3D1) ! Workers Planned: 2 ! Workers Launched: 2 ! -> Partial Aggregate (cost=3D97.28..97.29 rows=3D1 width=3D32= ) (actual time=3D29.377..29.379 rows=3D1 loops=3D3) ! -> Parallel Hash Left Join (cost=3D23.23..88.88 rows=3D= 3360 width=3D32) (actual time=3D22.747..25.340 rows=3D1 loops=3D3) ! Hash Cond: (wide.id =3D wide_1.id) ! -> Parallel Seq Scan on wide (cost=3D0.00..15.29 = rows=3D529 width=3D4) (actual time=3D0.086..0.113 rows=3D2 loops=3D1) ! -> Parallel Hash (cost=3D16.61..16.61 rows=3D529 = width=3D36) (actual time=3D16.382..16.382 rows=3D1 loops=3D3) ! Buckets: 1024 (originally 2048) Batches: 1 (= originally 1) Memory Usage: 0kB ! -> Parallel Seq Scan on wide wide_1 (cost=3D= 0.00..16.61 rows=3D529 width=3D36) (actual time=3D9.167..21.301 rows=3D2 l= oops=3D1) ! Planning time: 1.289 ms ! Execution time: 243.120 ms ! (13 rows) = I don't have enough insight to be totally sure what this means, but the "Memory Usage: 0kB" bit is obviously bogus, so I'd venture that at least part of the issue is failure to return stats from a worker. I also find it most curious that the "success" case is a lot slower than the "not success" case. Perhaps this is related to your livelock issue? Doing another run, I get something even slower: ! explain analyze select length(max(s.t)) from wide left join (select id, coalesce(t, '') || '' as t from wide) = s using (id); ! QUERY= PLAN = ! ------------------------------------------------------------------------= ------------------------------------------------------------------------- ! Finalize Aggregate (cost=3D97.49..97.51 rows=3D1 width=3D4) (actual ti= me=3D487.245..487.246 rows=3D1 loops=3D1) ! -> Gather (cost=3D97.28..97.49 rows=3D2 width=3D32) (actual time=3D= 444.650..475.390 rows=3D3 loops=3D1) ! Workers Planned: 2 ! Workers Launched: 2 ! -> Partial Aggregate (cost=3D97.28..97.29 rows=3D1 width=3D32= ) (actual time=3D345.816..345.819 rows=3D1 loops=3D3) ! -> Parallel Hash Left Join (cost=3D23.23..88.88 rows=3D= 3360 width=3D32) (actual time=3D334.229..338.098 rows=3D1 loops=3D3) ! Hash Cond: (wide.id =3D wide_1.id) ! -> Parallel Seq Scan on wide (cost=3D0.00..15.29 = rows=3D529 width=3D4) (actual time=3D0.065..0.074 rows=3D1 loops=3D3) ! -> Parallel Hash (cost=3D16.61..16.61 rows=3D529 = width=3D36) (actual time=3D140.210..140.210 rows=3D1 loops=3D3) ! Buckets: 1024 (originally 2048) Batches: 8 (= originally 1) Memory Usage: 321kB ! -> Parallel Seq Scan on wide wide_1 (cost=3D= 0.00..16.61 rows=3D529 width=3D36) (actual time=3D4.233..15.117 rows=3D1 l= oops=3D3) ! Planning time: 1.380 ms ! Execution time: 509.607 ms ! (13 rows) Aside from the instability problems, I'm pretty unhappy about how much the PHJ patch has added to the runtime of "make check". I do not think any one feature can justify adding 20% to that. Can't you cut down the amount of data processed by these new test cases? regards, tom lane