Re: Getting better results from valgrind leak tracking

Hi,

On 2021-03-16 20:50:17 -0700, Andres Freund wrote:
> What I meant was that I didn't understand how there's not a leak
> danger when compilation fails halfway through, given that the context
> in question is below TopMemoryContext and that I didn't see a relevant
> TRY block. But that probably there is something cleaning it up that I
> didn't see.

Looks like it's an actual leak:

postgres[2058957][1]=# DO $do$BEGIN CREATE OR REPLACE FUNCTION foo() RETURNS VOID LANGUAGE plpgsql AS $$BEGIN frakbar;END;$$;^C
postgres[2058957][1]=# SELECT count(*), SUM(total_bytes) FROM pg_backend_memory_contexts WHERE name = 'PL/pgSQL function';
┌───────┬────────┐
│ count │ sum │
├───────┼────────┤
│ 0 │ (null) │
└───────┴────────┘
(1 row)

Time: 1.666 ms
postgres[2058957][1]=# CREATE OR REPLACE FUNCTION foo() RETURNS VOID LANGUAGE plpgsql AS $$BEGIN frakbar;END;$$;
ERROR: 42601: syntax error at or near "frakbar"
LINE 1: ...ON foo() RETURNS VOID LANGUAGE plpgsql AS $$BEGIN frakbar;EN...
^
LOCATION: scanner_yyerror, scan.l:1176
Time: 5.463 ms
postgres[2058957][1]=# CREATE OR REPLACE FUNCTION foo() RETURNS VOID LANGUAGE plpgsql AS $$BEGIN frakbar;END;$$;
ERROR: 42601: syntax error at or near "frakbar"
LINE 1: ...ON foo() RETURNS VOID LANGUAGE plpgsql AS $$BEGIN frakbar;EN...
^
LOCATION: scanner_yyerror, scan.l:1176
Time: 1.223 ms
postgres[2058957][1]=# CREATE OR REPLACE FUNCTION foo() RETURNS VOID LANGUAGE plpgsql AS $$BEGIN frakbar;END;$$;
ERROR: 42601: syntax error at or near "frakbar"
LINE 1: ...ON foo() RETURNS VOID LANGUAGE plpgsql AS $$BEGIN frakbar;EN...
^
LOCATION: scanner_yyerror, scan.l:1176
Time: 1.194 ms
postgres[2058957][1]=# SELECT count(*), SUM(total_bytes) FROM pg_backend_memory_contexts WHERE name = 'PL/pgSQL function';
┌───────┬───────┐
│ count │ sum │
├───────┼───────┤
│ 3 │ 24576 │
└───────┴───────┘
(1 row)

Something like

DO $do$ BEGIN FOR i IN 1 .. 10000 LOOP BEGIN EXECUTE $cf$CREATE OR REPLACE FUNCTION foo() RETURNS VOID LANGUAGE plpgsql AS $f$BEGIN frakbar; END;$f$;$cf$; EXCEPTION WHEN others THEN END; END LOOP; END;$do$;

will show the leak visible in top too (albeit slowly - a more
complicated statement will leak more quickly I think).

postgres[2059268][1]=# SELECT count(*), SUM(total_bytes) FROM pg_backend_memory_contexts WHERE name = 'PL/pgSQL function';
┌───────┬──────────┐
│ count │ sum │
├───────┼──────────┤
│ 10000 │ 81920000 │
└───────┴──────────┘
(1 row)

The leak appears to be not new, I see it in 9.6 as well. This seems like
a surprisingly easy to trigger leak...

Looks like there's something else awry. The above DO statement takes
2.2s on an 13 assert build, but 32s on a master assert build. Spending a
lot of time doing dependency lookups:

- 94.62% 0.01% postgres postgres [.] CreateFunction
- 94.61% CreateFunction
- 94.56% ProcedureCreate
- 89.68% deleteDependencyRecordsFor
- 89.38% systable_getnext
- 89.33% index_getnext_slot
- 56.00% index_fetch_heap
+ 54.64% table_index_fetch_tuple
0.09% heapam_index_fetch_tuple
+ 28.53% index_getnext_tid
2.77% ItemPointerEquals
0.10% table_index_fetch_tuple
0.09% btgettuple
0.03% index_getnext_tid

1000 iterations: 521ms
1000 iterations: 533ms
2000 iterations: 1670ms
3000 iterations: 3457ms
3000 iterations: 3457ms
10000 iterations: 31794ms

The quadratic seeming nature made me wonder if someone broke killtuples
in this situation. And it seem that someone was me, in 623a9ba . We need
to bump xactCompletionCount in the subxid abort case as well...

Greetings,

Andres Freund