Re: Function performance degrades after repeated execution

From: Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com>
To: Dave Roberge <droberge(at)bluetarp(dot)com>
Cc: "pgsql-general(at)postgresql(dot)org" <pgsql-general(at)postgresql(dot)org>
Subject: Re: Function performance degrades after repeated execution
Date: 2019-11-16 15:35:58
Message-ID: CAFj8pRC0fauvwOgjYgOWQWa3cpcEL-XQmwM0duZ9yLvqZc5f3Q@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

so 16. 11. 2019 v 16:06 odesílatel Dave Roberge <droberge(at)bluetarp(dot)com>
napsal:

> Hi,
>
> We've been troubleshooting a slow running function in our postgres
> database. I've been able to boil it down to the simplest function possible.
> It looks like this:
>
> FOR rec IN select 1 as matchval FROM table1 t1, table2 t2
> join table3 t3 on t3.col = t2.col
> WHERE t1.col = id
> LOOP
> IF rec.matchval > 0 THEN
> co := co + 1;
> END IF;
> if co % 100 = 0 then
> raise notice 'match value %', co;
> end if;
> END LOOP;
>
> Here's the interesting parts:
> - The result of that query returns about 13,000 rows.
> - If I open a PSQL session and execute the function it returns almost
> immediately.
> - If I execute the same function 4 more times in the same session (a total
> of 5 times) it returns immediately.
> - On the 6th execution it slows down. It processes 100 records every 1.5
> minutes.
> - On every subsequent execution from the same session (after 5 times) it
> is slow.
> - It reliably slows down after 5 consecutive executions.
> - If I exit the PSQL session and open a new one the function returns
> immediately (up to the 6th execution.)
> - If I replace the function from a separate session after executing it 5
> times, it returns immediately up to 5 executions.
> - The CPU spikes to 100% after the 5 execution.
>
> I'm attempting to understand what is causing the slow down after 5
> consecutive executions. But I'm having a hard time getting insight. We are
> on PostgreSQL 9.6.15.
>

6 time slow execution is known issue - it is unwanted effect of query plan
cache.

See part of doc https://www.postgresql.org/docs/9.6/sql-prepare.html

Prepared statements can use generic plans rather than re-planning with each
set of supplied EXECUTE values. This occurs immediately for prepared
statements with no parameters; otherwise it occurs only after five or more
executions produce plans whose estimated cost average (including planning
overhead) is more expensive than the generic plan cost estimate. Once a
generic plan is chosen, it is used for the remaining lifetime of the
prepared statement. Using EXECUTE values which are rare in columns with
many duplicates can generate custom plans that are so much cheaper than the
generic plan, even after adding planning overhead, that the generic plan
might never be used.

in postgresql 9.6 you can use dynamic query as workaround - it generates
only one shot plans, and it should be ok every time

FOR rec IN EXECUTE 'SELECT ...

https://www.postgresql.org/docs/9.6/plpgsql-control-structures.html#PLPGSQL-RECORDS-ITERATING

Regards

Pavel

> We've tried:
> - Increase logging to debug5 but don't get any helpful feedback there.
> - Reviewing the execution plan of the query. Seems fine when running it
> outside of the function.
> - Turn on temp file logging -- but no temp files are logged.
>
> Any ideas for where we might get insight? Or clues as to what is happening?
>
> Thank you.
>
>

In response to

Browse pgsql-general by date

  From Date Subject
Next Message Tom Lane 2019-11-16 15:37:13 Re: access to original-statement predicates in an INSTEAD-OF row trigger
Previous Message John Lumby 2019-11-16 14:52:19 Re: access to original-statement predicates in an INSTEAD-OF row trigger