Обсуждение: [BUGS] BUG #14843: CREATE TABLE churns through all memory, crashes db

The following bug has been logged on the website:

Bug reference:      14843
Logged by:           Ben
Email address:      ropeladder@gmail.com
PostgreSQL version: 10rc1
Operating system:   Linux Mint 18.2
Description:

(first bug report here so please let me know if this can be improved)

Congrats on the new release!

I just installed v10 and am trying to re-run an ETL I had scripted. I'm
unable to run a CREATE TABLE command that works fine in 9.6 (it took 83
seconds). When I try to run it in v10 it quickly maxes out my RAM usage and
then swallows up all my virtual memory before finally  crashing
PostgreSQL.

The command takes a table with one jsonb document and creates a new table
with 3 rows: one jsonb, one text, and one timestamp. The initial table has
2.6M rows, the new table should have 4.9M rows (because of a
jsonb_array_elements() expansion). The actual query is below:

CREATE TABLE new_table as (
SELECT   jsonb_array_elements(doc->'text'->0->'hasauthor') doc,   doc->'text'->0->'$'->>'id' rid,
regexp_replace(doc->>'mtime','[TZ]','')::timestamp mtime
 
FROM source_table
WHERE (doc#>'{"text",0,"hasauthor"}') IS NOT NULL)

The 2.6M jsonb documents in the source table are structured similar to
this:

{"$": {"xmlns": "http://amf.openlib.org", "xmlns:xsi":
"http://www.w3.org/2001/XMLSchema-instance", "xmlns:repec":
"http://repec.openlib.org", "xsi:schemaLocation": "http://amf.openlib.org
http://amf.openlib.org/2001/amf.xsd"}, "text": [{"$": {"id":
"RePEc:zwi:ipaper:56"}, "date": [{"$": {"event": "created"}, "_":
"2009-02"}], "file": [{"url":
["http://www.url.edu/documents/issuepapers/ip56.pdf"], "format":
["application/pdf"]}], "type": ["preprint"], "title": ["The Need for New
Milk Pricing Policies"], "status": ["Number 56 18 pages"], "abstract":
["Long text string."], "ispartof": [{"collection": [{"$": {"ref":
"RePEc:zwi:ipaper"}}]}], "keywords": ["milk, dairy, pricing, price gouging,
New England"], "hasauthor": [{"person": [{"name": ["Adam Lastname"],
"email": ["email@gmail.com"], "ispartof": [{"organization": [{"name":
["University of Connecticut"]}]}]}]}, {"person": [{"name": ["Ronald
Lastname"], "email": ["email@email.com"], "ispartof": [{"organization":
[{"name": ["University of Connecticut"]}]}]}]}]}], "mtime":
"2014-05-31T03:59:33.000Z"}


--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

Hi!

On 2017-10-05 23:03:21 +0000, ropeladder@gmail.com wrote:
> (first bug report here so please let me know if this can be improved)

Thanks for reporting. This is a pretty good start.


> The command takes a table with one jsonb document and creates a new table
> with 3 rows: one jsonb, one text, and one timestamp. The initial table has
> 2.6M rows, the new table should have 4.9M rows (because of a
> jsonb_array_elements() expansion). The actual query is below:
> 
> CREATE TABLE new_table as (
> SELECT
>     jsonb_array_elements(doc->'text'->0->'hasauthor') doc,
>     doc->'text'->0->'$'->>'id' rid,
>     regexp_replace(doc->>'mtime','[TZ]',' ')::timestamp mtime
> FROM source_table
> WHERE (doc#>'{"text",0,"hasauthor"}') IS NOT NULL)
> 
> The 2.6M jsonb documents in the source table are structured similar to
> this:
> 
> {"$": {"xmlns": "http://amf.openlib.org", "xmlns:xsi":
> "http://www.w3.org/2001/XMLSchema-instance", "xmlns:repec":
> "http://repec.openlib.org", "xsi:schemaLocation": "http://amf.openlib.org
> http://amf.openlib.org/2001/amf.xsd"}, "text": [{"$": {"id":
> "RePEc:zwi:ipaper:56"}, "date": [{"$": {"event": "created"}, "_":
> "2009-02"}], "file": [{"url":
> ["http://www.url.edu/documents/issuepapers/ip56.pdf"], "format":
> ["application/pdf"]}], "type": ["preprint"], "title": ["The Need for New
> Milk Pricing Policies"], "status": ["Number 56 18 pages"], "abstract":
> ["Long text string."], "ispartof": [{"collection": [{"$": {"ref":
> "RePEc:zwi:ipaper"}}]}], "keywords": ["milk, dairy, pricing, price gouging,
> New England"], "hasauthor": [{"person": [{"name": ["Adam Lastname"],
> "email": ["email@gmail.com"], "ispartof": [{"organization": [{"name":
> ["University of Connecticut"]}]}]}]}, {"person": [{"name": ["Ronald
> Lastname"], "email": ["email@email.com"], "ispartof": [{"organization":
> [{"name": ["University of Connecticut"]}]}]}]}]}], "mtime":
> "2014-05-31T03:59:33.000Z"}

