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 1gjm64-0002aA-1t for pgsql-bugs@arkaria.postgresql.org; Wed, 16 Jan 2019 14:23:12 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1gjm62-0005YB-B1 for pgsql-bugs@arkaria.postgresql.org; Wed, 16 Jan 2019 14:23:10 +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 1gjm61-0005Y4-Qe for pgsql-bugs@lists.postgresql.org; Wed, 16 Jan 2019 14:23:10 +0000 Received: from mail-lf1-x141.google.com ([2a00:1450:4864:20::141]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gjm5x-0004iD-N3 for pgsql-bugs@lists.postgresql.org; Wed, 16 Jan 2019 14:23:08 +0000 Received: by mail-lf1-x141.google.com with SMTP id c16so5018371lfj.8 for ; Wed, 16 Jan 2019 06:23:05 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=subject:to:references:from:message-id:date:user-agent:mime-version :in-reply-to:content-language; bh=Y/DUFLKBqwyl0DPFVatvdOf2YjVA1X5GQdGlyDNDPh0=; b=oXRfYR6w8Pmf+ZZ/6JpdInSpwTNWvb7qVHyQwsOP2y7t1J8dB6/Nf9VQiz1McvVAhC FpytSFOlgr85KICOZNfDqqb85GayL3fqKkUV48KnUa3wL0MXNL4kONqZ8FM3od5jJ56/ aNpKjipUoWxD/KouOJwDExIA1hbt3oWMULKhmZ8JNiONiAdTOzXn07ocBUdLGoYsWb8H Ux0wbA+VAYBIIIw0WanvTkmCawwuUsGP1e2qaDhFplnszDv0OQqAys76KmozXysegnum ibLp9JRP8VLq522Yx5BpL/UFUSHqZVGK+xd0kkpWJKUIuY+Kgw9RAl2Jf6jqfKowsRgr cT+Q== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:subject:to:references:from:message-id:date :user-agent:mime-version:in-reply-to:content-language; bh=Y/DUFLKBqwyl0DPFVatvdOf2YjVA1X5GQdGlyDNDPh0=; b=WG+Xhi0V2dqc0hH4pU+rJW7CSRR2oJTwMxjzUZ3ghJAIwBvbQdc7mpUoN/k/6hO/zz QDRfTZrlhPTtzFRsCTZ4jCiccs73E1MMhlDAI+4I2KHQ3qn6zN/rOpFnof0h93hVXXN6 +L+PbjfT7dMKxTgdCuENN5Ghl0/VXc0J8frkiiIlOnpDX0dCtIulgRCb7nId+Y1g1hDk itteA9S0c+5jyHfqqoGFNLiuFvPP1Duukcecm+kMHzFY3aEcjbcVFEFn65vhrkogn7ge SArr+EiwqtZ+0eyMH1aLkJh1u3pZ9yyBnWsjDG6PZb05XiTlcl8nhc9lSEqOEQ8yihLA kfPQ== X-Gm-Message-State: AJcUukfvKIdKZCGe3Rhk8QDwl1X1DX8nKWVs2XHwGFRXq5tfmgS5khIC mNnwZd0bOUeOK44j8sLOEy/cfPXOM5Y= X-Google-Smtp-Source: ALg8bN6QSInfpeMGizrs8TTlYB2aiDbpcBDjDcaGU2OMeQbiOHXZ+dkEZipNpb0DEv9TjHQEBLFrjQ== X-Received: by 2002:a19:6806:: with SMTP id d6mr6941767lfc.48.1547648582827; Wed, 16 Jan 2019 06:23:02 -0800 (PST) Received: from [192.168.27.213] ([93.174.131.141]) by smtp.gmail.com with ESMTPSA id m1sm1185738lfb.56.2019.01.16.06.23.01 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Wed, 16 Jan 2019 06:23:01 -0800 (PST) Subject: Re: BUG #15585: infinite DynamicSharedMemoryControlLock waiting in parallel query To: Thomas Munro , sk@zsrv.org, PostgreSQL mailing lists References: <15585-324ff6a93a18da46@postgresql.org> From: Maksim Milyutin Message-ID: <458c691a-1b2d-7a70-1c04-58361b894011@gmail.com> Date: Wed, 16 Jan 2019 17:23:01 +0300 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Thunderbird/60.2.1 MIME-Version: 1.0 In-Reply-To: Content-Type: multipart/alternative; boundary="------------52824CDEE78139B6E312F354" Content-Language: en-US List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk This is a multi-part message in MIME format. --------------52824CDEE78139B6E312F354 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 8bit On 1/11/19 8:16 AM, Thomas Munro wrote: > On Fri, Jan 11, 2019 at 10:04 AM Thomas Munro > wrote: >> I am trying to reproduce it. > I ran squillions of concurrent parallel queries today, making sure > they would allocate and free entire segments a lot (based on the > assumption that something along those lines must be required). I made > sure to use Linux, GCC, -O2, no asserts (since both reports came from > that environment, and I'd previously failed to reproduce this on my > usual tool chain/platforms), and I used a multi-socket box (in case > some cache coherency effect was not occurring on my development > laptops). I did learn some interesting things about parallel query > performance that I plan to follow up on, but I had no luck in > reproducing this error. Rats. > > One observation is that the other report involved a fairly simple > Parallel Hash Join query (on 11), and this report involves Parallel > Index Scan and Parallel Bitmap Index Scan (on 10), so that suggests > that it's probably not a bug in the parallel executor code (for > example an access-after-free, whose undefined behaviour could in > theory look like this with unlucky timing, I speculate) but rather > something lower level. Recently one of our customers encountered the same problem on PG 11.1. The query structure and error messages are similar to one that was described in [1]. OS/PG settings: Ubuntu 16.04 mem 128 GB cpu 16 cores huge_pages is turned off # sudo cat /proc/sys/kernel/shmmax 18446744073692774399 max_connections = 200 shared_buffers = 33GB dynamic_shared_memory_type = posix max_worker_processes = 16 max_parallel_maintenance_workers = 6 max_parallel_workers_per_gather = 6 max_parallel_workers = 12 The query was: SELECT   ev.date,   r.indicator_id,   r.service_reg_id,   count(r.value),   count(CASE WHEN r.value::int > 3 THEN 1 ELSE NULL END),   avg(r.value::int) FROM base.hershel_events AS ev   INNER JOIN base.hershel_rates AS r ON r.event_id = ev.id WHERE ev.date between '2018-09-15' AND '2018-12-15' GROUP BY ev.date, r.indicator_id, r.service_reg_id ORDER BY ev.date ASC Its plan with record statistics:  Finalize GroupAggregate (actual rows=81332937 loops=1)    Group Key: ev.date, r.indicator_id, r.service_reg_id    ->  Gather Merge (actual rows=81332937 loops=1)          Workers Planned: 7          Workers Launched: 7          ->  Partial GroupAggregate (actual rows=10166617 loops=8)                Group Key: ev.date, r.indicator_id, r.service_reg_id                ->  Sort (actual rows=10166617 loops=8)                      Sort Key: ev.date, r.indicator_id, r.service_reg_id                      Sort Method: external merge  Disk: 549392kB                      Worker 0:  Sort Method: external merge Disk: 516104kB                      Worker 1:  Sort Method: external merge Disk: 533200kB                      Worker 2:  Sort Method: external merge Disk: 540680kB                      Worker 3:  Sort Method: external merge Disk: 540760kB                      Worker 4:  Sort Method: external merge Disk: 530512kB                      Worker 5:  Sort Method: external merge Disk: 472240kB                      Worker 6:  Sort Method: external merge Disk: 539256kB                      ->  Parallel Hash Join (actual rows=10166617 loops=8)                            Hash Cond: (r.event_id = ev.id)                            ->  Parallel Seq Scan on hershel_rates r (actual rows=15000000 loops=8)                            ->  Parallel Hash (actual rows=9319175 loops=8)                                  Buckets: 4194304  Batches: 32 Memory Usage: 124064kB                                  ->  Parallel Seq Scan on hershel_events ev (actual rows=9319175 loops=8)                                        Filter: ((date >= '2018-09-15'::date) AND (date <= '2018-12-15'::date))                                        Rows Removed by Filter: 4430825 At some moment one of parallel workers emitted to log the error message: dsa_area could not attach to segment. After terminating all workers (the leader also bumped into the same error) the last one began to emit to log the following type of messages: LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp5027.0.sharedfileset/i55of128.p1.0", size 458752. The summary size of temp files that was mentioned in the log was about *14GB*. And eventually that last worker got the fatal error: cannot unpin a segment that is not pinned. After that the DynamicSharedMemoryControlLock left unreleased and soon new backends hanged on it. Another time some backend (more likely, it was some utility worker) bumped into the error: could not open shared memory segment "/PostgreSQL.1948558832": No such file or directory. After that other backends stopped on DynamicSharedMemoryControlLock. Before this issue there were parallel aggregate queries. Unfortunately our customer doesn't want to catch up this error on production system again. He turned off the query parallelism. And this issue doesn't reproduce on test environment. AFAIK this is heisenbug and is reproducible on heavy load. I'll try to run some stress tests to catch up stack trace. [1] https://www.postgresql.org/message-id/flat/20181231221734.GB25379%40telsasoft.com -- Regards, Maksim Milyutin Postgres Professional:http://www.postgrespro.ru The Russian Postgres Company --------------52824CDEE78139B6E312F354 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit


On 1/11/19 8:16 AM, Thomas Munro wrote:
On Fri, Jan 11, 2019 at 10:04 AM Thomas Munro
<thomas.munro@enterprisedb.com> wrote:

I am trying to reproduce it.

I ran squillions of concurrent parallel queries today, making sure
they would allocate and free entire segments a lot (based on the
assumption that something along those lines must be required).  I made
sure to use Linux, GCC, -O2, no asserts (since both reports came from
that environment, and I'd previously failed to reproduce this on my
usual tool chain/platforms), and I used a multi-socket box (in case
some cache coherency effect was not occurring on my development
laptops).  I did learn some interesting things about parallel query
performance that I plan to follow up on, but I had no luck in
reproducing this error.  Rats.

One observation is that the other report involved a fairly simple
Parallel Hash Join query (on 11), and this report involves Parallel
Index Scan and Parallel Bitmap Index Scan (on 10), so that suggests
that it's probably not a bug in the parallel executor code (for
example an access-after-free, whose undefined behaviour could in
theory look like this with unlucky timing, I speculate) but rather
something lower level.


