The Power of the Oracle Trace Files

Although I had different topics planned for my first blog, but I just received this client issue this morning, and I decided to share it with you to explain how to take advantage of the powerful information contained in the oracle trace files.

What is the issue?

I received a call from one of my clients. He is complaining that the oracle database is producing large amounts of trace files per sec (he mentioned 500MB/sec!). This is very interesting.

The client DBA is manually deleting the trace files to free space, until reaching a solution.  He sent me the alert file and sample traces.

Database version is 11.2.0.4 on Windows platform (Windows 2008).

 

Quick investigation:

 

Alert.log file has no major issues or errors.

The trace file has the following information:

1

2_1

3

It is clear that the above insert statement is not shareable and has 32767 child cursors.

The reason(s) for not being shared:

4

5

So, it is clear from the trace file that:

  • The problem is coming from the Enterprise Manager Control and is related to the Auditing.
  • There is one statement that is not shareable – due to the above two reasons – and that is executed frequently.

 

More Investigation:

I asked my client to run the following query to explore the above doubts more:

First Query:

select sql_id,version_count,substr(sql_text,1,30)

from v$sqlarea where version_count > 100

order by 2 desc;

SQL_ID        VERSION_COUNT SUBSTR(SQL_TEXT,1,30)

————- ————- ——————————