Could you either try to form a reproducible demonstration of the problem
out of this, or get a memory context dump?  If you disable the kernel's
overcommit heuristics, your computer won't crash on OOM, instead
postgres will get an error, and log a dump that shows where memory is
used.

I use
$ cat /etc/sysctl.d/60-oom.conf
vm.overcommit_memory = 2
vm.overcommit_ratio = 50

for that purpose (that means only swap + 50% of memory can be handed out
to applications, if you don't have swap you might want to use 80 or
such).

Greetings,

Andres Freund


-- 
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On Fri, Oct 6, 2017 at 8:16 AM, Andres Freund <andres@anarazel.de> wrote:
> Could you either try to form a reproducible demonstration of the problem
> out of this, or get a memory context dump?  If you disable the kernel's
> overcommit heuristics, your computer won't crash on OOM, instead
> postgres will get an error, and log a dump that shows where memory is
> used.

It is not really complicated to reproduce the problem. Just insert the
JSON data attached into a table, multiply it and then run the query
given in the report. I could easily get out an OOM error:
ERROR:  53200: out of memory
DETAIL:  Failed on request of size 1085.
LOCATION:  palloc, mcxt.c:868
And a dump:
TopMemoryContext: 161440 total in 7 blocks; 66016 free (5 chunks); 95424 used
  Record information cache: 8192 total in 1 blocks; 1760 free (0
chunks); 6432 used
  TableSpace cache: 8192 total in 1 blocks; 2272 free (0 chunks); 5920 used
  Operator lookup cache: 24576 total in 2 blocks; 10936 free (4
chunks); 13640 used
  pgstat TabStatusArray lookup hash table: 8192 total in 1 blocks;
1632 free (0 chunks); 6560 used
  TopTransactionContext: 8192 total in 1 blocks; 7944 free (1 chunks); 248 used
  MessageContext: 65536 total in 4 blocks; 29208 free (3 chunks); 36328 used
  Operator class cache: 8192 total in 1 blocks; 736 free (0 chunks); 7456 used
  smgr relation table: 24576 total in 2 blocks; 12960 free (3 chunks);
11616 used
  TransactionAbortContext: 32768 total in 1 blocks; 32728 free (0
chunks); 40 used
  Portal hash: 8192 total in 1 blocks; 736 free (0 chunks); 7456 used
  PortalMemory: 8192 total in 1 blocks; 7872 free (0 chunks); 320 used
    PortalHeapMemory: 1024 total in 1 blocks; 800 free (0 chunks); 224 used
      ExecutorState: 62906368 total in 17 blocks; 13736 free (35
chunks); 62892632 used
        printtup: 8192 total in 1 blocks; 8152 free (0 chunks); 40 used
        ExprContext: 8192 total in 1 blocks; 7152 free (0 chunks); 1040 used
        ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
  Relcache by OID: 24576 total in 2 blocks; 11840 free (3 chunks); 12736 used
  CacheMemoryContext: 516096 total in 6 blocks; 23264 free (1 chunks);
492832 used
    pg_statistic_ext_relid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_db_role_setting_databaseid_rol_index: 1024 total in 1 blocks;
256 free (0 chunks); 768 used
    pg_user_mapping_user_server_index: 1024 total in 1 blocks; 256
free (0 chunks); 768 used
    pg_user_mapping_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_type_oid_index: 1024 total in 1 blocks; 336 free (0 chunks); 688 used
    pg_type_typname_nsp_index: 1024 total in 1 blocks; 200 free (0
chunks); 824 used
    pg_ts_template_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_ts_template_tmplname_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_ts_parser_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_ts_parser_prsname_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_ts_dict_oid_index: 1024 total in 1 blocks; 392 free (0 chunks); 632 used
    pg_ts_dict_dictname_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_ts_config_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_ts_config_cfgname_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_ts_config_map_index: 3072 total in 2 blocks; 1968 free (0
chunks); 1104 used
    pg_transform_type_lang_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_transform_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_tablespace_oid_index: 1024 total in 1 blocks; 336 free (0
chunks); 688 used
    pg_subscription_rel_srrelid_srsubid_index: 1024 total in 1 blocks;
256 free (0 chunks); 768 used
    pg_subscription_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_subscription_subname_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_statistic_relid_att_inh_index: 3072 total in 2 blocks; 1912
free (0 chunks); 1160 used
    pg_statistic_ext_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_statistic_ext_name_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_sequence_seqrelid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_replication_origin_roname_index: 1024 total in 1 blocks; 392
