Wednesday, October 26, 2011

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.

3 comments:

Dimitri Gielis said...

Hi Joel,

An alternative in APEX 4.1 may be to grant the apex_administrator_role to a user and then the apex_workspace_activity_log view seems to go cross workspace.

grant apex_administrator_role to ;

as that user:
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
group by workspace, application_name, application_id, page_id
order by 6, 7 asc

Unless that view is hiding some other things?

Dimitri

Joel R. Kallman said...

Hi Dimitri,

Thank you for mentioning this. Even though my example above uses APEX 4.1, the preferred approach is to use the APEX_ADMINISTRATOR_ROLE and the APEX_WORKSPACE_ACTIVITY_LOG view. If you're using APEX 3.2.1, you'll need to connect as SYS. If you're using APEX 4.1 or later, you can simply grant someone the APEX_ADMINISTRATOR_ROLE and they can query this view across all workspaces and applications.

Thanks again.

Joel

Arave said...

Joel,

Thanks for the post! We recently experienced periods of slow performance in our production instance. We also had high CPU waits and the same anonymous block was identified. Interesting cause for us was that we had moved from our old production server with 8GB of memory to a server with only 4GB. Our system admin had mistakenly setup the box with half as much memory.

Todd