Recently one of our customers encountered the same problem on PG 11.1. The query structure and error messages are similar to one that was described in [1].


OS/PG settings:

Ubuntu 16.04

mem 128 GB
cpu 16 cores
huge_pages is turned off

# sudo cat /proc/sys/kernel/shmmax
18446744073692774399

max_connections = 200
shared_buffers = 33GB
dynamic_shared_memory_type = posix
max_worker_processes = 16
max_parallel_maintenance_workers = 6
max_parallel_workers_per_gather = 6
max_parallel_workers = 12


The query was:

SELECT
  ev.date,
  r.indicator_id,
  r.service_reg_id,
  count(r.value),
  count(CASE WHEN r.value::int > 3 THEN 1 ELSE NULL END),
  avg(r.value::int)
FROM base.hershel_events AS ev
  INNER JOIN base.hershel_rates AS r ON r.event_id = ev.id
WHERE ev.date between '2018-09-15' AND '2018-12-15'
GROUP BY ev.date, r.indicator_id, r.service_reg_id
ORDER BY ev.date ASC

Its plan with record statistics:

 Finalize GroupAggregate (actual rows=81332937 loops=1)
   Group Key: ev.date, r.indicator_id, r.service_reg_id
   ->  Gather Merge (actual rows=81332937 loops=1)
         Workers Planned: 7
         Workers Launched: 7
         ->  Partial GroupAggregate (actual rows=10166617 loops=8)
               Group Key: ev.date, r.indicator_id, r.service_reg_id
               ->  Sort (actual rows=10166617 loops=8)
                     Sort Key: ev.date, r.indicator_id, r.service_reg_id
                     Sort Method: external merge  Disk: 549392kB
                     Worker 0:  Sort Method: external merge  Disk: 516104kB
                     Worker 1:  Sort Method: external merge  Disk: 533200kB
                     Worker 2:  Sort Method: external merge  Disk: 540680kB
                     Worker 3:  Sort Method: external merge  Disk: 540760kB
                     Worker 4:  Sort Method: external merge  Disk: 530512kB
                     Worker 5:  Sort Method: external merge  Disk: 472240kB
                     Worker 6:  Sort Method: external merge  Disk: 539256kB
                     ->  Parallel Hash Join (actual rows=10166617 loops=8)
                           Hash Cond: (r.event_id = ev.id)
                           ->  Parallel Seq Scan on hershel_rates r (actual rows=15000000 loops=8)
                           ->  Parallel Hash (actual rows=9319175 loops=8)
                                 Buckets: 4194304  Batches: 32  Memory Usage: 124064kB
                                 ->  Parallel Seq Scan on hershel_events ev (actual rows=9319175 loops=8)
                                       Filter: ((date >= '2018-09-15'::date) AND (date <= '2018-12-15'::date))
                                       Rows Removed by Filter: 4430825


At some moment one of parallel workers emitted to log the error message: dsa_area could not attach to segment. After terminating all workers (the leader also bumped into the same error) the last one began to emit to log the following type of messages: LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp5027.0.sharedfileset/i55of128.p1.0", size 458752. The summary size of temp files that was mentioned in the log was about *14GB*. And eventually that last worker got the fatal error: cannot unpin a segment that is not pinned. After that the DynamicSharedMemoryControlLock left unreleased and soon new backends hanged on it.

Another time some backend (more likely, it was some utility worker) bumped into the error: could not open shared memory segment "/PostgreSQL.1948558832": No such file or directory. After that other backends stopped on DynamicSharedMemoryControlLock. Before this issue there were parallel aggregate queries.


Unfortunately our customer doesn't want to catch up this error on production system again. He turned off the query parallelism. And this issue doesn't reproduce on test environment. AFAIK this is heisenbug and is reproducible on heavy load. I'll try to run some stress tests to catch up stack trace.


[1] https://www.postgresql.org/message-id/flat/20181231221734.GB25379%40telsasoft.com

-- 
Regards, Maksim Milyutin
Postgres Professional:http://www.postgrespro.ru
The Russian Postgres Company
--------------52824CDEE78139B6E312F354--