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

The following bug has been logged on the website:

Bug reference:      17015
Logged by:          First name Last name
Email address:      m1ttdn7cj5@yandex.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.

[...@... ~]$ 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.

[...@... ~]$ 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!

[...@... ~]$ 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.)