| |
 |
|
Analyzing the Oracle 10046 Trace File
Oracle Tips by
Robert Freeman |
Note: Here are related Oracle
10046 trace file notes:
Loading and Analyzing the 10046 Event
Oracle provides us with a
tool, TKPROF, that will analyze a trace file generated via a
10046 event. In fact, it collects summary wait information for
each event for you to look at. Often, this might be sufficient,
but it would be nice to be able to load critical 10046 trace
information into the database to do some analysis both current
and even historical. I can even envision some trending that
could be done with such data.
To conclude this white paper,
I present my first attack at making this information available
within the database. I have created 3 external tables that load
specific event information from within the trace file. You may
well find ways to improve this code, or build on it. I?d love to
see what you do to it.
These external tables have
been tested on Oracle Database 10g on a Windows XP platform.
They should work on other 10g databases. I have not tested them
in Oracle9i, so I can't guarantee they will work there.
The Wait Event External Table
The first external table is
designed to load the wait events listed in the 10046 trace file.
Notice that in each of the external tables I use the
TRACE_ROW_NUM pseudo column to track the actual row number of
the event in the trace file. This will allow us to reconstruct
the records in the order that they appear in the trace file,
which is very important!
Also note that you will need
to use the create directory command to create the LOAD_DIRECTORY
directory that is referenced in these external tables. Here is
the SQL for that command:
create directory
load_directory
as 'c:\oracle\product\admin\BOOKTST\udump';
And here is the first external
table DDL code. Note that I load in all of the variables related
to the particular events to external table columns:
drop table
ext_10046_table_wait_events;
create table
ext_10046_table_wait_events
(event_type
varchar2(10),
cursor_number number,
wait_event_name
varchar2(60),
total_elapsed_time number,
p1
varchar2(100),
p2
varchar2(100),
p3
varchar2(100),
trace_row_num number
)
ORGANIZATION EXTERNAL
(TYPE oracle_loader
DEFAULT DIRECTORY
load_directory
access parameters
( RECORDS
DELIMITED BY NEWLINE
badfile
load_directory:'bad_10046.log'
logfile
load_directory:'load_10046.log'
skip 24
LOAD WHEN
event_type="WAIT"
FIELDS RTRIM
(
event_type CHAR terminated by '#',
cursor_number CHAR terminated by ': nam=',
wait_event_name CHAR terminated by 'ela=',
total_elapsed_time CHAR terminated by 'p1=',
p1 CHAR
terminated by 'p2=',
p2 CHAR
terminated by 'p3=',
p3 CHAR
terminated by WHITESPACE,
trace_row_num recnum
)
)
location
('booktst_ora_3640.trc')
)
reject limit unlimited;
The Parse, Execute and Fetch
Events External Table
Because the parse, execute and
fetch record formats are pretty much the same, I loaded them up
into a single external table. Here is the code for that table.
drop table
ext_10046_table_pef_events;
create table
ext_10046_table_pef_events
(event_type
varchar2(10),
cursor_number number,
pef_cpu_time number,
pef_elap number,
pef_blocks number,
pef_blocks_cm number,
pef_blocks_curmode number,
pef_lib_cache_misses number,
pef_rows_returned number,
pef_depth number,
pef_goal number,
pef_tim number,
trace_row_num number
)
ORGANIZATION EXTERNAL
(TYPE oracle_loader
DEFAULT DIRECTORY
load_directory
access parameters
( RECORDS
DELIMITED BY NEWLINE
badfile
load_directory:'bad_10046.log'
logfile
load_directory:'load_10046.log'
skip 24
LOAD WHEN (
event_type="EXEC"
or
event_type="FETCH"
or
event_type="PARSE" )
FIELDS RTRIM
(
event_type CHAR terminated by '#',
cursor_number CHAR terminated by ':c=',
pef_cpu_time
CHAR terminated by ',e=',
pef_elap
CHAR terminated by ',p=',
pef_blocks CHAR terminated by ',cr=',
pef_blocks_cm CHAR terminated by ',cu=',
pef_blocks_curmode CHAR terminated by ',mis=',
pef_lib_cache_misses CHAR terminated by ',r=',
pef_rows_returned CHAR terminated by ',dep=',
pef_depth CHAR terminated by ',og=',
pef_goal
CHAR terminated by ',tim=',
pef_tim
CHAR terminated by WHITESPACE,
trace_row_num recnum
)
)
location
('booktst_ora_3640.trc')
)
reject limit unlimited;
The Cursor Record External
Table
Ok, now a story. I found out
that I got accepted for this presentation about 30 days before
it was to be given. I had about a week to put this all in place,
get the presentation together and make all the code work.
Unfortunately, I had to cut a corner or two, and it was on this
table that most of the corners got cut.
I wanted the table to load the
cursor related statistics, and the SQL statement itself. I just
ran out of time, and could not get the SQL code to load in with
the rest of the data. I?m going to try to work on this when I
have time, but if you manage to get it working, please let me
know and send me updated code if you like!
drop table
ext_10046_table_cursor_events;
create table
ext_10046_table_cursor_events
(event_type
varchar2(40),
cursor_number number,
cur_length number,
cur_dependency number,
cur_uid number,
cur_oct number,
cur_lid number,
cur_tim number,
cur_hv number,
cur_ad
varchar2(30),
trace_row_num number
)
ORGANIZATION EXTERNAL
(TYPE oracle_loader
DEFAULT DIRECTORY
load_directory
access parameters
( RECORDS
DELIMITED BY NEWLINE
badfile
load_directory:'bad_10046.log'
logfile
load_directory:'load_10046.log'
skip 24
LOAD WHEN (
event_type='PARSING IN CURSOR ' )
FIELDS RTRIM
MISSING FIELD VALUES ARE NULL
(
event_type CHAR terminated by '#',
cursor_number CHAR terminated by 'len=',
cur_length CHAR terminated by 'dep=',
cur_dependency CHAR terminated by 'uid=',
cur_uid
CHAR terminated by 'oct=',
cur_oct
CHAR terminated by 'lid=',
cur_lid
CHAR terminated by 'tim=',
cur_tim
CHAR terminated by 'hv=',
cur_hv
CHAR terminated by "ad='",
cur_ad
CHAR terminated by "'",
trace_row_num recnum
)
)
location
('booktst_ora_2504.trc')
)
reject limit unlimited;
Making it all work
Here are examples of the
execution of this code:
select trace_row_num,
event_type, cursor_number, wait_event_name
from
ext_10046_table_wait_events
where rownum < 5;
TRACE_ROW_NUM EVENT_TYPE
CURSOR_NUMBER WAIT_EVENT_NAME
------------- ----------
------------- --------------------------------
30
WAIT 1 'SQL*Net message to client'
31
WAIT 1 'SQL*Net message from client'
41
WAIT 2 'SQL*Net message to client'
43
WAIT 2 'SQL*Net message from client'
select trace_row_num,
event_type, cursor_number
from
ext_10046_table_pef_events
where rownum < 5;
TRACE_ROW_NUM EVENT_TYPE
CURSOR_NUMBER
------------- ----------
-------------
29
EXEC 1
38
PARSE 2
40
EXEC 2
42
FETCH 2
select distinct
b.trace_row_num, sql_text
from v$sql a,
ext_10046_table_cursor_events b
where upper(b.cur_ad)=a.address
(+)
order by b.trace_row_num;
TRACE_ROW_NUM
-------------
SQL_TEXT
-----------------------------------------------------------------------69
SELECT a.emp_first_name, b.job_name
FROM emp a, job b
WHERE a.job_key=b.job_key
END OF STMT
This join puts all the records
together?Again, it isn't perfect, but what do you expect for
free!!
J
(Ok, so you probably paid to attend the conference, but you did
get a 15 page paper from me!)
Column wait_time heading ?Wait
Time|or|SQL Text?
Column wait_time format a30
select trace_row_num,
event_type, cursor_number, wait_event_name,
to_char(total_elapsed_time) wait_time
from
ext_10046_table_wait_events
union
select trace_row_num,
event_type, cursor_number , null, null
from
ext_10046_table_pef_events
union
select distinct
b.trace_row_num, null, null, null, sql_text
from v$sql a,
ext_10046_table_cursor_events b
where upper(b.cur_ad)=a.address
(+)
order by 1;
Wait Time
or
TRACE_ROW_NUM EVENT_TYPE
CURSOR_NUMBER WAIT_EVENT_NAME SQL Text
------------- ----------
------------- ------------------------------ -------------------
29
EXEC 1 alter
session set
events '10046
trace name context
forever, level 12'
30
WAIT 1 'SQL*Net message to client' 9
31
WAIT 1 'SQL*Net message from client' 5913918
38
PARSE 2
40 EXEC
2 SELECT
a.emp_first_name,
b.job_name
FROM emp a, job b
WHERE
a.job_key=b.job_key
41
WAIT 2 'SQL*Net message to client' 10
42
FETCH 2
43
WAIT 2 'SQL*Net message from client' 2120
44
WAIT 2 'SQL*Net message to client' 6
45
FETCH 2
46
WAIT 2 'SQL*Net message from client' 1353028
Let's summarize our waits?
select cursor_number,
wait_event_name,
sum(total_elapsed_time)/1000000
wait_time
from
ext_10046_table_wait_events
group by cursor_number,
wait_event_name;
CURSOR_NUMBER WAIT_EVENT_NAME WAIT_TIME
------------- ------------------------------ ----------
0 'log file sync' .108999
0 'SQL*Net message to client' .000417
0 'SQL*Net message from client' 1259.44319
3 'latch free' .000856
3 'db file sequential read' 18.398237
3 'SQL*Net message to client' 1.006712
3 'log file switch completion' .03704
3 'SQL*Net message from client' 139.085542
3 'SQL*Net more data from client 3.613657
Click here
to read next section
Click here
to read previous section
 |
If you like Oracle tuning, see the book "Oracle
Tuning: The Definitive Reference", with 950 pages of tuning tips and
scripts.
You can buy it direct from the publisher for 30%-off and get
instant access to the code depot of Oracle tuning scripts. |
|
|
|
and include the URL for the page.
