Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mS2N6-0003vg-DW for pgsql-performance@arkaria.postgresql.org; Sun, 19 Sep 2021 19:21:04 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1mS2N4-0002vF-Q1 for pgsql-performance@arkaria.postgresql.org; Sun, 19 Sep 2021 19:21:02 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mS2N4-0002v7-Cn for pgsql-performance@lists.postgresql.org; Sun, 19 Sep 2021 19:21:02 +0000 Received: from mail-qk1-x732.google.com ([2607:f8b0:4864:20::732]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1mS2N1-00081V-23 for pgsql-performance@lists.postgresql.org; Sun, 19 Sep 2021 19:21:01 +0000 Received: by mail-qk1-x732.google.com with SMTP id m21so35244998qkm.13 for ; Sun, 19 Sep 2021 12:20:58 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=subject:to:references:from:message-id:date:user-agent:mime-version :in-reply-to:content-language; bh=xZZTVIn6ZJHlzh58LLhsTgRUlnd9W7Tba9Oz3j7ajno=; b=L0yTat9mM58DTcHryU9XoAHCXIebLQSrXa604PZYU0b4yPO1VNmFytscc4UJPcH7XE s4/4Hr79N69mngAjq+AqP1fo7t9tvwHAKGULSeA/uBzhB5sD5du1Seq0Ye8AnqY83pxC eKUMS4RUcqQfSCw9++vve2/OL0nmyVFO2WebP4SPpqsoezS7pumP7zP5OnLVqbYTHhPF TBSBcYsYyoft0zHco7TOETMqvBDsBOo/cISn/UVGyELVtYCNodqsJTsLecZIDiYJ04MP rxOptUcSX56nbjkceb6Zqhv3BNxQ0hUhCdK7sRLU4u8ET1LeXLEBhZo7x/a1xf7HfWIE GA6Q== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:subject:to:references:from:message-id:date :user-agent:mime-version:in-reply-to:content-language; bh=xZZTVIn6ZJHlzh58LLhsTgRUlnd9W7Tba9Oz3j7ajno=; b=r25+n00z0lQOJ7pJaldEnaHmYNIHLPbE3L7MEuT8G+Wz4q96pqKbHx0Z5rc9SCVL5c 9zk4lo3OHLJIq/QjnpRQTJuMkWs41Ju+fwxMV2NKqaMPOnYt6QUv7PZguUENae8KtZBW 6WJJ/9tGt/AecHBK7DjuB6MpD58NH60H+DLooQQ+iWSzNCX0i9O5W2BNQbt1nF89hzgY f7qxGXer5xCN/XWy2TyqRxX/7KqSfTbBzuQWEIWldyWawF2sqnbe8s3XT7XixVgJDH8n WS5Iqqjwi/dVFI1DMLK0wKc8D3warqy+PeS8jQdN4GGMTBfGJS+XArl4hfWhark0Y1Uo k7aQ== X-Gm-Message-State: AOAM531WXH73e4lHqXfPsvPcrzy3rHaBNroU0lLDtXVeAagMlLpn8/A7 HVqjtSpAr36wrLhy2HMseFzY8cMqfXo= X-Google-Smtp-Source: ABdhPJzA6KkakL2Q1n0DzoityM50iWkSwoTFDFEDnpmIN2uEJLlA5NUHHi0qlZWihSYzobpS3+DiRw== X-Received: by 2002:a37:a985:: with SMTP id s127mr12090291qke.214.1632079256807; Sun, 19 Sep 2021 12:20:56 -0700 (PDT) Received: from [172.17.30.11] ([65.196.60.4]) by smtp.gmail.com with ESMTPSA id v201sm5459910qkb.29.2021.09.19.12.20.55 for (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Sun, 19 Sep 2021 12:20:56 -0700 (PDT) Subject: Re: Query executed during pg_dump leads to excessive memory usage To: pgsql-performance@lists.postgresql.org References: From: "Gogala, Mladen" Message-ID: Date: Sun, 19 Sep 2021 15:20:56 -0400 User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:78.0) Gecko/20100101 Thunderbird/78.14.0 MIME-Version: 1.0 In-Reply-To: Content-Type: multipart/alternative; boundary="------------2475F284E78F6B5928DF3F7D" Content-Language: en-US List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk This is a multi-part message in MIME format. --------------2475F284E78F6B5928DF3F7D Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 8bit On 9/19/2021 8:05 AM, Ranier Vilela wrote: > Em dom., 19 de set. de 2021 às 07:05, Ulf Lohbrügge > > escreveu: > > Hi there, > > A database cluster (PostgreSQL 12.4 running on Amazon Aurora @ > db.r5.xlarge) with a single database of mine consists of 1,656,618 > rows in pg_class. Using pg_dump on that database leads to > excessive memory usage and sometimes even a kill by signal 9: > > 2021-09-18 16:51:24 UTC::@:[29787]:LOG:  Aurora Runtime process > (PID 29794) was terminated by signal 9: Killed > 2021-09-18 16:51:25 UTC::@:[29787]:LOG:  terminating any other > active server processes > 2021-09-18 16:51:27 UTC::@:[29787]:FATAL:  Can't handle storage > runtime process crash > 2021-09-18 16:51:31 UTC::@:[29787]:LOG:  database system is shut down > > The query that is being fired by pg_dump is the following: > SELECT t.tableoid, t.oid, t.typname, t.typnamespace, (SELECT > pg_catalog.array_agg(acl ORDER BY row_n) FROM (SELECT acl, row_n > FROM > pg_catalog.unnest(coalesce(t.typacl,pg_catalog.acldefault('T',t.typowner))) > WITH ORDINALITY AS perm(acl,row_n) WHERE NOT EXISTS ( SELECT 1 > FROM > pg_catalog.unnest(coalesce(pip.initprivs,pg_catalog.acldefault('T',t.typowner))) > AS init(init_acl) WHERE acl = init_acl)) as foo) AS typacl, > (SELECT pg_catalog.array_agg(acl ORDER BY row_n) FROM (SELECT acl, > row_n FROM > pg_catalog.unnest(coalesce(pip.initprivs,pg_catalog.acldefault('T',t.typowner))) > WITH ORDINALITY AS initp(acl,row_n) WHERE NOT EXISTS ( SELECT 1 > FROM > pg_catalog.unnest(coalesce(t.typacl,pg_catalog.acldefault('T',t.typowner))) > AS permp(orig_acl) WHERE acl = orig_acl)) as foo) AS rtypacl, NULL > AS inittypacl, NULL AS initrtypacl, (SELECT rolname FROM > pg_catalog.pg_roles WHERE oid = t.typowner) AS rolname, t.typelem, > t.typrelid, CASE WHEN t.typrelid = 0 THEN ' '::"char" ELSE (SELECT > relkind FROM pg_class WHERE oid = t.typrelid) END AS typrelkind, > t.typtype, t.typisdefined, t.typname[0] = '_' AND t.typelem != 0 > AND (SELECT typarray FROM pg_type te WHERE oid = t.typelem) = > t.oid AS isarray FROM pg_type t LEFT JOIN pg_init_privs pip ON > (t.oid = pip.objoid AND pip.classoid = 'pg_type'::regclass AND > pip.objsubid = 0); > > The query plan looks like this. It takes almost 13 minutes(!) to > execute that query: >             QUERY PLAN > ---------------------------------------------------------------------------------------------------------------------------------------------- >  Hash Left Join  (cost=4.65..8147153.76 rows=1017962 width=280) > (actual time=2.526..106999.294 rows=1026902 loops=1) >    Hash Cond: (t.oid = pip.objoid) >    ->  Seq Scan on pg_type t  (cost=0.00..36409.62 rows=1017962 > width=122) (actual time=0.008..8836.693 rows=1026902 loops=1) >    ->  Hash  (cost=4.64..4.64 rows=1 width=45) (actual > time=2.342..41.972 rows=0 loops=1) >          Buckets: 1024  Batches: 1  Memory Usage: 8kB >          ->  Seq Scan on pg_init_privs pip  (cost=0.00..4.64 > rows=1 width=45) (actual time=2.341..22.109 rows=0 loops=1) >                Filter: ((classoid = '1247'::oid) AND (objsubid = 0)) >                Rows Removed by Filter: 176 >    SubPlan 1 >      ->  Aggregate  (cost=0.38..0.39 rows=1 width=32) (actual > time=0.031..0.031 rows=1 loops=1026902) >            ->  Hash Anti Join  (cost=0.24..0.37 rows=1 width=20) > (actual time=0.008..0.008 rows=0 loops=1026902) >                  Hash Cond: (perm.acl = init.init_acl) >                  ->  Function Scan on unnest perm >  (cost=0.01..0.11 rows=10 width=20) (actual time=0.001..0.001 > rows=2 loops=1026902) >                  ->  Hash  (cost=0.11..0.11 rows=10 width=12) > (actual time=0.002..0.002 rows=2 loops=1026902) >                        Buckets: 1024  Batches: 1  Memory Usage: 9kB >                        ->  Function Scan on unnest init >  (cost=0.01..0.11 rows=10 width=12) (actual time=0.001..0.001 > rows=2 loops=1026902) >    SubPlan 2 >      ->  Aggregate  (cost=0.38..0.39 rows=1 width=32) (actual > time=0.050..0.050 rows=1 loops=1026902) >            ->  Hash Anti Join  (cost=0.24..0.37 rows=1 width=20) > (actual time=0.008..0.008 rows=0 loops=1026902) >                  Hash Cond: (initp.acl = permp.orig_acl) >                  ->  Function Scan on unnest initp >  (cost=0.01..0.11 rows=10 width=20) (actual time=0.001..0.001 > rows=2 loops=1026902) >                  ->  Hash  (cost=0.11..0.11 rows=10 width=12) > (actual time=0.002..0.002 rows=2 loops=1026902) >                        Buckets: 1024  Batches: 1  Memory Usage: 9kB >                        ->  Function Scan on unnest permp >  (cost=0.01..0.11 rows=10 width=12) (actual time=0.001..0.001 > rows=2 loops=1026902) >    SubPlan 3 >      ->  Index Scan using pg_authid_oid_index on pg_authid >  (cost=0.28..2.29 rows=1 width=64) (actual time=0.002..0.002 > rows=1 loops=1026902) >            Index Cond: (oid = t.typowner) >    SubPlan 4 >      ->  Index Scan using pg_class_oid_index on pg_class >  (cost=0.43..2.45 rows=1 width=1) (actual time=0.003..0.003 rows=1 > loops=671368) >            Index Cond: (oid = t.typrelid) >    SubPlan 5 >      ->  Index Scan using pg_type_oid_index on pg_type te >  (cost=0.42..2.44 rows=1 width=4) (actual time=0.020..0.020 rows=1 > loops=355428) >            Index Cond: (oid = t.typelem) >  Planning Time: 0.535 ms >  Execution Time: 774011.175 ms > (35 rows) > > The high number of rows in pg_class result from more than ~550 > schemata, each containing more than 600 tables. It's part of a > multi tenant setup where each tenant lives in its own schema. > > I began to move schemata to another database cluster to reduce the > number of rows in pg_class but I'm having a hard time doing so as > a call to pg_dump might result in a database restart. > > Is there anything I can do to improve that situation? > > Can you try: > > 1. Limit resource usage by Postgres, with cgroups configuration. > 2. pg_dump compression: man pgsql -Z > 3. Run vacuum and reindex before? > > regards, > Ranier Vilela Try setting enable_seqscan=off for the user executing pg_dump, usually "postgres".  You have a ton of full table scans and hash joins which are the best plan for pg_dump, given the fact that you are dumping the entire database, but use a lot of memory.  Index scan will be slower, probably a lot slower, but will avoid allocating large memory areas for hash. -- Mladen Gogala Oracle DBA Tel: (347) 321-1217 Blog: https://dbwhisperer.wordpress.com --------------2475F284E78F6B5928DF3F7D Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit


On 9/19/2021 8:05 AM, Ranier Vilela wrote:
Em dom., 19 de set. de 2021 às 07:05, Ulf Lohbrügge <ulf.lohbruegge@gmail.com> escreveu:
Hi there,

A database cluster (PostgreSQL 12.4 running on Amazon Aurora @ db.r5.xlarge) with a single database of mine consists of 1,656,618 rows in pg_class. Using pg_dump on that database leads to excessive memory usage and sometimes even a kill by signal 9:

2021-09-18 16:51:24 UTC::@:[29787]:LOG:  Aurora Runtime process (PID 29794) was terminated by signal 9: Killed
2021-09-18 16:51:25 UTC::@:[29787]:LOG:  terminating any other active server processes
2021-09-18 16:51:27 UTC::@:[29787]:FATAL:  Can't handle storage runtime process crash
2021-09-18 16:51:31 UTC::@:[29787]:LOG:  database system is shut down

The query that is being fired by pg_dump is the following:
SELECT t.tableoid, t.oid, t.typname, t.typnamespace, (SELECT pg_catalog.array_agg(acl ORDER BY row_n) FROM (SELECT acl, row_n FROM pg_catalog.unnest(coalesce(t.typacl,pg_catalog.acldefault('T',t.typowner))) WITH ORDINALITY AS perm(acl,row_n) WHERE NOT EXISTS ( SELECT 1 FROM pg_catalog.unnest(coalesce(pip.initprivs,pg_catalog.acldefault('T',t.typowner))) AS init(init_acl) WHERE acl = init_acl)) as foo) AS typacl, (SELECT pg_catalog.array_agg(acl ORDER BY row_n) FROM (SELECT acl, row_n FROM pg_catalog.unnest(coalesce(pip.initprivs,pg_catalog.acldefault('T',t.typowner))) WITH ORDINALITY AS initp(acl,row_n) WHERE NOT EXISTS ( SELECT 1 FROM pg_catalog.unnest(coalesce(t.typacl,pg_catalog.acldefault('T',t.typowner))) AS permp(orig_acl) WHERE acl = orig_acl)) as foo) AS rtypacl, NULL AS inittypacl, NULL AS initrtypacl, (SELECT rolname FROM pg_catalog.pg_roles WHERE oid = t.typowner) AS rolname, t.typelem, t.typrelid, CASE WHEN t.typrelid = 0 THEN ' '::"char" ELSE (SELECT relkind FROM pg_class WHERE oid = t.typrelid) END AS typrelkind, t.typtype, t.typisdefined, t.typname[0] = '_' AND t.typelem != 0 AND (SELECT typarray FROM pg_type te WHERE oid = t.typelem) = t.oid AS isarray FROM pg_type t LEFT JOIN pg_init_privs pip ON (t.oid = pip.objoid AND pip.classoid = 'pg_type'::regclass AND pip.objsubid = 0);

The query plan looks like this. It takes almost 13 minutes(!) to execute that query:
                                                                  QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------
 Hash Left Join  (cost=4.65..8147153.76 rows=1017962 width=280) (actual time=2.526..106999.294 rows=1026902 loops=1)
   Hash Cond: (t.oid = pip.objoid)
   ->  Seq Scan on pg_type t  (cost=0.00..36409.62 rows=1017962 width=122) (actual time=0.008..8836.693 rows=1026902 loops=1)
   ->  Hash  (cost=4.64..4.64 rows=1 width=45) (actual time=2.342..41.972 rows=0 loops=1)
         Buckets: 1024  Batches: 1  Memory Usage: 8kB
         ->  Seq Scan on pg_init_privs pip  (cost=0.00..4.64 rows=1 width=45) (actual time=2.341..22.109 rows=0 loops=1)
               Filter: ((classoid = '1247'::oid) AND (objsubid = 0))
               Rows Removed by Filter: 176
   SubPlan 1
     ->  Aggregate  (cost=0.38..0.39 rows=1 width=32) (actual time=0.031..0.031 rows=1 loops=1026902)
           ->  Hash Anti Join  (cost=0.24..0.37 rows=1 width=20) (actual time=0.008..0.008 rows=0 loops=1026902)
                 Hash Cond: (perm.acl = init.init_acl)
                 ->  Function Scan on unnest perm  (cost=0.01..0.11 rows=10 width=20) (actual time=0.001..0.001 rows=2 loops=1026902)
                 ->  Hash  (cost=0.11..0.11 rows=10 width=12) (actual time=0.002..0.002 rows=2 loops=1026902)
                       Buckets: 1024  Batches: 1  Memory Usage: 9kB
                       ->  Function Scan on unnest init  (cost=0.01..0.11 rows=10 width=12) (actual time=0.001..0.001 rows=2 loops=1026902)
   SubPlan 2
     ->  Aggregate  (cost=0.38..0.39 rows=1 width=32) (actual time=0.050..0.050 rows=1 loops=1026902)
           ->  Hash Anti Join  (cost=0.24..0.37 rows=1 width=20) (actual time=0.008..0.008 rows=0 loops=1026902)
                 Hash Cond: (initp.acl = permp.orig_acl)
                 ->  Function Scan on unnest initp  (cost=0.01..0.11 rows=10 width=20) (actual time=0.001..0.001 rows=2 loops=1026902)
                 ->  Hash  (cost=0.11..0.11 rows=10 width=12) (actual time=0.002..0.002 rows=2 loops=1026902)
                       Buckets: 1024  Batches: 1  Memory Usage: 9kB
                       ->  Function Scan on unnest permp  (cost=0.01..0.11 rows=10 width=12) (actual time=0.001..0.001 rows=2 loops=1026902)
   SubPlan 3
     ->  Index Scan using pg_authid_oid_index on pg_authid  (cost=0.28..2.29 rows=1 width=64) (actual time=0.002..0.002 rows=1 loops=1026902)
           Index Cond: (oid = t.typowner)
   SubPlan 4
     ->  Index Scan using pg_class_oid_index on pg_class  (cost=0.43..2.45 rows=1 width=1) (actual time=0.003..0.003 rows=1 loops=671368)
           Index Cond: (oid = t.typrelid)
   SubPlan 5
     ->  Index Scan using pg_type_oid_index on pg_type te  (cost=0.42..2.44 rows=1 width=4) (actual time=0.020..0.020 rows=1 loops=355428)
           Index Cond: (oid = t.typelem)
 Planning Time: 0.535 ms
 Execution Time: 774011.175 ms
(35 rows)

The high number of rows in pg_class result from more than ~550 schemata, each containing more than 600 tables. It's part of a multi tenant setup where each tenant lives in its own schema.

I began to move schemata to another database cluster to reduce the number of rows in pg_class but I'm having a hard time doing so as a call to pg_dump might result in a database restart.

Is there anything I can do to improve that situation?
Can you try:

1. Limit resource usage by Postgres, with cgroups configuration.
2. pg_dump compression: man pgsql -Z
3. Run vacuum and reindex before?

regards,
Ranier Vilela


Try setting enable_seqscan=off for the user executing pg_dump, usually "postgres".  You have a ton of full table scans and hash joins which are the best plan for pg_dump, given the fact that you are dumping the entire database, but use a lot of memory.  Index scan will be slower, probably a lot slower, but will avoid allocating large memory areas for hash.

--
Mladen Gogala
Oracle DBA
Tel: (347) 321-1217
Blog: https://dbwhisperer.wordpress.com
--------------2475F284E78F6B5928DF3F7D--