Обсуждение: BUG #15225: [XX000] ERROR: invalid DSA memory alloc request size1073741824 / Where: parallel worker
BUG #15225: [XX000] ERROR: invalid DSA memory alloc request size1073741824 / Where: parallel worker
От
PG Bug reporting form
Дата:
The following bug has been logged on the website:
Bug reference: 15225
Logged by: Frits Jalvingh
Email address: jal@etc.to
PostgreSQL version: 11beta1
Operating system: Ubuntu 18.04 64bit
Description:
Running the following:
explain (analyze, costs, verbose, buffers, timing, summary, format xml)
select
coalesce(tijd.tijdkey,'Unknown') as calender_id
, coalesce(eenheid_pe.id_s,-1) as eenheid_id
, sum(prijscomponent_pe.bedrag)::numeric(23,2) as kg00225
from tijd
cross join s_h_eenheid_ssm eenheid_pe
inner join l_prijscomponent_eenheid l_prijscomponent_eenheid_ps
on eenheid_pe.id_h_eenheid = l_prijscomponent_eenheid_ps.id_h_eenheid
inner join s_l_prijscomponent_eenheid_ssm
s_l_prijscomponent_eenheid_ssm_ps
on l_prijscomponent_eenheid_ps.id_l =
s_l_prijscomponent_eenheid_ssm_ps.id_l
and s_l_prijscomponent_eenheid_ssm_ps.dv_start_dts <= tijd.begindatum
and s_l_prijscomponent_eenheid_ssm_ps.dv_end_dts > tijd.begindatum
inner join s_h_prijscomponent_ssm prijscomponent_ps
on l_prijscomponent_eenheid_ps.id_h_prijscomponent =
prijscomponent_ps.id_h_prijscomponent
inner join s_h_eenheid_ssm eenheid_ps
on eenheid_pe.id_h_eenheid = eenheid_ps.id_h_eenheid
inner join l_prijscomponent_eenheid l_prijscomponent_eenheid_pe
on eenheid_pe.id_h_eenheid = l_prijscomponent_eenheid_pe.id_h_eenheid
inner join s_l_prijscomponent_eenheid_ssm
s_l_prijscomponent_eenheid_ssm_pe
on l_prijscomponent_eenheid_pe.id_l =
s_l_prijscomponent_eenheid_ssm_pe.id_l
and s_l_prijscomponent_eenheid_ssm_pe.dv_start_dts <= tijd.einddatum
and s_l_prijscomponent_eenheid_ssm_pe.dv_end_dts > tijd.einddatum
inner join s_h_prijscomponent_ssm prijscomponent_pe
on l_prijscomponent_eenheid_pe.id_h_prijscomponent =
prijscomponent_pe.id_h_prijscomponent
where eenheid_pe.dv_start_dts <= tijd.einddatum
and eenheid_pe.dv_end_dts > tijd.einddatum
and prijscomponent_ps.dv_start_dts <= tijd.einddatum
and prijscomponent_ps.dv_end_dts > tijd.einddatum
and eenheid_ps.dv_start_dts <= tijd.einddatum
and eenheid_ps.dv_end_dts > tijd.einddatum
and prijscomponent_pe.dv_start_dts <= tijd.einddatum
and prijscomponent_pe.dv_end_dts > tijd.einddatum
and ((prijscomponent_pe.soort = 'NET')
and (prijscomponent_ps.begindatum <= Tijd.begindatum and
(prijscomponent_ps.einddatum is null or prijscomponent_ps.einddatum >=
Tijd.begindatum))
and (eenheid_ps.inBezitbegindatum <= Tijd.einddatum and
(eenheid_ps.inBeziteinddatum is null or eenheid_ps.inBeziteinddatum >=
Tijd.einddatum)
and (eenheid_ps.bezitSoort = 'EIG' or (eenheid_ps.bezitSoort = 'BEH' and
eenheid_ps.bezitDetailsoort = 'BEC')))
and (eenheid_pe.inExploitatiedatum <= Tijd.einddatum and
(eenheid_pe.uitExploitatiedatum is null or eenheid_pe.uitExploitatiedatum >=
Tijd.begindatum))
)
group by
coalesce(tijd.tijdkey,'Unknown')
, coalesce(eenheid_pe.id_s,-1)
;
causes an abort after just a few seconds:
[XX000] ERROR: invalid DSA memory alloc request size 1073741824
Where: parallel worker
I have changed the default postgresql.conf file as follows:
work_mem = 2GB
shared_buffers=1GB
huge_pages = try
max_worker_processes = 8 # (change requires restart)
max_parallel_maintenance_workers = 2 # taken from max_parallel_workers
max_parallel_workers_per_gather = 2 # taken from max_parallel_workers
max_parallel_workers = 8
synchronous_commit = off
commit_delay = 100000
max_wal_size = 8GB
min_wal_size = 80MB
random_page_costs = 2.0
default_statistics_target = 500
My machine is an Ubuntu 18.04 64 bit up-to-date installation with Postgres
11 beta installed through the pgdg repo. psql -V reports:
psql (PostgreSQL) 11beta1 (Ubuntu 11~beta1-2.pgdg18.04+1)
The machine has an I7-4790K cpu with 32GB of memory.
The query does run successfully without the explain plan part.
Just running explain (analyse) also dies (but without the "in parallel
worker" part), as does explain (analyze, costs false, verbose false, buffers
false, timing false).
The execution plan of the query is:
[
{
"Plan": {
"Node Type": "Aggregate",
"Strategy": "Sorted",
"Partial Mode": "Finalize",
"Parallel Aware": false,
"Startup Cost": 1258419.25,
"Total Cost": 1258607.65,
"Plan Rows": 1462,
"Plan Width": 58,
"Group Key": ["(COALESCE(tijd.tijdkey, 'Unknown'::text))",
"(COALESCE(eenheid_pe.id_s, '-1'::integer))"],
"Plans": [
{
"Node Type": "Gather Merge",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Startup Cost": 1258419.25,
"Total Cost": 1258573.54,
"Plan Rows": 1218,
"Plan Width": 68,
"Workers Planned": 2,
"Plans": [
{
"Node Type": "Aggregate",
"Strategy": "Sorted",
"Partial Mode": "Partial",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Startup Cost": 1257419.22,
"Total Cost": 1257432.93,
"Plan Rows": 609,
"Plan Width": 68,
"Group Key": ["(COALESCE(tijd.tijdkey, 'Unknown'::text))",
"(COALESCE(eenheid_pe.id_s, '-1'::integer))"],
"Plans": [
{
"Node Type": "Sort",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Startup Cost": 1257419.22,
"Total Cost": 1257420.75,
"Plan Rows": 609,
"Plan Width": 40,
"Sort Key": ["(COALESCE(tijd.tijdkey, 'Unknown'::text))",
"(COALESCE(eenheid_pe.id_s, '-1'::integer))"],
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Parallel Aware": true,
"Join Type": "Inner",
"Startup Cost": 1132841.04,
"Total Cost": 1257391.06,
"Plan Rows": 609,
"Plan Width": 40,
"Inner Unique": false,
"Hash Cond": "(prijscomponent_pe.id_h_prijscomponent =
l_prijscomponent_eenheid_pe.id_h_prijscomponent)",
"Join Filter": "((prijscomponent_pe.dv_start_dts <=
tijd.einddatum) AND (prijscomponent_pe.dv_end_dts > tijd.einddatum))",
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Parallel Aware": true,
"Relation Name": "s_h_prijscomponent_ssm",
"Alias": "prijscomponent_pe",
"Startup Cost": 0.00,
"Total Cost": 122485.93,
"Plan Rows": 541285,
"Plan Width": 24,
"Filter": "(soort = 'NET'::text)"
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Parallel Aware": true,
"Startup Cost": 1132594.30,
"Total Cost": 1132594.30,
"Plan Rows": 19739,
"Plan Width": 44,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Parallel Aware": true,
"Join Type": "Inner",
"Startup Cost": 1065869.72,
"Total Cost": 1132594.30,
"Plan Rows": 19739,
"Plan Width": 44,
"Inner Unique": false,
"Hash Cond":
"(s_l_prijscomponent_eenheid_ssm_pe.id_l =
l_prijscomponent_eenheid_pe.id_l)",
"Join Filter":
"((s_l_prijscomponent_eenheid_ssm_pe.dv_start_dts <= tijd.einddatum) AND
(s_l_prijscomponent_eenheid_ssm_pe.dv_end_dts > tijd.einddatum))",
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Parallel Aware": true,
"Relation Name":
"s_l_prijscomponent_eenheid_ssm",
"Alias":
"s_l_prijscomponent_eenheid_ssm_pe",
"Startup Cost": 0.00,
"Total Cost": 58323.93,
"Plan Rows": 1944093,
"Plan Width": 24
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Parallel Aware": true,
"Startup Cost": 1063649.10,
"Total Cost": 1063649.10,
"Plan Rows": 177650,
"Plan Width": 48,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Parallel Aware": true,
"Join Type": "Inner",
"Startup Cost": 1001869.55,
"Total Cost": 1063649.10,
"Plan Rows": 177650,
"Plan Width": 48,
"Inner Unique": false,
"Hash Cond":
"(l_prijscomponent_eenheid_pe.id_h_eenheid = eenheid_pe.id_h_eenheid)",
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Parallel Aware": true,
"Relation Name":
"l_prijscomponent_eenheid",
"Alias":
"l_prijscomponent_eenheid_pe",
"Startup Cost": 0.00,
"Total Cost": 53749.04,
"Plan Rows": 1944104,
"Plan Width": 12
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Parallel Aware": true,
"Startup Cost": 1001843.22,
"Total Cost": 1001843.22,
"Plan Rows": 2106,
"Plan Width": 52,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship":
"Outer",
"Parallel Aware": true,
"Join Type": "Inner",
"Startup Cost": 875758.08,
"Total Cost": 1001843.22,
"Plan Rows": 2106,
"Plan Width": 52,
"Inner Unique": false,
"Hash Cond":
"(prijscomponent_ps.id_h_prijscomponent =
l_prijscomponent_eenheid_ps.id_h_prijscomponent)",
"Join Filter":
"((prijscomponent_ps.dv_start_dts <= tijd.einddatum) AND
(prijscomponent_ps.dv_end_dts > tijd.einddatum) AND
(prijscomponent_ps.begindatum <= tijd.begindatum) AND
((prijscomponent_ps.einddatum IS NULL) OR (prijscomponent_ps.einddatum >=
tijd.begindatum)))",
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship":
"Outer",
"Parallel Aware": true,
"Relation Name":
"s_h_prijscomponent_ssm",
"Alias":
"prijscomponent_ps",
"Startup Cost": 0.00,
"Total Cost": 117615.34,
"Plan Rows": 1948234,
"Plan Width": 28
},
{
"Node Type": "Hash",
"Parent Relationship":
"Inner",
"Parallel Aware": true,
"Startup Cost":
874012.21,
"Total Cost": 874012.21,
"Plan Rows": 139670,
"Plan Width": 60,
"Plans": [
{
"Node Type": "Hash
Join",
"Parent Relationship":
"Outer",
"Parallel Aware":
true,
"Join Type":
"Inner",
"Startup Cost":
800541.50,
"Total Cost":
874012.21,
"Plan Rows": 139670,
"Plan Width": 60,
"Inner Unique":
false,
"Hash Cond":
"(s_l_prijscomponent_eenheid_ssm_ps.id_l =
l_prijscomponent_eenheid_ps.id_l)",
"Join Filter":
"((s_l_prijscomponent_eenheid_ssm_ps.dv_start_dts <= tijd.begindatum) AND
(s_l_prijscomponent_eenheid_ssm_ps.dv_end_dts > tijd.begindatum))",
"Plans": [
{
"Node Type": "Seq
Scan",
"Parent
Relationship": "Outer",
"Parallel Aware":
true,
"Relation Name":
"s_l_prijscomponent_eenheid_ssm",
"Alias":
"s_l_prijscomponent_eenheid_ssm_ps",
"Startup Cost":
0.00,
"Total Cost":
58323.93,
"Plan Rows":
1944093,
"Plan Width": 24
},
{
"Node Type":
"Hash",
"Parent
Relationship": "Inner",
"Parallel Aware":
true,
"Startup Cost":
784828.56,
"Total Cost":
784828.56,
"Plan Rows":
1257035,
"Plan Width":
64,
"Plans": [
{
"Node Type":
"Hash Join",
"Parent
Relationship": "Outer",
"Parallel
Aware": true,
"Join Type":
"Inner",
"Startup
Cost": 716394.59,
"Total Cost":
784828.56,
"Plan Rows":
1257035,
"Plan Width":
64,
"Inner
Unique": false,
"Hash Cond":
"(l_prijscomponent_eenheid_ps.id_h_eenheid = eenheid_pe.id_h_eenheid)",
"Plans": [
{
"Node
Type": "Seq Scan",
"Parent
Relationship": "Outer",
"Parallel
Aware": true,
"Relation
Name": "l_prijscomponent_eenheid",
"Alias":
"l_prijscomponent_eenheid_ps",
"Startup
Cost": 0.00,
"Total
Cost": 53749.04,
"Plan
Rows": 1944104,
"Plan
Width": 12
},
{
"Node
Type": "Hash",
"Parent
Relationship": "Inner",
"Parallel
Aware": true,
"Startup
Cost": 716131.57,
"Total
Cost": 716131.57,
"Plan
Rows": 21041,
"Plan
Width": 52,
"Plans":
[
{
"Node
Type": "Hash Join",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Join
Type": "Inner",
"Startup Cost": 700308.75,
"Total
Cost": 716131.57,
"Plan
Rows": 21041,
"Plan
Width": 52,
"Inner
Unique": false,
"Hash
Cond": "(eenheid_ps.id_h_eenheid = eenheid_pe.id_h_eenheid)",
"Join
Filter": "((eenheid_ps.dv_start_dts <= tijd.einddatum) AND
(eenheid_ps.dv_end_dts > tijd.einddatum) AND (eenheid_ps.inbezitbegindatum
<= tijd.einddatum) AND ((eenheid_ps.inbeziteinddatum IS NULL) OR
(eenheid_ps.inbeziteinddatum >= tijd.einddatum)))",
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Parallel Aware": true,
"Relation Name": "s_h_eenheid_ssm",
"Alias": "eenheid_ps",
"Startup Cost": 0.00,
"Total Cost": 2695.46,
"Plan Rows": 32541,
"Plan Width": 28,
"Filter": "((bezitsoort = 'EIG'::text) OR ((bezitsoort = 'BEH'::text) AND
(bezitdetailsoort = 'BEC'::text)))"
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Parallel Aware": false,
"Startup Cost": 687268.69,
"Total Cost": 687268.69,
"Plan Rows": 1043205,
"Plan Width": 48,
"Plans": [
{
"Node Type": "Nested Loop",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Join Type": "Inner",
"Startup Cost": 0.00,
"Total Cost": 687268.69,
"Plan Rows": 1043205,
"Plan Width": 48,
"Inner Unique": false,
"Join Filter": "((eenheid_pe.dv_start_dts <= tijd.einddatum) AND
(eenheid_pe.dv_end_dts > tijd.einddatum) AND (eenheid_pe.inexploitatiedatum
<= tijd.einddatum) AND ((eenheid_pe.uitexploitatiedatum IS NULL) OR
(eenheid_pe.uitexploitatiedatum >= tijd.begindatum)))",
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Relation Name": "s_h_eenheid_ssm",
"Alias": "eenheid_pe",
"Startup Cost": 0.00,
"Total Cost": 2679.19,
"Plan Rows": 55319,
"Plan Width": 32
},
{
"Node Type": "Materialize",
"Parent Relationship": "Inner",
"Parallel Aware": false,
"Startup Cost": 0.00,
"Total Cost": 18.25,
"Plan Rows": 550,
"Plan Width": 40,
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Relation Name": "tijd",
"Alias": "tijd",
"Startup Cost": 0.00,
"Total Cost": 15.50,
"Plan Rows": 550,
"Plan Width": 40
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
},
"JIT": {
"Functions": 108,
"Inlining": true,
"Optimization": true
}
}
]
On Sun, Jun 3, 2018 at 10:13 PM, PG Bug reporting form
<noreply@postgresql.org> wrote:
> The following bug has been logged on the website:
>
> Bug reference: 15225
> Logged by: Frits Jalvingh
> Email address: jal@etc.to
> PostgreSQL version: 11beta1
> Operating system: Ubuntu 18.04 64bit
> Description:
> ...
>
> Running the following:
> causes an abort after just a few seconds:
> [XX000] ERROR: invalid DSA memory alloc request size 1073741824
> Where: parallel worker
> work_mem = 2GB
> max_parallel_workers_per_gather = 2 # taken from max_parallel_workers
> psql (PostgreSQL) 11beta1 (Ubuntu 11~beta1-2.pgdg18.04+1)
> "Node Type": "Hash Join",
> "Parallel Aware": true,
Thanks for the report. I think it is probably trying to allocate 1GB
worth of hash table buckets and failing, here:
batch->buckets =
dsa_allocate(hashtable->area, sizeof(dsa_pointer_atomic) * nbuckets);
sizeof(dsa_pointer_atomic) is 8 on your system, so it must be 128
million buckets. We could fix that by changing this to use
dsa_allocate_extended(..., DSA_ALLOC_HUGE), and that may be a change
we want to consider to support super-sized hash joins on large memory
machines. But the first question is whether it's actually reasonable
to be trying to do 128 million buckets in your case, and if not, what
has gone wrong. That's a couple of orders of magnitude higher than
the number of rows it estimated would be inserted into the hash table,
so presumably it was in the process of increasing the number of
buckets.
Could you please try running with SET enable_parallel_hash = off, so
we can see the estimated and actual row counts?
--
Thomas Munro
http://www.enterprisedb.com
Hi Thomas, thanks for your help.
The problem seems to be not very consistent. Without any changes to either database or query I now get:
org.postgresql.util.PSQLException: ERROR: could not resize shared memory segment "/PostgreSQL.347733883" to 2147483648 bytes: No space left on device
Just executing the statement WITHOUT the explain does work properly, so it is the explain part that seems to trigger the issue.
I set enable_parallel_hash = off in the code and now the explain part works properly. The plan XML looks like this:
<explain xmlns="http://www.postgresql.org/2009/explain">
<Query>
<Plan>
<Node-Type>Aggregate</Node-Type>
<Strategy>Sorted</Strategy>
<Partial-Mode>Simple</Partial-Mode>
<Parallel-Aware>false</Parallel-Aware>
<Startup-Cost>1524879.03</Startup-Cost>
<Total-Cost>1524919.24</Total-Cost>
<Plan-Rows>1462</Plan-Rows>
<Plan-Width>62</Plan-Width>
<Actual-Startup-Time>878413.051</Actual-Startup-Time>
<Actual-Total-Time>936007.744</Actual-Total-Time>
<Actual-Rows>677107</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>(COALESCE(tijd.tijdkey, 'Unknown'::text))</Item>
<Item>(COALESCE(eenheid_pe.id_s, '-1'::integer))</Item>
<Item>(COALESCE(adres_pe.id_s, '-1'::integer))</Item>
<Item>(sum(prijscomponent_pe.bedrag))::numeric(23,2)</Item>
</Output>
<Group-Key>
<Item>(COALESCE(tijd.tijdkey, 'Unknown'::text))</Item>
<Item>(COALESCE(eenheid_pe.id_s, '-1'::integer))</Item>
<Item>(COALESCE(adres_pe.id_s, '-1'::integer))</Item>
</Group-Key>
<Shared-Hit-Blocks>2438</Shared-Hit-Blocks>
<Shared-Read-Blocks>322664</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>12221239</Temp-Read-Blocks>
<Temp-Written-Blocks>12221247</Temp-Written-Blocks>
<Plans>
<Plan>
<Node-Type>Sort</Node-Type>
<Parent-Relationship>Outer</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Startup-Cost>1524879.03</Startup-Cost>
<Total-Cost>1524882.69</Total-Cost>
<Plan-Rows>1462</Plan-Rows>
<Plan-Width>44</Plan-Width>
<Actual-Startup-Time>878412.942</Actual-Startup-Time>
<Actual-Total-Time>915326.679</Actual-Total-Time>
<Actual-Rows>184162324</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>(COALESCE(tijd.tijdkey, 'Unknown'::text))</Item>
<Item>(COALESCE(eenheid_pe.id_s, '-1'::integer))</Item>
<Item>(COALESCE(adres_pe.id_s, '-1'::integer))</Item>
<Item>prijscomponent_pe.bedrag</Item>
</Output>
<Sort-Key>
<Item>(COALESCE(tijd.tijdkey, 'Unknown'::text))</Item>
<Item>(COALESCE(eenheid_pe.id_s, '-1'::integer))</Item>
<Item>(COALESCE(adres_pe.id_s, '-1'::integer))</Item>
</Sort-Key>
<Sort-Method>external merge</Sort-Method>
<Sort-Space-Used>5464336</Sort-Space-Used>
<Sort-Space-Type>Disk</Sort-Space-Type>
<Shared-Hit-Blocks>2438</Shared-Hit-Blocks>
<Shared-Read-Blocks>322664</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>12221239</Temp-Read-Blocks>
<Temp-Written-Blocks>12221247</Temp-Written-Blocks>
<Plans>
<Plan>
<Node-Type>Hash Join</Node-Type>
<Parent-Relationship>Outer</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Join-Type>Left</Join-Type>
<Startup-Cost>1363078.23</Startup-Cost>
<Total-Cost>1524802.18</Total-Cost>
<Plan-Rows>1462</Plan-Rows>
<Plan-Width>44</Plan-Width>
<Actual-Startup-Time>451502.428</Actual-Startup-Time>
<Actual-Total-Time>629056.050</Actual-Total-Time>
<Actual-Rows>184162324</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>COALESCE(tijd.tijdkey, 'Unknown'::text)</Item>
<Item>COALESCE(eenheid_pe.id_s, '-1'::integer)</Item>
<Item>COALESCE(adres_pe.id_s, '-1'::integer)</Item>
<Item>prijscomponent_pe.bedrag</Item>
</Output>
<Inner-Unique>false</Inner-Unique>
<Hash-Cond>(l_adres_eenheid_pe.id_h_adres = adres_pe.id_h_adres)</Hash-Cond>
<Join-Filter>((adres_pe.dv_start_dts <= tijd.einddatum) AND (adres_pe.dv_end_dts > tijd.einddatum))</Join-Filter>
<Rows-Removed-by-Join-Filter>0</Rows-Removed-by-Join-Filter>
<Shared-Hit-Blocks>2432</Shared-Hit-Blocks>
<Shared-Read-Blocks>322664</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>11538197</Temp-Read-Blocks>
<Temp-Written-Blocks>11538197</Temp-Written-Blocks>
<Plans>
<Plan>
<Node-Type>Hash Join</Node-Type>
<Parent-Relationship>Outer</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Join-Type>Left</Join-Type>
<Startup-Cost>1360706.69</Startup-Cost>
<Total-Cost>1522403.22</Total-Cost>
<Plan-Rows>1462</Plan-Rows>
<Plan-Width>48</Plan-Width>
<Actual-Startup-Time>451482.554</Actual-Startup-Time>
<Actual-Total-Time>604384.623</Actual-Total-Time>
<Actual-Rows>184162324</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>tijd.tijdkey</Item>
<Item>tijd.einddatum</Item>
<Item>eenheid_pe.id_s</Item>
<Item>prijscomponent_pe.bedrag</Item>
<Item>l_adres_eenheid_pe.id_h_adres</Item>
</Output>
<Inner-Unique>false</Inner-Unique>
<Hash-Cond>(l_adres_eenheid_pe.id_l = s_l_adres_eenheid_ssm_pe.id_l)</Hash-Cond>
<Join-Filter>((s_l_adres_eenheid_ssm_pe.dv_start_dts <= tijd.einddatum) AND (s_l_adres_eenheid_ssm_pe.dv_end_dts > tijd.einddatum))</Join-Filter>
<Rows-Removed-by-Join-Filter>0</Rows-Removed-by-Join-Filter>
<Shared-Hit-Blocks>2432</Shared-Hit-Blocks>
<Shared-Read-Blocks>321535</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>11538197</Temp-Read-Blocks>
<Temp-Written-Blocks>11538197</Temp-Written-Blocks>
<Plans>
<Plan>
<Node-Type>Hash Join</Node-Type>
<Parent-Relationship>Outer</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Join-Type>Left</Join-Type>
<Startup-Cost>1359001.01</Startup-Cost>
<Total-Cost>1520670.13</Total-Cost>
<Plan-Rows>1462</Plan-Rows>
<Plan-Width>52</Plan-Width>
<Actual-Startup-Time>451465.428</Actual-Startup-Time>
<Actual-Total-Time>580081.413</Actual-Total-Time>
<Actual-Rows>184162324</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>tijd.tijdkey</Item>
<Item>tijd.einddatum</Item>
<Item>eenheid_pe.id_s</Item>
<Item>prijscomponent_pe.bedrag</Item>
<Item>l_adres_eenheid_pe.id_l</Item>
<Item>l_adres_eenheid_pe.id_h_adres</Item>
</Output>
<Inner-Unique>false</Inner-Unique>
<Hash-Cond>(eenheid_pe.id_h_eenheid = l_adres_eenheid_pe.id_h_eenheid)</Hash-Cond>
<Shared-Hit-Blocks>2432</Shared-Hit-Blocks>
<Shared-Read-Blocks>321074</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>11538197</Temp-Read-Blocks>
<Temp-Written-Blocks>11538197</Temp-Written-Blocks>
<Plans>
<Plan>
<Node-Type>Hash Join</Node-Type>
<Parent-Relationship>Outer</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Join-Type>Inner</Join-Type>
<Startup-Cost>1357349.34</Startup-Cost>
<Total-Cost>1518998.35</Total-Cost>
<Plan-Rows>1462</Plan-Rows>
<Plan-Width>48</Plan-Width>
<Actual-Startup-Time>451449.831</Actual-Startup-Time>
<Actual-Total-Time>557115.926</Actual-Total-Time>
<Actual-Rows>184162324</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>tijd.tijdkey</Item>
<Item>tijd.einddatum</Item>
<Item>eenheid_pe.id_s</Item>
<Item>eenheid_pe.id_h_eenheid</Item>
<Item>prijscomponent_pe.bedrag</Item>
</Output>
<Inner-Unique>false</Inner-Unique>
<Hash-Cond>(prijscomponent_pe.id_h_prijscomponent = l_prijscomponent_eenheid_pe.id_h_prijscomponent)</Hash-Cond>
<Join-Filter>((prijscomponent_pe.dv_start_dts <= tijd.einddatum) AND (prijscomponent_pe.dv_end_dts > tijd.einddatum))</Join-Filter>
<Rows-Removed-by-Join-Filter>0</Rows-Removed-by-Join-Filter>
<Shared-Hit-Blocks>2430</Shared-Hit-Blocks>
<Shared-Read-Blocks>320669</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>11538197</Temp-Read-Blocks>
<Temp-Written-Blocks>11538197</Temp-Written-Blocks>
<Plans>
<Plan>
<Node-Type>Seq Scan</Node-Type>
<Parent-Relationship>Outer</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Relation-Name>s_h_prijscomponent_ssm</Relation-Name>
<Schema>datavault</Schema>
<Alias>prijscomponent_pe</Alias>
<Startup-Cost>0.00</Startup-Cost>
<Total-Cost>156580.02</Total-Cost>
<Plan-Rows>1299083</Plan-Rows>
<Plan-Width>24</Plan-Width>
<Actual-Startup-Time>1375.832</Actual-Startup-Time>
<Actual-Total-Time>1876.664</Actual-Total-Time>
<Actual-Rows>1235341</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>prijscomponent_pe.id_s</Item>
<Item>prijscomponent_pe.dv_end_dts</Item>
<Item>prijscomponent_pe.dv_load_dts</Item>
<Item>prijscomponent_pe.dv_start_dts</Item>
<Item>prijscomponent_pe.id_h_prijscomponent</Item>
<Item>prijscomponent_pe.auditinfo</Item>
<Item>prijscomponent_pe.bedrag</Item>
<Item>prijscomponent_pe.begindatum</Item>
<Item>prijscomponent_pe.bronsysteem</Item>
<Item>prijscomponent_pe.btw</Item>
<Item>prijscomponent_pe.businesskey</Item>
<Item>prijscomponent_pe.code</Item>
<Item>prijscomponent_pe.detailsoort</Item>
<Item>prijscomponent_pe.einddatum</Item>
<Item>prijscomponent_pe.extraelementen</Item>
<Item>prijscomponent_pe.identificatie</Item>
<Item>prijscomponent_pe.organisatie</Item>
<Item>prijscomponent_pe.sat_attributes_concat</Item>
<Item>prijscomponent_pe.soort</Item>
<Item>prijscomponent_pe.wijzigingreden</Item>
</Output>
<Filter>(prijscomponent_pe.soort = 'NET'::text)</Filter>
<Rows-Removed-by-Filter>3430513</Rows-Removed-by-Filter>
<Shared-Hit-Blocks>168</Shared-Hit-Blocks>
<Shared-Read-Blocks>97965</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>0</Temp-Read-Blocks>
<Temp-Written-Blocks>0</Temp-Written-Blocks>
</Plan>
<Plan>
<Node-Type>Hash</Node-Type>
<Parent-Relationship>Inner</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Startup-Cost>1356757.17</Startup-Cost>
<Total-Cost>1356757.17</Total-Cost>
<Plan-Rows>47373</Plan-Rows>
<Plan-Width>48</Plan-Width>
<Actual-Startup-Time>450073.694</Actual-Startup-Time>
<Actual-Total-Time>450073.694</Actual-Total-Time>
<Actual-Rows>731320569</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>tijd.tijdkey</Item>
<Item>tijd.einddatum</Item>
<Item>eenheid_pe.id_s</Item>
<Item>eenheid_pe.id_h_eenheid</Item>
<Item>l_prijscomponent_eenheid_pe.id_h_prijscomponent</Item>
</Output>
<Hash-Buckets>33554432</Hash-Buckets>
<Original-Hash-Buckets>65536</Original-Hash-Buckets>
<Hash-Batches>32</Hash-Batches>
<Original-Hash-Batches>1</Original-Hash-Batches>
<Peak-Memory-Usage>1835009</Peak-Memory-Usage>
<Shared-Hit-Blocks>2262</Shared-Hit-Blocks>
<Shared-Read-Blocks>222704</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>5965116</Temp-Read-Blocks>
<Temp-Written-Blocks>9770745</Temp-Written-Blocks>
<Plans>
<Plan>
<Node-Type>Hash Join</Node-Type>
<Parent-Relationship>Outer</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Join-Type>Inner</Join-Type>
<Startup-Cost>1247323.72</Startup-Cost>
<Total-Cost>1356757.17</Total-Cost>
<Plan-Rows>47373</Plan-Rows>
<Plan-Width>48</Plan-Width>
<Actual-Startup-Time>171240.780</Actual-Startup-Time>
<Actual-Total-Time>336721.515</Actual-Total-Time>
<Actual-Rows>731320569</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>tijd.tijdkey</Item>
<Item>tijd.einddatum</Item>
<Item>eenheid_pe.id_s</Item>
<Item>eenheid_pe.id_h_eenheid</Item>
<Item>l_prijscomponent_eenheid_pe.id_h_prijscomponent</Item>
</Output>
<Inner-Unique>false</Inner-Unique>
<Hash-Cond>(s_l_prijscomponent_eenheid_ssm_pe.id_l = l_prijscomponent_eenheid_pe.id_l)</Hash-Cond>
<Join-Filter>((s_l_prijscomponent_eenheid_ssm_pe.dv_start_dts <= tijd.einddatum) AND (s_l_prijscomponent_eenheid_ssm_pe.dv_end_dts > tijd.einddatum))</Join-Filter>
<Rows-Removed-by-Join-Filter>0</Rows-Removed-by-Join-Filter>
<Shared-Hit-Blocks>2262</Shared-Hit-Blocks>
<Shared-Read-Blocks>222704</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>5965116</Temp-Read-Blocks>
<Temp-Written-Blocks>5965116</Temp-Written-Blocks>
<Plans>
<Plan>
<Node-Type>Seq Scan</Node-Type>
<Parent-Relationship>Outer</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Relation-Name>s_l_prijscomponent_eenheid_ssm</Relation-Name>
<Schema>datavault</Schema>
<Alias>s_l_prijscomponent_eenheid_ssm_pe</Alias>
<Startup-Cost>0.00</Startup-Cost>
<Total-Cost>85541.23</Total-Cost>
<Plan-Rows>4665823</Plan-Rows>
<Plan-Width>24</Plan-Width>
<Actual-Startup-Time>0.026</Actual-Startup-Time>
<Actual-Total-Time>308.939</Actual-Total-Time>
<Actual-Rows>4665854</Actual-Rows>
<Actual-Loops>1</Actual-Loops>
<Output>
<Item>s_l_prijscomponent_eenheid_ssm_pe.id_s</Item>
<Item>s_l_prijscomponent_eenheid_ssm_pe.dv_end_dts</Item>
<Item>s_l_prijscomponent_eenheid_ssm_pe.dv_load_dts</Item>
<Item>s_l_prijscomponent_eenheid_ssm_pe.dv_start_dts</Item>
<Item>s_l_prijscomponent_eenheid_ssm_pe.id_l</Item>
<Item>s_l_prijscomponent_eenheid_ssm_pe.organisatie</Item>
</Output>
<Shared-Hit-Blocks>32</Shared-Hit-Blocks>
<Shared-Read-Blocks>38851</Shared-Read-Blocks>
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks>
<Shared-Written-Blocks>0</Shared-Written-Blocks>
<Local-Hit-Blocks>0</Local-Hit-Blocks>
<Local-Read-Blocks>0</Local-Read-Blocks>
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks>
<Local-Written-Blocks>0</Local-Written-Blocks>
<Temp-Read-Blocks>0</Temp-Read-Blocks>
<Temp-Written-Blocks>0</Temp-Written-Blocks>
</Plan>
<Plan>
<Node-Type>Hash</Node-Type>
<Parent-Relationship>Inner</Parent-Relationship>
<Parallel-Aware>false</Parallel-Aware>
<Startup-Cost>1241994.21</Startup-Cost>
<Total-Cost>1241994.21</Total-Cost>
<Plan-Rows>426361</Plan-Rows>
<Plan-Width>52</Plan-Width>
<Actual-Startup-Time>171239.530</Actual-Startup-Time>
On Tue, Jun 5, 2018 at 11:08 PM, Frits Jalvingh <jal@etc.to> wrote: > Hi Thomas, thanks for your help. > > The problem seems to be not very consistent. Without any changes to either > database or query I now get: > org.postgresql.util.PSQLException: ERROR: could not resize shared memory > segment "/PostgreSQL.347733883" to 2147483648 bytes: No space left on device That's what it looks like when the OS just can't allocate any more virtual memory (posix_fallocate() on a shared memory region failed). The solution to that problem is to turn down work_mem. With our current model of memory management, we'll use work_mem for every backend for every sort or hash join. So when you said work_mem = 2GB and max_parallel_workers = 2 (+ 1 leader process = 3 backends) and you joined N tables together (that's a very hand wavy and stupid approximation of the number of nodes), you said it was OK to use a total of 2GB * (N - 1) * 3. That's apparently too much for this rig. Does it work if you turn work_mem down? > Just executing the statement WITHOUT the explain does work properly, so it > is the explain part that seems to trigger the issue. That is weird. I don't have a theory to explain that yet. > I set enable_parallel_hash = off in the code and now the explain part works > properly. The plan XML looks like this: > <Node-Type>Sort</Node-Type> > <Plan-Rows>1462</Plan-Rows> > <Actual-Rows>184162324</Actual-Rows> > <Node-Type>Hash Join</Node-Type> > <Plan-Rows>1462</Plan-Rows> > <Actual-Rows>184162324</Actual-Rows> > <Node-Type>Hash</Node-Type> > <Plan-Rows>47373</Plan-Rows> > <Actual-Rows>731320569</Actual-Rows> Thanks. Hmm. I didn't try to understand this plan in detail but clearly it is dramatically underestimating cardinality, and there are large numbers involved that would result in nbuckets of the right sort of order. If the first error you reported results from an attempt to allocate a very large bucket array (rather than, say, a monster tuple >= 1GB), as I speculated, then there would need to be a flaw in the logic that clamps nbuckets to fit in MaxAllocSize. I will do some digging today. -- Thomas Munro http://www.enterprisedb.com
Hi Thomas,
I know that the message is about running out of memory, I just meant to say that it is a different message than before. Which led me to think that this might be another issue. But of course OOM can occur at many places and that might explain the different messages.
As far as that explain thing goes, the odd thing seems to be that /without/ the explain the database uses a non parallel plan. If I execute the exact same statement without explain I see one postgres process running at 100% for a long time, then it produces its output proper.
If I add the explain part to it I see three processes: the main process handling the EXPLAIN and two parallel workers. So the issue is that the explain plan actually uses another plan than the same statement without explain(!). This also explains the OOM, because indeed I see all processes gobble up memory like mad, growing to 12GB each and then it dies.
Reducing work_mem to 512MB makes the explain plan succeed, finally.
So there seem to be two conclusions:
- explain seems to somehow influence the plan that is being made.
- there is a big problem with postgres memory assignment, because with the increase of parallelism having work_mem work per process means that you cannot effectively control the amount of memory that postgres uses anymore. This was quite bad before, but because there were only limited places where work_mem had effect this was... workable... But with more and more parallelism thrown into the mix the net effect is unstable execution as a random set of queries fired to the database will abort the backends at random with OOM. That, I think, is a Bad Thing. The only way to prevent backends aborting with oom would be to have a lot of memory but set work_mem small - meaning you waste all that memory about 99% of the time....
Frits Jalvingh <jal@etc.to> writes:
> As far as that explain thing goes, the odd thing seems to be that /without/
> the explain the database uses a non parallel plan. If I execute the exact
> same statement without explain I see one postgres process running at 100%
> for a long time, then it produces its output proper.
This doesn't prove that the thing is non-parallel, only that the work is
badly distributed. You might try cranking up log_min_messages to the
point that worker-process launching gets logged, and then see whether
or not it's really non-parallel.
> - explain seems to somehow influence the plan that is being made.
That should absolutely *not* be the case.
> - there is a big problem with postgres memory assignment, because with the
> increase of parallelism having work_mem work per process means that you
> cannot effectively control the amount of memory that postgres uses anymore.
work_mem has always been like that. You cannot set it to any very large
fraction of your system's available memory, at least not globally across
a whole bunch of queries.
regards, tom lane
Thanks for your explanation.
>> - explain seems to somehow influence the plan that is being made.
>That should absolutely *not* be the case.
I could not agree more ;)
The "good" news is that this effect is apparently caused by something else. I fired those statements through an IDE (IntelliJ) written in Java and using jdbc. There seems to be something odd going on in there, because when I paste the query in psql then the effect with and without explain looks the same: 3 processes of which 2 "parallel workers" doing enormous amounts of I/O at 50..90% CPU. I will try to find out what easter egg in either that IDE or the JDBC driver causes this 8-/.
> this does not prove that the thing is non-parallel, ....
I do not understand? When it runs without explain there are no "parallel worker" processes at all, just a single backend process running the "select" at 100% cpu (there are of course the normal postgres processes but all are all but idle and none are "background workers"). If it has a bad distribution would this not just mean its workers are less busy?
Related question: as postgres does not use threading I assume that background workers are visible as such, so even if they are not very busy I would assume I would see them with ps -ef.
>work_mem has always been like that.
I know. My observation is that this behavior has more of a bad effect with newer postgresses: because of the increased parallelism (and the apparent OK to every node to grab work_mem when they see fit) newer version make way less good use of memory than older versions because you have to decrease the parameter. That 2GB value I had worked fine on 10, and helped a lot with speeding up my workload. Now for the same workload I have to put it on 512MB, so all queries that just do one sort are slower - and memory is used less well. It means that in all the system might perform less well despite parallelism because you have to prevent aborting queries.
Regards,
Frits Jalvingh
On Wed, Jun 6, 2018 at 4:38 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
Frits Jalvingh <jal@etc.to> writes:
> As far as that explain thing goes, the odd thing seems to be that /without/
> the explain the database uses a non parallel plan. If I execute the exact
> same statement without explain I see one postgres process running at 100%
> for a long time, then it produces its output proper.
This doesn't prove that the thing is non-parallel, only that the work is
badly distributed. You might try cranking up log_min_messages to the
point that worker-process launching gets logged, and then see whether
or not it's really non-parallel.
> - explain seems to somehow influence the plan that is being made.
That should absolutely *not* be the case.
> - there is a big problem with postgres memory assignment, because with the
> increase of parallelism having work_mem work per process means that you
> cannot effectively control the amount of memory that postgres uses anymore.
work_mem has always been like that. You cannot set it to any very large
fraction of your system's available memory, at least not globally across
a whole bunch of queries.
regards, tom lane
Frits Jalvingh <jal@etc.to> writes:
> The "good" news is that this effect is apparently caused by something else.
> I fired those statements through an IDE (IntelliJ) written in Java and
> using jdbc. There seems to be something odd going on in there, because when
> I paste the query in psql then the effect with and without explain looks
> the same: 3 processes of which 2 "parallel workers" doing enormous amounts
> of I/O at 50..90% CPU. I will try to find out what easter egg in either
> that IDE or the JDBC driver causes this 8-/.
Ah. Something about query parameterization, is my bet.
regards, tom lane
On Wed, Jun 6, 2018 at 3:45 PM, Frits Jalvingh <jal@etc.to> wrote:
Hi Thomas,I know that the message is about running out of memory, I just meant to say that it is a different message than before. Which led me to think that this might be another issue. But of course OOM can occur at many places and that might explain the different messages.As far as that explain thing goes, the odd thing seems to be that /without/ the explain the database uses a non parallel plan. If I execute the exact same statement without explain I see one postgres process running at 100% for a long time, then it produces its output proper.If I add the explain part to it I see three processes: the main process handling the EXPLAIN and two parallel workers. So the issue is that the explain plan actually uses another plan than the same statement without explain(!). This also explains the OOM, because indeed I see all processes gobble up memory like mad, growing to 12GB each and then it dies.
There is also possiblility that it might have planned to use parallel worker (which is shown in explain )but during actual execution it has not got any free background worker (other parallel sessions might be using all the workers).
Hi Dilip,
That should not be possible; nothing else is using the DB on that machine as it is my development machine.
On Wed, Jun 6, 2018 at 6:53 PM Dilip Kumar <dilipbalaut@gmail.com> wrote:
On Wed, Jun 6, 2018 at 3:45 PM, Frits Jalvingh <jal@etc.to> wrote:Hi Thomas,I know that the message is about running out of memory, I just meant to say that it is a different message than before. Which led me to think that this might be another issue. But of course OOM can occur at many places and that might explain the different messages.As far as that explain thing goes, the odd thing seems to be that /without/ the explain the database uses a non parallel plan. If I execute the exact same statement without explain I see one postgres process running at 100% for a long time, then it produces its output proper.If I add the explain part to it I see three processes: the main process handling the EXPLAIN and two parallel workers. So the issue is that the explain plan actually uses another plan than the same statement without explain(!). This also explains the OOM, because indeed I see all processes gobble up memory like mad, growing to 12GB each and then it dies.There is also possiblility that it might have planned to use parallel worker (which is shown in explain )but during actual execution it has not got any free background worker (other parallel sessions might be using all the workers).
On Thu, Jun 7, 2018 at 4:19 AM, Frits Jalvingh <jal@etc.to> wrote: >>work_mem has always been like that. > I know. My observation is that this behavior has more of a bad effect with > newer postgresses: because of the increased parallelism (and the apparent OK > to every node to grab work_mem when they see fit) newer version make way > less good use of memory than older versions because you have to decrease the > parameter. That 2GB value I had worked fine on 10, and helped a lot with > speeding up my workload. Now for the same workload I have to put it on > 512MB, so all queries that just do one sort are slower - and memory is used > less well. It means that in all the system might perform less well despite > parallelism because you have to prevent aborting queries. It's a problem alright, and many people think we should address it. It's not exactly obvious how though... Here's a recent thread on the topic: https://www.postgresql.org/message-id/flat/CAH2-WzmNwV%3DLfDRXPsmCqgmm91mp%3D2b4FvXNF%3DcCvMrb8YFLfQ%40mail.gmail.com > ERROR: invalid DSA memory alloc request size 1073741824 The problem is that I failed to constrain nbuckets to fit in MaxAllocSize when increasing it due to load factor, and for now Parallel Hash doesn't use DSA_ALLOC_HUGE (so essentially any attempt to allocate 1GB+ is assumed to be crazy and rejected by dsa.c, just like the equivalent non-parallel code). Here is a proposed fix that constrains it. Longer term, I don't see why we should limit large memory systems to < 1GB of hash buckets, but that doesn't seem like a change that belongs in a pgsql-bugs thread. I'll put that on a list of hash join ideas/improvements for discussion on the pgsql-hackers list. In your case I'd doubt the limit really hurts since work_mem was clearly set too high for the system and "64 million buckets ought to be enough" for a smaller setting on your machine. Clearly a 1TB box could make good use of more buckets than that though. -- Thomas Munro http://www.enterprisedb.com
Вложения
On Thu, Jun 7, 2018 at 4:23 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Frits Jalvingh <jal@etc.to> writes: >> The "good" news is that this effect is apparently caused by something else. >> I fired those statements through an IDE (IntelliJ) written in Java and >> using jdbc. There seems to be something odd going on in there, because when >> I paste the query in psql then the effect with and without explain looks >> the same: 3 processes of which 2 "parallel workers" doing enormous amounts >> of I/O at 50..90% CPU. I will try to find out what easter egg in either >> that IDE or the JDBC driver causes this 8-/. > > Ah. Something about query parameterization, is my bet. The symptoms match this other report I just diagnosed over here: https://www.postgresql.org/message-id/CAEepm%3D3rvRBxD_g8RngT6nAtUuTdGskL0xdDK3WXroebLDRwgg%40mail.gmail.com We only allow parallelism if you asked for all rows to be returned, but these GUI tools ask for a limited number. This is probably an unintended consequence of commit 691b8d59, but I'm not sure. Let's discuss that over in that other thread. -- Thomas Munro http://www.enterprisedb.com
On Thu, Jun 7, 2018 at 1:00 PM, Thomas Munro <thomas.munro@enterprisedb.com> wrote: >> ERROR: invalid DSA memory alloc request size 1073741824 > > Here is a proposed fix Here is a tidier version that I'd like to commit before beta2, if there are no objections. I've added this to the PostgreSQL 11 open items page. Here's a simple way to reach the error with default settings in unpatched master (given enough memory and disk): create table foo (i int); insert into foo select generate_series(1, 128000000); set work_mem = '2GB'; select count(*) from foo f1 join foo f2 using (i); -- Thomas Munro http://www.enterprisedb.com
Вложения
Thomas Munro <thomas.munro@enterprisedb.com> writes:
> Here is a tidier version that I'd like to commit before beta2, if
> there are no objections. I've added this to the PostgreSQL 11 open
> items page.
That looks fine as far as it goes. But I noticed that the code that
actually resizes the hashtable looks like
/* Double the size of the bucket array. */
pstate->nbuckets *= 2;
size = pstate->nbuckets * sizeof(dsa_pointer_atomic);
hashtable->batches[0].shared->size += size / 2;
dsa_free(hashtable->area, hashtable->batches[0].shared->buckets);
hashtable->batches[0].shared->buckets =
dsa_allocate(hashtable->area, size);
buckets = (dsa_pointer_atomic *)
dsa_get_address(hashtable->area,
hashtable->batches[0].shared->buckets);
for (i = 0; i < pstate->nbuckets; ++i)
dsa_pointer_atomic_init(&buckets[i], InvalidDsaPointer);
with no apparent provision for failure of the realloc. So the first
question is does the query actually fail cleanly if dsa_allocate gets
an OOM, and the second is whether we really want to fail the query in
such a case, rather than plow ahead with the existing bucket array.
BTW, that method of updating shared->size would do credit to
Rube Goldberg. Wouldn't this:
hashtable->batches[0].shared->size = size;
be both faster and less confusing?
regards, tom lane
On Sun, Jun 10, 2018 at 3:51 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Thomas Munro <thomas.munro@enterprisedb.com> writes: >> Here is a tidier version that I'd like to commit before beta2, if >> there are no objections. I've added this to the PostgreSQL 11 open >> items page. > > That looks fine as far as it goes. Thanks. Pushed! > But I noticed that the code that > actually resizes the hashtable looks like > > /* Double the size of the bucket array. */ > pstate->nbuckets *= 2; > size = pstate->nbuckets * sizeof(dsa_pointer_atomic); > hashtable->batches[0].shared->size += size / 2; > dsa_free(hashtable->area, hashtable->batches[0].shared->buckets); > hashtable->batches[0].shared->buckets = > dsa_allocate(hashtable->area, size); > buckets = (dsa_pointer_atomic *) > dsa_get_address(hashtable->area, > hashtable->batches[0].shared->buckets); > for (i = 0; i < pstate->nbuckets; ++i) > dsa_pointer_atomic_init(&buckets[i], InvalidDsaPointer); > > with no apparent provision for failure of the realloc. So the first > question is does the query actually fail cleanly if dsa_allocate gets > an OOM, If dsa_allocate() fails then an error is raised and the query fails cleanly using the standard parallel query error propagation machinery (as this bug report actually showed). > and the second is whether we really want to fail the query in > such a case, rather than plow ahead with the existing bucket array. Right, we could use dsa_allocate_extended(..., DSA_ALLOC_NO_OOM) and only free and replace the original array if that succeeds, but otherwise keep using it. On the other hand, we don't do the equivalent for non-parallel hash joins (and it probably wouldn't be reached much considering the widespread use of overcommit). Unfortunately DSA_ALLOC_NO_OOM doesn't suppress all errors, in particular not the Linux-only case where posix_fallocate() fails, because dsm_create() calls dsm_impl_op(..., elevel=ERROR). So, independently of whether Parallel Hash should use that facility, I see now that I need to fix that. Perhaps the DSM_CREATE_NULL_IF_MAXSEGMENTS flag to dsm_create() should be renamed (or supplemented with another flag) and generalised to suppress the error from posix_fallocate(). Currently the only in-tree user of DSA_ALLOC_NO_OOM is dshash.c, which could leak a control object as a result of this problem (it's using DSA_ALLOC_NO_OOM not because it has a fall-back strategy for lack of memory but because it wants to clean up something else before raising an OOM error of its own). I will look into that and start a new thread. > BTW, that method of updating shared->size would do credit to > Rube Goldberg. Wouldn't this: > > hashtable->batches[0].shared->size = size; > > be both faster and less confusing? The local variable 'size' is the size of the new bucket array, but 'hashtable->batches[0].shared->size' tracks the chunks of tuples too so we can't just overwrite it. We want to subtract the old bucket array size and then add the new bucket array size, which amounts to adding half the new size. Yeah, that needs a comment. Also, I dropped the ball on point 2 of https://wiki.postgresql.org/wiki/Parallel_Hash so the initial array size isn't actually counted yet. I will propose a clean-up patch for that soon. -- Thomas Munro http://www.enterprisedb.com