10046 Extended SQL Tracing for a Session – What is Wrong with this Quote?

16092011

September 16, 2011

While reading the Oracle 11g Performance Tuning Recipes book, I noticed that some of the recipes in chapter 10 seemed to have an odd familiarity, although as of yet I have not quite pinpointed where I had previously seen some of the concepts in chapter 10. Recipes 10-2, 10-11, and 10-16 seem to share a common ancestry with a blog article, but maybe I am imagining things. A quote from recipe 10-16, found on page 351 (page 351 is currently unavailable for me in Google Books, but page 352 is available – you might need to scroll down one page if you click this link) of the book is certainly interesting, using a named event that was introduced with Oracle Database 11.1, rather than the event number 10046:

Execute the alter session (or alter system) set events command to trace a session by its operating system process ID which is shown by the SPID column in the V$PROCESS view [the book demonstrates replacing the word pid in the following command with the SPID value from V$PROCESS] . The general format of this command is as follows:

alter session set events 'sql_trace {process:pid}'

For additional clarification, the book provides the following extended example:

Interesting… a slight distraction (requires a sign-on for My Oracle Support) Metalink (MOS) Doc ID 813737.1, “How To Use The New 11g Events++ Syntax For Easier SQL Tracing Of Datapump Operations” – I wonder if I had read that article in the past?

What, if anything, is wrong with the above quote from the book?

The point of blog articles like this one is not to insult authors who have spent thousands of hours carefully constructing an accurate and helpful book, but instead to suggest that readers investigate when something stated does not exactly match what one believes to be true. It could be that the author “took a long walk down a short pier”, or that the author is revealing accurate information which simply cannot be found through other resources (and may in the process be directly contradicting information sources you have used in the past). If you do not investigate in such cases, you may lose an important opportunity to learn something that could prove to be extremely valuable.

Actions

Information

8 responses

I’ve not really done any testing or investigation into the new extended syntax apart from noting that it seems much more powerful etc.

If you set out specifically as an 11g performance tuning recipes book then I don’t have a problem with using a syntax that only works in 11g onwards.

I would have expected “alter session” to only affect your own session so I would expect it to be pointless to set sql trace for a process pid which wasn’t your own. Similarly, even if you do know your own pid, you shouldn’t need it for alter session.

I could understand using “alter session” to set sql trace on for your session only for a specific sql_id.

The syntax does seem a bit confusing in that “pid=” should reference v$process.spid whereas “orapid=” should reference v$process.pid.

Very good comments. Your third bullet point is what forced me to stop and ponder while reading the book. So, can ALTER SESSION be used to alter the session of a specific session other than your own by using the new Oracle tracing syntax? I was curious, so I just had to test to verify my assumptions.

Your fifth point is also very good – why use your own database terms when Oracle Database itself uses different ones? Confusion should not be a desired end result in my opinion.

(I was hoping that someone else would have jumped in with a test case by now 🙂 )

My testing showed that ALTER SESSION will only enable a 10046 trace for the current session. ALTER SESSION had no effect on the tracing that was enabled in another session. If one were to replace “alter session set events ‘sql_trace {process : n…” with “alter SYSTEM set events ‘sql_trace {process : n…” then tracing may be enabled in another session if the process ID is specified correctly.

Out of curiosity, has anyone enabled a 10046 trace at the SYSTEM level (likely with an ALTER SYSTEM call) and then not been able to stop tracing for some of the sessions (possibly the background sessions) without bouncing the database? I thought that I recalled seeing this problem on Oracle Database 10.2.0.2, but a quick test on 11.2.0.2 did not reproduce the problem.

Not related to this book, but related to the named wait events. Is there really an event named Millsap, or was this just a bit of humor? If there is an event named Millsap, I fully support the naming of that event name, and will quickly work to adopt the 11.1 and above syntax (side note: Cary Millsap’s book introduced me to understanding raw 10046 extended SQL traces, so it would be a worthy tribute to his contribution to Oracle performance tuning for this event to be named Millsap). Take a look at slide 17:http://oraclue.files.wordpress.com/2011/03/oracle-diagnostic-events1.pptx

Charles,
Maybe it’s worth to throw in Tanel Poder (or at least one of his posts):http://tech.e2sn.com/oracle/troubleshooting/oradebug-doc#TOC-ORADEBUG-DOC-EVENT-SCOPE
Based on this (which makes sense to me, even without test right now) I’d say ALTER SESSION SET EVENTS ‘sql_trace {process: orapid …’ is a _valid_ syntax. (similar to WHERE 1=2 is also _valid). So it’s not ‘wrong’, but it would be _nice_ to mention it in the book.
For the syntax inconsistency I’d say it should be OSPID instead of PID. – still untested, just reading docs 🙂
My biggest concern with the parts you quoted is the missing reference to ORADEBUG DOC.
Martin

Sorry for the delayed response – I was trying to understand how Tanel’s article applied to my blog article. Now that I have started SQL*Plus, I think that I understand your points. Tanel’s document shows how to get information about various ORADEBUG commands from within SQL*Plus. One of the commands that Tanel shows is this one:

ORADEBUG DOC EVENT FILTER process

When I execute that command in SQL*Plus (when connected as SYS), I receive the following output:

Usage
-------
{process: ospid ,
orapid ,
pname }

In the above it should be clear that PID should have been listed as OSPID in the book (you mentioned this also) and I think that Dom also picked up on the inconsistency. It was this oddity combined with the phrase “rest of event specification” and the overall similarity including the spacing in the command that lead me to believe that the oraclue.com article linked above might to related to this section of the book.

Regarding the syntax being valid just like “WHERE 1=2″… now that I think about it, you might have a point. Neither throws and error, and both prevent something from happening. But then editing a spfile with a text editor might also meet that criteria. 🙂

Hints for Posting Code Sections in Comments

********************
When the spacing of text in a comment section is important for readability (execution plans, PL/SQL blocks, SQL, SQL*Plus output, etc.) please use a <pre> tag before the code section and a </pre> tag after the code section:
<pre>

SQL> SELECT
2 SYSDATE TODAY
3 FROM
4 DUAL;
TODAY
---------
01-MAR-12

</pre>
********************
When posting test case samples, it is much easier for people to reproduce the test case when the SQL*Plus line prefixes are not included - if possible, please remove those line prefixes. This:

SELECT
SYSDATE TODAY
FROM
DUAL;

Is easier to execute in a test case script than this:

SQL> SELECT
2 SYSDATE TODAY
3 FROM
4 DUAL;

********************
Greater than and Less than signs in code sections are often interpretted as HTML formatting commands. Please replace these characters in the code sections with the HTML equivalents for these characters: