A few days ago I was asked to take a look at two queries that shows up among the top queries in the Oracle SQL Developer instance viewer.

I’ve extracted two statements that are relevant for this case.

Oracle SQL Developer Instance viewer

The select statements for both records are almost identical:

SELECT
    scn,
    username,
    operation_code,
    timestamp,
    sql_redo,
    table_name,
    commit_scn,
    sequence#,
    csf,
    xidusn,
    xidslt,
    xidsqn,
    rs_id,
    ssn,
    seg_owner,
    rollback,
    row_id
FROM
    v$logmnr_contents
WHERE
        timestamp >= :1
    AND ( ( ( ( seg_owner = :"SYS_B_0"
                AND ( table_name LIKE :"SYS_B_1" ) )
              OR ( seg_owner = :"SYS_B_2"
                   AND ( table_name LIKE :"SYS_B_3" ) ) )
            AND operation_code IN ( :"SYS_B_4",
                                    :"SYS_B_5",
                                    :"SYS_B_6" ) )
          OR operation_code IN ( :"SYS_B_7",
                                 :"SYS_B_8" ) )

 

From the SELECT statement it is obvious it is about reading from the redo files/archive logs to perform real time replication of data out of the Oracle database.

 

The numbers for CPU seconds and Elapsed seconds are matter of concern (around 1440 seconds for CPU and 2400 seconds for elapsed time).

When I dig deeper to see what is going on, I realize it is about a continuously reading a fix table (LogMiner continuous mining) which is materialized in form of the redo log files.

Btw, LogMiner continuous mining is deprecated in recent releases of Oracle database but that is not related to this case.

To see what is really happening, I gather AWR SQL reports.

AWR SQL Report for the first query
AWR SQL Report for the second query

According to above reports it seems that one execution is taking about 300 seconds.

I wanted to perform one additional check by looking at V$SESSION view to confirm my conclusion:

select a.sql_id ,a.username, a.prev_exec_start, (select sysdate from dual) as current_time, a.logon_time, a.event, a.* from v$session a where sql_id in ('gxrfu71qhuawv', '9p809bf97c5hj'); 
V$SESSION query result

From the V$SESSION view it is clear that statement executes very fast, and that most of the time it is waiting (LogMiner reader: redo (idle) wait event).

Consulting Oracle Metaling confirms that the V$LOGMNR_CONTENTS view reads files sequentially from the redo log until either the filter criteria specified at startup are met or the end of the redo log file is reached.

When you combine all the information acquired so far, it is obvious that V$LOGMNR_CONTENTS is populated through the call to DBMS_LOGMNR.START_LOGMNR procedure, and it mines for log changes constantly.

It is known that the interface itself is not very fast especially in case like this when time interval is large.

However, the impact on the source system (Oracle database) is almost neglectable – from the AWR reports above, impact is 0,1 second in CPU for 8 hours interval.

Summary:

This is a typical case which proves that visual tools cannot be replacement of knowledge.

Understanding how something works under the hood, along with constant learning, is the best tool you can get.

Visual tools can only help but only in case you are able to read the report with understanding.

In this case, it is not fault of Oracle SQL Developer if you can’t read the reports it provides in a right way.



Get notified when a new post is published!

Loading

Comments

There are no comments yet. Why not start the discussion?

Leave a Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.