free (0 chunks); 632 used
    pg_replication_origin_roiident_index: 1024 total in 1 blocks; 392
free (0 chunks); 632 used
    pg_class_relname_nsp_index: 1024 total in 1 blocks; 200 free (0
chunks); 824 used
    pg_range_rngtypid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_publication_rel_prrelid_prpubid_index: 1024 total in 1 blocks;
256 free (0 chunks); 768 used
    pg_publication_rel_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_publication_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_publication_pubname_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_proc_oid_index: 1024 total in 1 blocks; 336 free (0 chunks); 688 used
    pg_proc_proname_args_nsp_index: 3072 total in 2 blocks; 1912 free
(0 chunks); 1160 used
    pg_partitioned_table_partrelid_index: 1024 total in 1 blocks; 392
free (0 chunks); 632 used
    pg_opfamily_oid_index: 1024 total in 1 blocks; 392 free (0 chunks); 632 used
    pg_opfamily_am_name_nsp_index: 3072 total in 2 blocks; 1968 free
(0 chunks); 1104 used
    pg_operator_oid_index: 1024 total in 1 blocks; 336 free (0 chunks); 688 used
    pg_operator_oprname_l_r_n_index: 3072 total in 2 blocks; 1912 free
(0 chunks); 1160 used
    pg_namespace_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_namespace_nspname_index: 1024 total in 1 blocks; 336 free (0
chunks); 688 used
    pg_language_oid_index: 1024 total in 1 blocks; 392 free (0 chunks); 632 used
    pg_language_name_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_foreign_table_relid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_foreign_server_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_foreign_server_name_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_foreign_data_wrapper_oid_index: 1024 total in 1 blocks; 392
free (0 chunks); 632 used
    pg_foreign_data_wrapper_name_index: 1024 total in 1 blocks; 392
free (0 chunks); 632 used
    pg_event_trigger_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_event_trigger_evtname_index: 1024 total in 1 blocks; 392 free
(0 chunks); 632 used
    pg_enum_typid_label_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_enum_oid_index: 1024 total in 1 blocks; 392 free (0 chunks); 632 used
    pg_default_acl_role_nsp_obj_index: 3072 total in 2 blocks; 1968
free (0 chunks); 1104 used
    pg_conversion_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_constraint_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_conversion_name_nsp_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_conversion_default_index: 3072 total in 2 blocks; 1968 free (0
chunks); 1104 used
    pg_collation_oid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_collation_name_enc_nsp_index: 3072 total in 2 blocks; 1968 free
(0 chunks); 1104 used
    pg_opclass_am_name_nsp_index: 3072 total in 2 blocks; 1968 free (0
chunks); 1104 used
    pg_cast_source_target_index: 1024 total in 1 blocks; 200 free (0
chunks); 824 used
    pg_auth_members_role_member_index: 1024 total in 1 blocks; 256
free (0 chunks); 768 used
    pg_attribute_relid_attnam_index: 1024 total in 1 blocks; 256 free
(0 chunks); 768 used
    pg_amop_fam_strat_index: 3072 total in 2 blocks; 1968 free (0
chunks); 1104 used
    pg_amop_opr_fam_index: 3072 total in 2 blocks; 1968 free (0
chunks); 1104 used
    pg_aggregate_fnoid_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_shseclabel_object_index: 3072 total in 2 blocks; 1968 free (0
chunks); 1104 used
    pg_auth_members_member_role_index: 1024 total in 1 blocks; 256
free (0 chunks); 768 used
    pg_authid_oid_index: 1024 total in 1 blocks; 392 free (0 chunks); 632 used
    pg_authid_rolname_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_database_oid_index: 1024 total in 1 blocks; 336 free (0 chunks); 688 used
    pg_database_datname_index: 1024 total in 1 blocks; 392 free (0
chunks); 632 used
    pg_trigger_tgrelid_tgname_index: 1024 total in 1 blocks; 256 free
(0 chunks); 768 used
    pg_rewrite_rel_rulename_index: 1024 total in 1 blocks; 256 free (0
chunks); 768 used
    pg_amproc_fam_proc_index: 3072 total in 2 blocks; 1912 free (0
chunks); 1160 used
    pg_opclass_oid_index: 1024 total in 1 blocks; 336 free (0 chunks); 688 used
    pg_index_indexrelid_index: 1024 total in 1 blocks; 336 free (0
chunks); 688 used
    pg_attribute_relid_attnum_index: 1024 total in 1 blocks; 200 free
