High CPU Waits and SQL from Oracle APEX

I was recently at a customer site helping one of the DBAs diagnose a performance issue on their rather large Oracle Application Express instance (over 800 production applications on the one instance). This gentleman self-admittedly didn't know all that much about APEX but he was adept at producing and analyzing ASH (Active Session History) and AWR (Active Workload Repository) reports.

He showed me the extraordinarily high CPU times between 0900 and 1100 his time, and he traced it to the following PL/SQL block that "comes from APEX":

declare 
   rc__ number; 
   simple_list__ owa_util.vc_arr; 
    complex_list__ owa_util.vc_arr; 
begin 
owa.init_cgi_env(:n__, :nm__, :v__); 
htp.HTBUF_LEN := 63; 
null;  null; 
simple_list__(1) := 'sys.%'; 
simple_list__(2) := 'dbms\_%'; 
simple_list__(3) := 'utl\_%'; 
simple_list__(4) := 'owa\_%'; 
simple_list__(5) := 'owa.%'; 
simple_list__(6) := 'htp.%'; 
simple_list__(7) := 'htf.%'; 
simple_list__(8) := 'wpg_docload.%'; 
simple_list__(9) := 'ctxsys.%'; 
simple_list__(10) := 'mdsys.%'; 
if ((owa_match.match_pattern(p_string => 'f' /* */, p_simple_pattern => simple_list__ , p_complex_pattern => complex_list__ , p_use_special_chars => false))) then 
    rc__ := 2; 
else 
    null; null; f(p=>:p); 
if (wpg_docload.is_file_download) then 
   rc__ := 1; 
   wpg_docload.get_download_file(:doc_info); 
   null;  null;   null; 
   commit; 
else 
  rc__ := 0;  null;      null;   null;  commit; 
   owa.get_page(:data__, :ndata__); 
end if; 
end if; 
:rc__ := rc__; 
end;

I've worked with Oracle Support on issues exactly like this from other customers too, so it seems to be a common problem "with APEX".

As I explained to this customer:

1. The engine of Oracle Application Express is written in SQL and PL/SQL.
2. When someone performs a page request from their browser to the Application Express engine, they are ultimately calling a PL/SQL procedure which is the entry point into APEX.
3. Oracle Application Express is front-ended by a Web server which has some facility to map requests in the URL to execution of the APEX engine - this is usually either Apache & mod_plsql or the APEX Listener or the XDB HTTP Protocol Server & embedded PL/SQL Gateway.
4. This "agent" on the Web server prepares an anonymous PL/SQL block for each and every request into the APEX engine. The PL/SQL he was showing me was exactly this anonymous PL/SQL block.

To state this succinctly and in more lucid terms, the PL/SQL block he was showing me wasn't anything out of the ordinary. I saw an anonymous PL/SQL block which was ultimately calling the APEX engine (via the code in the block: f(p=>:p); ). And since he showed me that this specific PL/SQL block executed about 800K times in an hour, I said that this directly correlated to the number of page events on his system, e.g., the number of times a page was rendered or posted or report paginated. He needed to drill down into the APEX instance and see what was consuming the vasty majority of execution time within APEX.

While there are nice instance administration reports in APEX to convey this type of information, this DBA didn't have instance administration access - poor guy. So we did some very basic queries against the APEX views to return the necessary information.

One of the most relevant views for him was APEX_WORKSPACE_ACTIVITY_LOG. Connecting as SYS (or in APEX 4.1 or later, connecting as SYS or a database user granted the APEX_ADMINISTRATOR_ROLE database role), we are able to see all information across all applications and workspaces. So we came up with a very easy query to pinpoint the slowest pages on the system during his time window:

select workspace, application_name, application_id, page_id, count(*) total_page_events, avg(elapsed_time) avg_elapsed_time, sum(elapsed_time) elapsed_time
  from apex_workspace_activity_log
 where view_date between to_date('201110260900','RRRRMMDDHH24MISS') and to_date('201110261100','RRRRMMDDHH24MISS')
 group by workspace, application_name, application_id, page_id
 order by 6, 7 asc

Thus, using this query, I was then able to tell him which application and page was consuming, on average, the most time on his system. Then, using this information along with other APEX views, we were able to identify the workspace names, applications, pages, report queries and eventually the administrators of these workspaces and applications so they could begin their own analysis and tuning exercise.