Large Memory Allocations due to Query Parsing

I’ve recently been alerted because of an ORA-04036 (PGA memory allocation limit) error on a 12.1 Oracle database. As the problem originated in the test environment and hence was not classified as urgent, I decided to investigate the root-cause instead of simply increasing the pga_aggregate_limit. It turned out to be a good decision, because the analysis revealed an underlying parsing issue.

In this blog post, I’ll describe the troubleshooting methodology which is underpinned by ASH dictionary views (subject to licensing!), Jonathan Lewis’ My Session Workload tool, DTrace and Flame Graphs.

First, I selected the samples from v$active_session_history and aggregated the size of the allocated pga memory based on force_matching_signature.

select a.force_matching_signature,max(pga_allocated),count(*) 
 from v$active_session_history a 
 where
 sample_time between
 to_date('10.02.2017 15:34:30','dd.mm.yyyy hh24:mi:ss') and
 to_date('10.02.2017 15:34:32','dd.mm.yyyy hh24:mi:ss')
 group by a.force_matching_signature 
 order by max(pga_allocated) desc ;

FORCE_MATCHING_SIGNATURE    MAX(PGA_ALLOCATED)	COUNT(*)
7.92426005037451E18	    4544622592	       28

Second, I found out the SQL text of the largest PGA consumer by querying the shared pool based on force_matching_signature obtained in the first step:

select distinct to_char(sql_fulltext) from v$sql s , v$active_session_history a  
  where s.force_matching_signature = a.force_matching_signature and
    sample_time between
      to_date('10.02.2017 15:34:30','dd.mm.yyyy hh24:mi:ss') and
      to_date('10.02.2017 15:34:32','dd.mm.yyyy hh24:mi:ss')
;

select ...

Note: I replaced the query text with select… in the entire post, because the SQL is application-specific anyway and as such wouldn’t provide any useful information for explaining the troubleshooting methodology.

Third, I reproduced the problem by running the query in question:

set serveroutput on size 1000000
exec snap_my_stats.start_snap ;
select  ... ;
exec snap_my_stats.end_snap ;

Name                            Value
----                            -----
DB time                         517
session pga memory max          275,644,416
parse time elapsed              431

Note: the package snap_my_stats is a part of Jonathan Lewis’ My Session Workload tool.

By looking at the statistics above, we can draw following conclusions:

• the test confirmed the high PGA usage observed in v$active_session_history
• the parse time is significantly higher than the execution time
  ( execution time = DB time – parse time elapsed )

At that point, I wondered whether the PGA memory was used for parsing or for execution. This question was easily answered by collecting the statistics for explain for select… instead for the query execution:

set serveroutput on size 1000000
exec snap_my_stats.start_snap ;
explain plan for select ...
exec snap_my_stats.end_snap ;

Name                            Value
----                            -----
session pga memory max          182,386,688
parse time elapsed              452

As we can see, the largest part of the used pga was allocated during parsing. To obtain some additional insight, I collected Oracle kernel functions stacks during the query optimization by using following DTrace script:

profile:::profile-997Hz
/ pid == $target /
{
  @[ustack()] = count() ;
}

After spooling the stacks in the output file ustacks.out, I generated Flame Graphs:

stackcollapse.pl ustacks.out > ustacks.folded
flamegraph.pl ustacks.folded > ustacks.svg

Note: Since the flame graph is a heavy file which would massively slow down a browser, I didn’t embed it here. I’m including the download link instead. However, I recommend download the file and looking into it on a device with more processing power. Right click here to download the flame graph.

The function that stands out in the Flame Graph is kkojnp. The search on MOS Knowledge Base with “slow parsing kkojnp” as the key words returned the Bug 22225899 : SLOW PARSE FOR COMPLEX QUERY. The bug note suggests setting the hidden parameter _optimizer_squ_bottomup to FALSE as a workaround.

Indeed, the workaround reduced the parse time from 4.52 seconds to just 270 msec. Furthermore, the PGA usage dropped from 174 MB to 19 MB.

alter session set "_optimizer_squ_bottomup" = FALSE ;

set serveroutput on size 1000000
exec snap_my_stats.start_snap ;
explain plan for select...
exec snap_my_stats.end_snap ;

Name                            Value
----                            -----
session pga memory max          19,791,872
parse time elapsed              27

I knew so far, that disabling _optimizer_squ_bottomup helped in both reducing the parsing time and memory footprint, but did it introduce any inefficiencies into the execution plan? To answer this question, I compared consistent gets of both execution plans:

-- without the workaround
set serveroutput on size 1000000
exec snap_my_stats.start_snap ;
select ...
exec snap_my_stats.end_snap ;

Name                            Value
----                            -----
DB time                         543
consistent gets                 312,986


-- with the workaround
alter session set "_optimizer_squ_bottomup" = FALSE ;

set serveroutput on size 1000000
exec snap_my_stats.start_snap ;
select  ...
exec snap_my_stats.end_snap ;

Name                            Value
----                            -----
DB time                         23
consistent gets                 2,369

Not only did the workaround reduce the parsing time, but the execution plan that was produced more quickly was superior to the original execution plan. In this particular case, I observed the problem on a Informatica Powercenter repository database and decided to disable _optimizer_squ_bottomup in the spfile.

However, please don’t take the result of this case study as a general recommendation to disable optimizer_squ_bottomup on all your databases. Instead, consider it only as a possible solution if you hit severe parsing issues. Should you do so, make sure that you thoroughly test the application for any side effects.

Last but not least, if you liked this post, you might be also interested in another article about query parsing performance: http://nenadnoveljic.com/blog/excessive-query-parsing-time-with-long-in-lists-and-extended-statistics/ .