Tracing Enabled for Sessions After Instance Restart

12 02 2010

February 12, 2010

An recent thread in the comp.databases.oracle.server Usenet group brought up an interesting question.  What would cause a 10046 trace at level 12 and and errorstack trace at level 3 for event 21700 to be enabled for sessions every time the original poster bounced the Oracle XE instance?  Is this possibly a sign that someone modified an initialization parameter?  Did someone modify the application to enabling tracing to log files?  Is it a bug in Oracle XE? 

Fortunately, the OP provided a portion of one of the trace files, as shown below:

*** SERVICE NAME:(SYS$USERS) 2010-02-02 09:46:36.593
*** SESSION ID:(31.46) 2010-02-02 09:46:36.593
=====================
PARSING IN CURSOR #6 len=69 dep=2 uid=0 oct=42 lid=0 tim=80934443123 hv=3164292706 ad='6688fd70'
alter session set events '10046 trace name context forever, level 12'
END OF STMT
EXEC #6:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934443118
=====================
PARSING IN CURSOR #6 len=71 dep=2 uid=0 oct=42 lid=0 tim=80934681241 hv=681663222 ad='6b8cb08c'
alter session set events '21700 trace name errorstack forever, level 3'
END OF STMT
PARSE #6:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934681236
BINDS #6:
EXEC #6:c=0,e=8426,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934748960
=====================
PARSING IN CURSOR #6 len=34 dep=2 uid=0 oct=42 lid=0 tim=80934753347 hv=1152259314 ad='66a0f058'
alter session set sql_trace = TRUE
END OF STMT
PARSE #6:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934753343
BINDS #6:
EXEC #6:c=0,e=29497,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934836162
=====================
PARSING IN CURSOR #7 len=435 dep=1 uid=0 oct=47 lid=0 tim=80934862347 hv=545826169 ad='6b897000'
begin
      execute immediate 'alter session set max_dump_file_size = unlimited';
      execute immediate 'alter session set tracefile_identifier = ''10046via_app''';
      execute immediate 'alter session set events ''10046 trace name context forever, level 12''';
      execute immediate 'alter session set events ''21700 trace name errorstack forever, level 3''';
      execute immediate 'alter session set sql_trace = TRUE';
  end;
END OF STMT

So, from the above trace file, is the tracing caused by:

  • A bug in Oracle XE
  • An application that was modified
  • A modified parameter in the spfile/pfile
  • None of the above

The number following dep= in the trace file is a significant clue.  SQL statements that are submitted by client application code will appear in 10046 trace files with dep= set to 0, so that probably rules out a change to the application code, unless of course the application is executing a PL/SQL block.  The discrete ALTER SESSION statements in the trace file that are wrapped in EXECUTE IMMEDIATE statements probably rules out the possibility of a parameter that was modified in the spfile/pfile and probably also rules out the possibilty of a bug in Oracle XE.  So, what might the next step be to find the cause of the trace files?

Another possibility is either a LOGON or STARTUP trigger that is enabling the trace.  The OP mentioned in the thread that he had enabled tracing earlier to troubleshoot a problem.  The tracing is apparently enabled in a PL/SQL procedure or anonymous PL/SQL block based on the value of dep= and the EXECUTE IMMEDIATE calls, so either a LOGON or STARTUP trigger is a possibility.  To test this possibility, you might execute a SQL statement like this:

SELECT
  TRIGGER_NAME,
  TRIGGER_TYPE,
  TRIGGERING_EVENT
FROM
  DBA_TRIGGERS
WHERE
  OWNER='SYS'
  AND TRIGGER_TYPE IN ('BEFORE EVENT','AFTER EVENT')
  AND SUBSTR(TRIGGERING_EVENT,1,5) IN ('START','LOGON');

TRIGGER_NAME           TRIGGER_TYPE TRIGGERING_EVENT
---------------------- ------------ ----------------
LOGON_FIX_MYAPP_PERF   AFTER EVENT  LOGON
LOGON_CAPTURE_10046    AFTER EVENT  LOGON
ENABLE_OUTLINES_TRIG   AFTER EVENT  STARTUP

If the above returned no rows, there is still a very small chance that a logon trigger or startup trigger is owned by a user other than SYS, so it might make sense to repeat the SQL statement without the OWNER=’SYS’ predicate in the WHERE clause.  In my case the SQL statement returned three rows – two logon triggers and one startup trigger.  The logon trigger name LOGON_CAPTURE_10046 is a significant indicator that a trigger is present that will enable a 10046 trace when the user logs into the database – it helps to use a consistent and descriptive naming convention.

The OP did not show the output of the above SQL statement, but did state that he found and removed a logon trigger that enabled the two traces.  If such a trigger is found, and you know that the trigger does not belong in the database, the trigger may be removed by connecting to the database as the SYS user and dropping the trigger:

DROP TRIGGER LOGON_CAPTURE_10046;

Actions

Information

5 responses

12 02 2010
Timur Akhmadeev

Oh, that one was simple :) Just yesterday I have the same issue on my test 11.2.0.1 database – 10046 was on and I couldn’t disable it. I’ve tried:
1) 10046 off
2) dbms_session.session_trace_disable
3) oradebug 10046 trace name context off
and nothing helped. I thought maybe SQL_TRACE is not only deprecated, but has a bug which prevents it from turning off. It turned out dbms_monitor.database_trace_enable can’t be overridden on the session level, which is strange.

12 02 2010
Charles Hooper

Timur,

That does sound like it would be hard to troubleshoot. Bouncing the database in your case probably would have magically fixed your problem, but that might not have been a possibility for you.

Thanks for the reminder. It appears that you could also end up in the same situation by executing an ALTER SYSTEM call to enable a 10046 trace.

8 03 2010
coskan

I think instead of checking triggers checking dba_source for possible 10046 or sql_trace statement might be on spot in case if it is not trigger like this.

8 03 2010
Charles Hooper

Coskan,

That is a great idea. Initially, when I read your comment I thought that reviewing DBA_SOURCE would be a very time consuming task – in part because of the number of different ways that a 10046 trace could be enabled. However, the portion of the trace file posted by the OP provided text that could be used to search the DBA_SOURCE view: “alter session set events ‘10046 trace name context forever, level 12′” – so searching DBA_SOURCE probably would not have been too difficult.

15 09 2011
Charles Hooper

I think that I might have found something interesting that is related to this blog article: Doc ID 556756.1, “SQL TRACE GENERATING TO TRACE FILES NEVER STOPS”

Just out of curiosity, has anyone noticed that if a 10046 trace is enabled system-wide (ALTER SYSTEM or DBMS_MONITOR.DATABASE_TRACE_ENABLE) that the trace cannot be disabled for certain sessions (likely background processes)? I thought that I encountered this problem the last time I tested system-wide 10046 traces, and I thought that I recalled reading that this was a problem that could only be resolved by bouncing the database.

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




Follow

Get every new post delivered to your Inbox.

Join 140 other followers

%d bloggers like this: