Thread: Function performance degrades after repeated execution
Hi,
We've been troubleshooting a slow running function in our postgres database. I've been able to boil it down to the
simplestfunction 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
gettinginsight. We are on PostgreSQL 9.6.15.
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.
so 16. 11. 2019 v 16:06 odesílatel Dave Roberge <droberge@bluetarp.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 ...
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.
On 11/16/19 8:22 AM, Dave Roberge wrote: > Hi, > > We've been troubleshooting a slow running function in our postgres database. I've been able to boil it down to the simplestfunction 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; Where are you joining table1 to either table2 or table3? -- Angular momentum makes the world go 'round.
so 16. 11. 2019 v 16:46 odesílatel Ron <ronljohnsonjr@gmail.com> napsal:
On 11/16/19 8:22 AM, Dave Roberge wrote:
> 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;
Where are you joining table1 to either table2 or table3?
good shot - there is maybe unwanted cartesian product
Pavel
--
Angular momentum makes the world go 'round.