It's amazing how you end up spending hours on a secondary problem when you start investigating a completely different one.
I set out in pursue of an allegedly trivial problem with an apex page this morning and I found myself sucked into a vortex of high CPU usage caused by one of the oldest built-in apex reports.
I wanted to inspect the session state values of the failing page and this has always been simply a matter of opening the Active sessions apex report, look up the right session id and drill down to item values, however when I opened page 7 of application 4350 (Active Sessions report) the CPU of my virtual server was skyrocketing. This phenomenon was duly recorded by Amazon EC2's instance monitoring chart as shown below.
|a CPU spike occurs when opening the Active Sessions report|
However it turned out this time the problem was not one of that kind.
So, after confirming that the problem was with this specific page while the rest of my applications were running normally, the next task was to identify which SQL statement was consuming all this CPU.
I ran a SQLDeveloper built-in report showing the top SQL by CPU and the following query turned out to be one of the most time consuming:
select "ID", "SESSION_OWNER", "CREATED_ON", "ITEM_CACHE_COUNT", "IP_ADDRESS", "MOST_RECENT_VIEW", "DISTINCT_APPLICATIONS", count(*) over () as apxws_row_cnt from ( select * from ( select /* APEX4350P7a */ /*+ FIRST_ROWS(21) */ id, session_owner, created_on, item_cache_count, ip_address, (select max(time_stamp) mt from WWV_FLOW_ACTIVITY_LOG l where l.SESSION_ID = s.id) most_recent_view, distinct_applications from ( select "WWV_FLOW_SESSIONS$".ID as "ID", cookie session_owner, created_on, count(*) item_cache_count, count(distinct(flow_id)) distinct_applications, "WWV_FLOW_SESSIONS$".remote_addr ip_address from "WWV_FLOW_DATA" "WWV_FLOW_DATA", "WWV_FLOW_SESSIONS$" "WWV_FLOW_SESSIONS$" where WWV_FLOW_DATA.FLOW_INSTANCE(+)=WWV_FLOW_SESSIONS$.ID and (:P7_OWNER is null or instr(upper(cookie),upper(:P7_OWNER))>0) and security_group_id = :flow_security_group_id group by "WWV_FLOW_SESSIONS$".ID, cookie, created_on, remote_addr ) s ) r ) r where rownum <= to_number(:APXWS_MAX_ROW_CNT) order by "MOST_RECENT_VIEW" DESC,"CREATED_ON" DESC
By examining the explain plan it was clear that for some reason Oracle was executing two FULL TABLE SCANs on WWV_FLOW_ACTIVITY_LOG1$ and WWV_FLOW_ACTIVITY_LOG2$, two tables merged inside the view WWV_FLOW_ACTIVITY_LOG and on these tables there were no indexes on column SESSION_ID.
The result was that the query took nearly 300 seconds to scan some 250,000 rows.
Now, what if I create a couple of indexes on those two tables?
CREATE INDEX "APEX_040000"."WWV_FLOW_ACTIVITY_LOG1$_IDX4" ON "APEX_040000"."WWV_FLOW_ACTIVITY_LOG1$" ( "SESSION_ID" );
CREATE INDEX "APEX_040000"."WWV_FLOW_ACTIVITY_LOG2$_IDX4" ON "APEX_040000"."WWV_FLOW_ACTIVITY_LOG2$" ( "SESSION_ID" );
Well, the result was encouraging, from 300 seconds to less than 2 seconds.
Clearly with the next apex upgrade, if things have not been fixed, I'll have to rebuild these indexes.
And now for the real questions:
did the missing indexes disappear from my installation for some reason?
Have they ever been there in the past?
Have they been removed or lost during the evolution of Apex?
Am I the only one having this problem?
Is anybody else using the Active Session report with some thousand active sessions?
Answers are welcome.
PS: Tyler (see the comments section) suggested to put a disclaimer at the top of this article, which I did, I also added that probably it might make sense to create these additional indexes only for the time needed and removing them thereafter.