(0 chunks); 824 used
    pg_class_oid_index: 1024 total in 1 blocks; 336 free (0 chunks); 688 used
  WAL record construction: 49776 total in 2 blocks; 6568 free (0
chunks); 43208 used
  PrivateRefCount: 8192 total in 1 blocks; 2808 free (0 chunks); 5384 used
  MdSmgr: 8192 total in 1 blocks; 7024 free (0 chunks); 1168 used
  LOCALLOCK hash: 8192 total in 1 blocks; 736 free (0 chunks); 7456 used
  Timezones: 104128 total in 2 blocks; 2808 free (0 chunks); 101320 used
  ErrorContext: 8192 total in 1 blocks; 8152 free (3 chunks); 40 used
Grand total: 64125904 bytes in 152 blocks; 315744 free (58 chunks);
63810160 used

This is suspicious:
      ExecutorState: 62906368 total in 17 blocks; 13736 free (35
chunks); 62892632 used
-- 
Michael

-- 
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On Fri, Oct 6, 2017 at 10:09 AM, ben m <ropeladder@gmail.com> wrote:
> Thanks, I'm assuming that's the same error as I'm getting. (Where do you get
> the memory dump logs from exactly? It just took me 45 minutes to find the
> main postgres logs...)

(Please avoid top-posting)
Well, this depends on your installation and distribution, which is
decided by how Postgres is packaged and deployed on Linux Mint. The
logs are found depending on the configuration of postgresql.conf. If
you are using stderr, or csvlog as log_destination, you would find the
new function called pg_current_logfile() interesting to know what is
the current log file in use. If log_directory is defined as an
absolute path you could also directly getting to it. But this really
depends on Mint, and this is an unknown territory for me.
-- 
Michael


-- 
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On Fri, Oct 6, 2017 at 10:00 AM, Michael Paquier
<michael.paquier@gmail.com> wrote:
> This is suspicious:
>       ExecutorState: 62906368 total in 17 blocks; 13736 free (35
> chunks); 62892632 used

The introduction of the ProjectSet node has caused the regressionin
the executor visibly. A bisect run is showing me this commit as the
culprit
commit 69f4b9c85f168ae006929eec44fc44d569e846b9
Author: Andres Freund <andres@anarazel.de>
Date:   Wed Jan 18 12:46:50 2017 -0800
Move targetlist SRF handling from expression evaluation to new executor node.

I was expecting a leak of some kind first, but valgrind does not
complain when executing the query eating all the memory. Before this
commit the memory usage remains low and stable, less than 1% in my
environments.
-- 
Michael


-- 
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On 2017-10-06 12:57:59 +0900, Michael Paquier wrote:
> On Fri, Oct 6, 2017 at 10:00 AM, Michael Paquier
> <michael.paquier@gmail.com> wrote:
> > This is suspicious:
> >       ExecutorState: 62906368 total in 17 blocks; 13736 free (35
> > chunks); 62892632 used
> 
> The introduction of the ProjectSet node has caused the regressionin
> the executor visibly. A bisect run is showing me this commit as the
> culprit
> commit 69f4b9c85f168ae006929eec44fc44d569e846b9
> Author: Andres Freund <andres@anarazel.de>
> Date:   Wed Jan 18 12:46:50 2017 -0800
> Move targetlist SRF handling from expression evaluation to new executor node.
> 
> I was expecting a leak of some kind first, but valgrind does not
> complain when executing the query eating all the memory. Before this
> commit the memory usage remains low and stable, less than 1% in my
> environments.

It's "just" a MemoryContextSwitchTo() that some idiot^WI forgot and
reviews didn't spot. The ResetExprContext() in ExecProjectSet() is
correctly placed afaict, it's just that we leak (query scope) a lot into
the surrounding memory context.  A MemoryContextSwitchTo() at the top &
bottom of ExecProjectSet() fixes the issue for me.

Greetings,

Andres Freund


-- 
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

Andres Freund <andres@anarazel.de> writes:
> It's "just" a MemoryContextSwitchTo() that some idiot^WI forgot and
> reviews didn't spot.

Yeah, I had just come to the same conclusion.  I have a fix about ready
to commit, unless you're nearly there ...
        regards, tom lane


-- 
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On 2017-10-06 14:18:57 -0400, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> > It's "just" a MemoryContextSwitchTo() that some idiot^WI forgot and
> > reviews didn't spot.
> 
> Yeah, I had just come to the same conclusion.  I have a fix about ready
> to commit, unless you're nearly there ...

Please go ahead in that case.

Thanks,

Andres


-- 
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On Sat, Oct 7, 2017 at 3:18 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Andres Freund <andres@anarazel.de> writes:
>> It's "just" a MemoryContextSwitchTo() that some idiot^WI forgot and
>> reviews didn't spot.
>
> Yeah, I had just come to the same conclusion.  I have a fix about ready
> to commit, unless you're nearly there ...

Ah, yes. I see. That makes sense.
-- 
Michael


-- 
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs