Wednesday, April 25, 2012

Why Apex 4.0.2 active sessions report took ages to run on my server

This articles discusses a workaround that might hamper the throughput of your production web site, it might be wise to implement this technique only for the time strictly needed to carry out the required investigation.

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
At first I thought that there was just something bad with my database instance, one of those odd problems that disappear when you bounce the database and you never get to know what really was the point.
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.

Monday, April 23, 2012

ORA-02080: database link is in use

Always check out the original article at http://www.oraclequirks.com for latest comments, fixes and updates.

Yet another web article about ORA-02080? Hopefully not.

ORA-02080: database link is in use

After reading several entries on this error and its remedies, including Tom Kyte's entry, I realized that the suggested cure is not always working, at least not on Oracle XE 10gR2 (at the moment I can't say on other versions, may be you can contribute on this).

Say we a database link called TEST_LINK.
The theory says that in order to explicitly close a database link connection, you must perform either of the following:

COMMIT; -- or ROLLBACK;
ALTER SESSION CLOSE DATABASE LINK test_link;

or
 
COMMIT; -- or ROLLBACK;
begin dbms_session.close_database_link('TEST_LINK'); end;

I also tried with ROLLBACK FORCE to no avail.
However if, after issuing either of the above, you are still getting the dreaded error message:
 
ORA-02080: database link is in use

it means it's time to ask what type of client you are issuing the SQL statements from.

I found out that when using SQL Developer, it's more likely to happen, even though in a bunch of cases the closing statement worked, apparently a few minutes after the COMMIT, on the contrary, SQL*Plus never failed a shot.
This odd behavior seems to be confirmed by running the following query as sysdba:

select * from v$open_cursor
where user_name = 'TEST'
and sql_text like '%test_link%';

In the case of SQL*Developer I still find the statement in V$OPEN_CURSOR, regardless of the transaction state (committed or rolled back), in the case of SQL*Plus is never listed there.

So here we have a situation where SQL*Developer exhibits a somewhat erratic behavior when it comes to closing a database link, whereas SQL*Plus seems to be always consistent.

Now, the truth is that, in most cases, you just don't need to care about this, unless, for some reason, you need to drop the database link immediately after executing the distributed query, in which case you can disconnect the session and retry the operation and so far I never encountered problems.

In conclusion I can't say why SQL Developer and SQL*Plus give different results when it comes to closing a database link, if you know something more about this, please chime in.

See message translations for ORA-02080 and search additional resources.

yes you can!

Two great ways to help us out with a minimal effort. Click on the Google Plus +1 button above or...
We appreciate your support!

latest articles