BUG #17015: trigger + array + 'md5' -> 'domain kernel: pid ... (postgres), uid ..., was killed: out of swap spac

The following bug has been logged on the website:

Bug reference: 17015
Logged by: First name Last name
Email address: m1ttdn7cj5(at)yandex(dot)com
PostgreSQL version: Unsupported/Unknown
Operating system: FreeBSD
Description:

Observing weird behaviour with some custom audit logging functions and
triggers. Here is how to reproduce:

-- Data table which is to be audit logged

CREATE TABLE ta1 ( c1 INTEGER, c2 text );

-- Generating a random string of 30 000 000 characters

INSERT INTO ta1
SELECT 30000000, array_to_string ( ARRAY_AGG ( t.c ), '' ) FROM (
SELECT chr ( CAST ( random() * 25 AS SMALLINT ) + 65 ) FROM (
SELECT generate_series ( 1, 30000000 )
) t
) t ( c );

SELECT CHAR_LENGTH ( c2 ), md5 ( c2 ) FROM ta1;

30000000;"0e6b9b88f0e1d07fce3e6e3cdac8f8c1"

Total query runtime: 740 ms.
1 row retrieved.

-- Log table

CREATE TABLE ta2 ( c1 text, c2 text, c3 text, c4 text, c5 text, c6 text, c7
text, c8 text, c9 text, c10 text );

-- Log function and trigger with 2 log information columns

CREATE FUNCTION f1 ( )
RETURNS trigger
LANGUAGE plpgsql
as $$
begin
INSERT INTO ta2
SELECT
c [ 1 ],
c [ 2 ]
FROM (
VALUES (
ARRAY [
md5 ( old.c2 ),
md5 ( new.c2 )
]
)
) t ( c );

RETURN NULL;
end;
$$;

CREATE TRIGGER tr
AFTER UPDATE
ON ta1
/* REFERENCING
NEW "NEW"
OLD "OLD" */
FOR EACH ROW
execute procedure f1 ( );

-- All good, fairly fast even on the 1st run and not hungry for memory

UPDATE ta1 SET c1 = c1 WHERE c1 = 30000000;

Query returned successfully: one row affected, 6100 ms execution time.

[(dot)(dot)(dot)(at)(dot)(dot)(dot) ~]$ while true; do swapinfo -h; sleep 1; done
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 414M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 414M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 414M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 414M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 414M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 414M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 414M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 414M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 420M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 420M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 420M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 420M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 420M 1.6G 20%
^C

SELECT * FROM ta2;

"0e6b9b88f0e1d07fce3e6e3cdac8f8c1";"0e6b9b88f0e1d07fce3e6e3cdac8f8c1";"";"";"";"";"";"";"";""

-- Log function and trigger with 10 log information columns (8 from the 10
are NULL but their values do not matter, what matters is that there are more
columns)

CREATE FUNCTION f2 ( )
RETURNS trigger
LANGUAGE plpgsql
as $$
begin
INSERT INTO ta2
SELECT
c [ 1 ],
c [ 2 ],
c [ 3 ],
c [ 4 ],
c [ 5 ],
c [ 6 ],
c [ 7 ],
c [ 8 ],
c [ 9 ],
c [ 10 ]
FROM (
VALUES (
ARRAY [
md5 ( old.c2 ), -- SUBSTRING ( old.c2 FROM 1 FOR 100 ),
md5 ( new.c2 ), -- SUBSTRING ( new.c2 FROM 1 FOR 100 ),
NULL,
NULL,
NULL,
NULL,
NULL,
NULL,
NULL,
NULL
]
)
) t ( c );

RETURN NULL;
end;
$$;

DROP TRIGGER tr ON ta1;

CREATE TRIGGER tr
AFTER UPDATE
ON ta1
/* REFERENCING
NEW "NEW"
OLD "OLD" */
FOR EACH ROW
execute procedure f2 ( );

-- Much slower and uses hundreds of MBs of memory

UPDATE ta1 SET c1 = c1 WHERE c1 = 30000000;

Query returned successfully: one row affected, 29680 ms execution time.

[(dot)(dot)(dot)(at)(dot)(dot)(dot) ~]$ while true; do swapinfo -h; sleep 1; done
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 419M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 419M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 419M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 419M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 419M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 420M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 420M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 420M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 420M 1.6G 20%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 451M 1.6G 22%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 486M 1.5G 24%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 507M 1.5G 25%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 546M 1.5G 27%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 569M 1.4G 28%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 592M 1.4G 29%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 615M 1.4G 30%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 638M 1.4G 31%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 659M 1.4G 32%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 663M 1.4G 32%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 688M 1.3G 34%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 733M 1.3G 36%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 768M 1.3G 37%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 791M 1.2G 39%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 813M 1.2G 40%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 836M 1.2G 41%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 859M 1.2G 42%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 547M 1.5G 27%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 547M 1.5G 27%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 547M 1.5G 27%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 547M 1.5G 27%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 547M 1.5G 27%
Device 1K-blocks Used Avail Capacity
/dev/ada0p4.eli 2097152 547M 1.5G 27%
^C

SELECT * FROM ta2;

"0e6b9b88f0e1d07fce3e6e3cdac8f8c1";"0e6b9b88f0e1d07fce3e6e3cdac8f8c1";"";"";"";"";"";"";"";""
"0e6b9b88f0e1d07fce3e6e3cdac8f8c1";"0e6b9b88f0e1d07fce3e6e3cdac8f8c1";"";"";"";"";"";"";"";""

Originally the array had 32 elements which led to running out of swap disk
space and crashed the host.

Interestingly if 'md5' is replaced with 'SUBSTRING' then things look good
again.

What is this strange side effect of 'md5' and arrays on each other? Any
idea? Thank you!

[(dot)(dot)(dot)(at)(dot)(dot)(dot) ~]$ postgres -V
postgres (PostgreSQL) 9.5.7

(Upgrade would be hard at this point. The example above is a simplified
version of the original code, probably you would suggest to rewrite it
without array. But do not want to go that way for various reasons.)