4vs91dcv7u1p6         32769 insert into sys.aud$( sessioni

This is the same info that we got from the trace file.

Second Query:

SELECT ‘UNBOUND_CURSOR:                 ‘||SUM(TO_NUMBER(DECODE(unbound_cursor,’Y’,1,’N’,’0′))),

‘SQL_TYPE_MISMATCH:              ‘||SUM(TO_NUMBER(DECODE(sql_type_mismatch,’Y’,1,’N’,’0′))),

‘OPTIMIZER_MISMATCH:             ‘||SUM(TO_NUMBER(DECODE(optimizer_mismatch,’Y’,1,’N’,’0′))),

‘OUTLINE_MISMATCH:               ‘||SUM(TO_NUMBER(DECODE(outline_mismatch,’Y’,1,’N’,’0′))),

‘STATS_ROW_MISMATCH:             ‘||SUM(TO_NUMBER(DECODE(stats_row_mismatch,’Y’,1,’N’,’0′))),

‘LITERAL_MISMATCH:               ‘||SUM(TO_NUMBER(DECODE(literal_mismatch,’Y’,1,’N’,’0′))),

‘FORCE_HARD_PARSE:               ‘||SUM(TO_NUMBER(DECODE(force_hard_parse,’Y’,1,’N’,’0′))),

‘EXPLAIN_PLAN_CURSOR:            ‘||SUM(TO_NUMBER(DECODE(explain_plan_cursor,’Y’,1,’N’,’0′))),

‘BUFFERED_DML_MISMATCH:          ‘||SUM(TO_NUMBER(DECODE(buffered_dml_mismatch,’Y’,1,’N’,’0′))),

‘PDML_ENV_MISMATCH:              ‘||SUM(TO_NUMBER(DECODE(pdml_env_mismatch,’Y’,1,’N’,’0′))),

‘INST_DRTLD_MISMATCH:            ‘||SUM(TO_NUMBER(DECODE(inst_drtld_mismatch,’Y’,1,’N’,’0′))),

‘SLAVE_QC_MISMATCH:              ‘||SUM(TO_NUMBER(DECODE(slave_qc_mismatch,’Y’,1,’N’,’0′))),

‘TYPECHECK_MISMATCH:             ‘||SUM(TO_NUMBER(DECODE(typecheck_mismatch,’Y’,1,’N’,’0′))),

‘AUTH_CHECK_MISMATCH:            ‘||SUM(TO_NUMBER(DECODE(auth_check_mismatch,’Y’,1,’N’,’0′))),

‘BIND_MISMATCH:                  ‘||SUM(TO_NUMBER(DECODE(bind_mismatch,’Y’,1,’N’,’0′))),

‘DESCRIBE_MISMATCH:              ‘||SUM(TO_NUMBER(DECODE(describe_mismatch,’Y’,1,’N’,’0′))),

‘LANGUAGE_MISMATCH:              ‘||SUM(TO_NUMBER(DECODE(language_mismatch,’Y’,1,’N’,’0′))),

‘TRANSLATION_MISMATCH:           ‘||SUM(TO_NUMBER(DECODE(translation_mismatch,’Y’,1,’N’,’0′))),

‘BIND_EQUIV_FAILURE:             ‘||SUM(TO_NUMBER(DECODE(bind_equiv_failure,’Y’,1,’N’,’0′))),

‘INSUFF_PRIVS:                   ‘||SUM(TO_NUMBER(DECODE(insuff_privs,’Y’,1,’N’,’0′))),

‘INSUFF_PRIVS_REM:               ‘||SUM(TO_NUMBER(DECODE(insuff_privs_rem,’Y’,1,’N’,’0′))),

‘REMOTE_TRANS_MISMATCH:          ‘||SUM(TO_NUMBER(DECODE(remote_trans_mismatch,’Y’,1,’N’,’0′))),

‘LOGMINER_SESSION_MISMATCH:      ‘||SUM(TO_NUMBER(DECODE(logminer_session_mismatch,’Y’,1,’N’,’0′))) ,

‘INCOMP_LTRL_MISMATCH:           ‘||SUM(TO_NUMBER(DECODE(incomp_ltrl_mismatch,’Y’,1,’N’,’0′))),

‘OVERLAP_TIME_MISMATCH:          ‘||SUM(TO_NUMBER(DECODE(overlap_time_mismatch,’Y’,1,’N’,’0′))),

‘EDITION_MISMATCH:               ‘||SUM(TO_NUMBER(DECODE(edition_mismatch,’Y’,1,’N’,’0′))),

‘MV_QUERY_GEN_MISMATCH:          ‘||SUM(TO_NUMBER(DECODE(mv_query_gen_mismatch,’Y’,1,’N’,’0′))),

‘USER_BIND_PEEK_MISMATCH:        ‘||SUM(TO_NUMBER(DECODE(user_bind_peek_mismatch,’Y’,1,’N’,’0′))),

‘TYPCHK_DEP_MISMATCH:            ‘||SUM(TO_NUMBER(DECODE(typchk_dep_mismatch,’Y’,1,’N’,’0′))),

‘NO_TRIGGER_MISMATCH:            ‘||SUM(TO_NUMBER(DECODE(no_trigger_mismatch,’Y’,1,’N’,’0′))),

‘FLASHBACK_CURSOR:               ‘||SUM(TO_NUMBER(DECODE(flashback_cursor,’Y’,1,’N’,’0′))),

‘ANYDATA_TRANSFORMATION:         ‘||SUM(TO_NUMBER(DECODE(anydata_transformation,’Y’,1,’N’,’0′))),

— NOTE: Next column only for 11.2.0.1

—       Please refer to http://docs.oracle.com/cd/E11882_01/server.112/e25513/dynviews_3059.htm#REFRN30254

‘INCOMPLETE_CURSOR:             ‘||SUM(TO_NUMBER(DECODE(incomplete_cursor,’Y’,1,’N’,’0′))),

— NOTE: Next column only for 11.2.0.2 and above

—       Please refer to http://docs.oracle.com/cd/E11882_01/server.112/e25513/dynviews_3059.htm#REFRN30254

‘PDDL_ENV_MISMATCH:              ‘||SUM(TO_NUMBER(DECODE(pddl_env_mismatch,’Y’,1,’N’,’0′))),

‘TOP_LEVEL_RPI_CURSOR:           ‘||SUM(TO_NUMBER(DECODE(top_level_rpi_cursor,’Y’,1,’N’,’0′))),

‘DIFFERENT_LONG_LENGTH:          ‘||SUM(TO_NUMBER(DECODE(different_long_length,’Y’,1,’N’,’0′))),

‘LOGICAL_STANDBY_APPLY:          ‘||SUM(TO_NUMBER(DECODE(logical_standby_apply,’Y’,1,’N’,’0′))),

‘DIFF_CALL_DURN:                 ‘||SUM(TO_NUMBER(DECODE(diff_call_durn,’Y’,1,’N’,’0′))),

‘BIND_UACS_DIFF:                 ‘||SUM(TO_NUMBER(DECODE(bind_uacs_diff,’Y’,1,’N’,’0′))),

‘PLSQL_CMP_SWITCHS_DIFF:         ‘||SUM(TO_NUMBER(DECODE(plsql_cmp_switchs_diff,’Y’,1,’N’,’0′))),

‘CURSOR_PARTS_MISMATCH:          ‘||SUM(TO_NUMBER(DECODE(cursor_parts_mismatch,’Y’,1,’N’,’0′))),

‘STB_OBJECT_MISMATCH:            ‘||SUM(TO_NUMBER(DECODE(stb_object_mismatch,’Y’,1,’N’,’0′))),

‘CROSSEDITION_TRIGGER_MISMATCH : ‘||SUM(TO_NUMBER(DECODE(crossedition_trigger_mismatch,’Y’,1,’N’,’0′))),

‘PQ_SLAVE_MISMATCH:              ‘||SUM(TO_NUMBER(DECODE(pq_slave_mismatch,’Y’,1,’N’,’0′))),

‘TOP_LEVEL_DDL_MISMATCH:         ‘||SUM(TO_NUMBER(DECODE(top_level_ddl_mismatch,’Y’,1,’N’,’0′))),

‘MULTI_PX_MISMATCH:              ‘||SUM(TO_NUMBER(DECODE(multi_px_mismatch,’Y’,1,’N’,’0′))),

‘BIND_PEEKED_PQ_MISMATCH:        ‘||SUM(TO_NUMBER(DECODE(bind_peeked_pq_mismatch,’Y’,1,’N’,’0′))),

‘MV_REWRITE_MISMATCH:            ‘||SUM(TO_NUMBER(DECODE(mv_rewrite_mismatch,’Y’,1,’N’,’0′))),

‘ROLL_INVALID_MISMATCH:          ‘||SUM(TO_NUMBER(DECODE(roll_invalid_mismatch,’Y’,1,’N’,’0′))),

‘OPTIMIZER_MODE_MISMATCH:        ‘||SUM(TO_NUMBER(DECODE(optimizer_mode_mismatch,’Y’,1,’N’,’0′))),

‘PX_MISMATCH:                    ‘||SUM(TO_NUMBER(DECODE(px_mismatch,’Y’,1,’N’,’0′))),

‘MV_STALEOBJ_MISMATCH:           ‘||SUM(TO_NUMBER(DECODE(mv_staleobj_mismatch,’Y’,1,’N’,’0′))),

‘FLASHBACK_TABLE_MISMATCH:       ‘||SUM(TO_NUMBER(DECODE(flashback_table_mismatch,’Y’,1,’N’,’0′))),

‘LITREP_COMP_MISMATCH:           ‘||SUM(TO_NUMBER(DECODE(litrep_comp_mismatch,’Y’,1,’N’,’0′))),

‘PLSQL_DEBUG:                    ‘||SUM(TO_NUMBER(DECODE(plsql_debug,’Y’,1,’N’,’0′))),

‘LOAD_OPTIMIZER_STATS:           ‘||SUM(TO_NUMBER(DECODE(load_optimizer_stats,’Y’,1,’N’,’0′))),

‘ACL_MISMATCH:                   ‘||SUM(TO_NUMBER(DECODE(acl_mismatch,’Y’,1,’N’,’0′))),

‘FLASHBACK_ARCHIVE_MISMATCH:     ‘||SUM(TO_NUMBER(DECODE(flashback_archive_mismatch,’Y’,1,’N’,’0′))),

‘LOCK_USER_SCHEMA_FAILED:        ‘||SUM(TO_NUMBER(DECODE(lock_user_schema_failed,’Y’,1,’N’,’0′))),

‘REMOTE_MAPPING_MISMATCH:        ‘||SUM(TO_NUMBER(DECODE(remote_mapping_mismatch,’Y’,1,’N’,’0′))),

‘LOAD_RUNTIME_HEAP_FAILED:       ‘||SUM(TO_NUMBER(DECODE(load_runtime_heap_failed,’Y’,1,’N’,’0′))),

‘HASH_MATCH_FAILED:              ‘||SUM(TO_NUMBER(DECODE(hash_match_failed,’Y’,1,’N’,’0′))),

‘PURGED_CURSOR:                  ‘||SUM(TO_NUMBER(DECODE(purged_cursor,’Y’,1,’N’,’0′))),

‘BIND_LENGTH_UPGRADEABLE:        ‘||SUM(TO_NUMBER(DECODE(bind_length_upgradeable,’Y’,1,’N’,’0′)))

FROM   v$sql_shared_cursor

WHERE  address IN (SELECT address FROM   v$sqlarea WHERE  sql_id = ‘4vs91dcv7u1p6’);

6

The above reasons are also matching the two reasons that we got from the trace file.

Third Query:

select * from v$sql_shared_cursor where address in (select address from v$sqlarea where sql_id = ‘4vs91dcv7u1p6’);

8

 

This query also produced a number of records = the number of the child cursors ( 32767 rows)

As a quick action and to confirm my understanding, I asked my client to stop the EM DBConsole (actually they don’t use it !!), and we were happy that no more trace files were produced!!!.

Second Issue:

After fixing the above issue (with a workaround , not a final solution ), the client told me that when he is trying to login to the database with normal database user, he is getting the following errors:

7

ORA-17059 is known to be related to memory corruptions. I asked my client to either restart the database or flush the shared pool using:

connect / as sysdba

alter system flush shared_pool;

alter system flush shared_pool;

alter system flush shared_pool;

exit

and this fixed the above login error.

 

Final Conclusion:

Although there are many bugs and related patches for fixing similar non-shareable cursors issues ,like:

Bug 10636231 – High version count for INSERT .. RETURNING statements with reason INST_DRTLD_MISMATCH [ID 10636231.8]

My advise for my client was to leave this buggy oracle release ( 12.1.0.1) and to upgrade the database to the latest available patchset (11.2.0.4) or to 12c (12.1.0.2).

Advertisements

2 thoughts on “The Power of the Oracle Trace Files

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s