Call now: 252-767-6166  
Oracle Training Oracle Support Development Oracle Apps

 
 Home
 E-mail Us
 Oracle Articles
New Oracle Articles


 Oracle Training
 Oracle Tips

 Oracle Forum
 Class Catalog


 Remote DBA
 Oracle Tuning
 Emergency 911
 RAC Support
 Apps Support
 Analysis
 Design
 Implementation
 Oracle Support


 SQL Tuning
 Security

 Oracle UNIX
 Oracle Linux
 Monitoring
 Remote s
upport
 Remote plans
 Remote
services
 Application Server

 Applications
 Oracle Forms
 Oracle Portal
 App Upgrades
 SQL Server
 Oracle Concepts
 Software Support

 Remote S
upport  
 Development  

 Implementation


 Consulting Staff
 Consulting Prices
 Help Wanted!

 


 Oracle Posters
 Oracle Books

 Oracle Scripts
 Ion
 Excel-DB  

Don Burleson Blog 


 

 

 


 

 

 

 
 

Displaying Oracle Trace Event files

Oracle Tips by Robert Freeman


Note: Here are related Oracle 10046 trace file notes:
Accessing Oracle Trace Records with external tables
 
After turning in this paper to meet the deadline, I did some more playing with this feature. Here is what I did:
 
I created a view to make accessing the trace records easier:
 
Create or replace view vw_10046_view as
select trace_row_num, event_type, cursor_number, wait_event_name, to_char(total_elapsed_time) wait_time,
-1 command
from ext_10046_table_wait_events
union
select trace_row_num, event_type, cursor_number
,null, to_char(pef_tim), -1
from ext_10046_table_pef_events
union
select distinct b.trace_row_num, null, null, null, sql_text, to_number(cur_oct) command
from v$sql a, ext_10046_table_cursor_events b
where upper(b.cur_ad)=a.address (+)
order by 1;
 
This made things easier, but there was still a problem, performance. External table access to large 10046 trace files is just very slow. To deal with that, I simply created a table and dumped the 10046 trace data into it.
 
Create table tab_10046 as
Select * from vw_10046_view;
 
Create index ix_tab_10046_01 on tab_10046(trace_row_num);
Create index ix_tab_10046_02 on tab_10046(command);
Create index ix_tab_10046_03 on tab_10046(event_type);
Create index ix_tab_10046_04 on tab_10046
(event_type, trace_row_num, cursor_number, wait_time);
 
 
 The indexes help tremendously with overall access times for queries. Next, I wanted to write some more queries that would help with real world 10046 trace problem solving. The first query uses the analytical functions of Oracle to provide some insight into the run times of various operations:
 
Column time_between_events heading 'time|Between|Events?
Column wait_time format 9999999999
 
select event_type, cursor_number, to_number(wait_time) wait_time,
(wait_time/1000000)-lag(wait_time/1000000, 1)
over (order by trace_row_num) "time_between_events"
from tab_10046
where event_type in ('EXEC','FETCH','PARSE')
order by trace_row_num;
 
This gives me a listing of each individual EXEC, FETCH and PARSE operation, and provides me with the time it took between the two operations. For example in the big 10046 trace file I run, it produced over 5 million records? Here is an example of this report:
 
  Time
  Cursor  Between
EVENT_TYPE  Number  WAIT_TIME  Events
---------- ---------- ----------- ----------
PARSE  3  3889179528
EXEC  3  3889180002  .000474
PARSE  3  3889182412  .00241
EXEC   3  3889182891  .000479
PARSE  3  3889185178  .002287
EXEC  3  3889185634  .000456
PARSE  3  3889188020  .002386
EXEC  3  3889188437  .000417
PARSE  3  3923555525  34.367088
EXEC  3  3923556292  .000767
PARSE  3  3923559154  .002862
EXEC  3  3923559754  .0006
PARSE  3  3923562154  .0024
EXEC  3  3923562690  .000536
PARSE  3  3923565068  .002378
EXEC  3  3923565564  .000496
 
 
So, five million plus records seems a bit extreme?. How do we reduce this number. TO deal with this I modified the query to add some run time criteria:
 
select trace_row_num, event_type, cursor_number,
to_number(wait_time) wait_time, event_time FROM  (select trace_row_num, event_type, cursor_number, wait_time,
  (wait_time/1000000)-lag(wait_time/1000000, 1)
  over (order by trace_row_num) "EVENT_TIME" from tab_10046
  where event_type in ('EXEC','FETCH','PARSE') order by trace_row_num  )
where trace_row_num in ( select trace_row_num
  from (select trace_row_num,
  (wait_time/1000000)-
  lag(wait_time/1000000, 1)
  over (order by trace_row_num)
  "EVENT_TIME"
  from tab_10046
  where event_type in ('EXEC','FETCH','PARSE') ) where event_time > .25 )
 
So, here I am limiting my result to those events that experienced a lag time of greater than .25 seconds. This significantly reduced my row set, and gave me something manageable to work with. Here is a partial result of this query:
 
TRACE_ROW_NUM EVENT_TYPE  Number  WAIT_TIME EVENT_TIME
------------- ---------- ---------- ----------- ----------
  2298019 PARSE  3  2881178580  32.95
  2425666 PARSE  3  2939522206  34.07
  2553299 PARSE   3  2994920152  31.08
  2680751 PARSE  3  3054787045  33.54
  2808832 PARSE  3  3110536030  32.24
  2936778 PARSE  3  3167765847  31.58
  3064266 PARSE  3  3227249876   33.48
  3191935 PARSE  3  3284241535  32.12
  3319636 PARSE  3  3341259394  31.84
  3447092 PARSE  3  3400515679  33.46
  3574826 PARSE  3  3457276827  33.02
  3702529 PARSE  3  3515651502  33.09
  3829993 PARSE  3  3575157371  34.83
  3957662 PARSE  3  3630381367  31.68
  4085349 PARSE  3  3689283680  33.62
  4106254 EXEC   3  3695989891  .45
  4213359 PARSE  3  3750297980  35.12
  4341185 PARSE  3  3805701373  31.61
  4468887 PARSE  3  3865174711  33.78
  4596361 PARSE  3  3923555525   34.37
 
 
This has really made it easier to look for specific problems. It would be even easier if I could see the operation prior to this operation, the one that the lag time is actually predicated on. This way I can determine a range of records that are of interest. I modified the query thusly to provide this information:
 
select ?E? operation, trace_row_num, event_type, cursor_number, wait_time, event_time FROM
  (select trace_row_num, event_type, cursor_number,
  to_number(wait_time) wait_time,
  (wait_time/1000000)-lag(wait_time/1000000, 1)
  over (order by trace_row_num) "EVENT_TIME" from tab_10046
  where event_type in ('EXEC','FETCH','PARSE')
  order by trace_row_num  )
where trace_row_num in
  ( select trace_row_num
  from (select trace_row_num,
  (wait_time/1000000)-
  lag(wait_time/1000000, 1)
  over (order by trace_row_num) "EVENT_TIME"
  from tab_10046
  where event_type in ('EXEC','FETCH','PARSE') )   
  where event_time > .25 )
UNION
select ?B? Operation, trace_row_num, event_type, cursor_number,
to_number(wait_time) wait_time, event_time
FROM 
  (select trace_row_num, event_type, cursor_number, wait_time,
  (wait_time/1000000)-lag(wait_time/1000000, 1)
  over (order by trace_row_num) "EVENT_TIME?  from tab_10046
  where event_type in ('EXEC','FETCH','PARSE') 
  order by trace_row_num  )
where rowid in  (select q_rowid
  from (select trace_row_num,
   (wait_time/1000000)-
  lag(wait_time/1000000, 1)
  over (order by trace_row_num) "EVENT_TIME?,
  lag(rowid) over
  (order by trace_row_num) q_rowid
  from tab_10046
  where event_type in ('EXEC','FETCH','PARSE') )
  where event_time > .25  )
order by trace_row_num;
 
Which gives us this dandy report:
 
  Cursor
O TRACE_ROW_NUM EVENT_TYPE  Number  WAIT_TIME EVENT_TIME
- ------------- ---------- ---------- ----------- ----------
B  4661621      PARSE      3          3936743204  .01
E  4661624      EXEC       3          3937120555  .38
 
B  4724009      EXEC       3          3948848444  .00
E  4724035      PARSE      3          3981191796  32.34
 
B  4851699      EXEC       3          4006419477  .00
E  4851727      PARSE      3          4040119254  33.70
 
B  4979646      EXEC       3          4063701927  .00
E  4979674      PARSE      3          4096337840  32.64
 
B  5033307      PARSE      3          4107294796  .01
E  5033311      EXEC       3          4107692394  .40
 
Note that this report gives me the beginning operation (denoted with the B), and the ending operation number (denoted with the E). The ending operation is the one reporting the lag, the beginning operation is the one where the lag timing started. So, the bottom line is that somewhere between these operations, trouble has occurred.
 
I can run another report to see all of the waits that occurred in between those events, this leads me to possible culprits:
 
select trace_row_num, event_type, wait_event_name,
cursor_number, wait_time/1000000 wait_time
from tab_10046
where trace_row_num between 4851699 and 4851727
order by trace_row_num;
 
 
  Cursor
TRACE_ROW_NUM EVENT_TYPE WAIT_EVENT_NAME  Number  WAIT_TIME
------------- ---------- ---------------  ------  ---------
  4851699 EXEC  3  4006
  4851700 WAIT  'SQL*Net message to client'  3  0
  4851701 WAIT  'SQL*Net message from client'  3  0
  4851703 WAIT  'log file sync'  0  0
  4851704 WAIT  'SQL*Net message to client'  0  0
  4851705 WAIT  'SQL*Net message from client'  0  0
  4851708 WAIT  'SQL*Net message to client'  3  0
  4851709 WAIT  'SQL*Net message from client'  3  0
  4851710 WAIT  'SQL*Net message to client'  0  0
  4851712 WAIT  'SQL*Net message from client'  0  34
 
  Cursor
TRACE_ROW_NUM EVENT_TYPE WAIT_EVENT_NAME Number  WAIT_TIME
------------- ---------- ---------------  ------  ---------
  4851713 WAIT  'SQL*Net message to client'  0  0
  4851714 WAIT  'SQL*Net message from client'  0  0
  4851715 WAIT  'SQL*Net message to client'  3  0
  4851716 WAIT  'SQL*Net message from client'  3  0
  4851718
  4851727 PARSE  3  4040
 
In this case, we find that we had a wait event, SQL*Net message from client, that lasted for 34 seconds. This may be a normal situation (waiting for user feedback perhaps) or it might demonstrate some sort of problem with the application or network.
 
Also note that there are 3rd party tools to format 10046 trace events to make them more readable.
 
About the Author
 
Robert G. Freeman is an independent database technologist who works closely with Burleson Consulting on database training, development, design and administration throughout the world. Robert speaks frequently at a number of different user groups including IOUG-A and the UKOUG.
 
Click here to read next section
Click here to read previous section
 


Randolf Geist, has this Unix command that can be used to transform the raw trace into a suitable input for an Oracle external table:

cat $TRACE_FILE | awk '
/^HEAP DUMP heap name=/ { split($0,ht,"\""); HTYPE=ht[2]; doPrintOut = 1; }
/Chunk/{ if ( doPrintOut == 1 ) {
split($0,sf,"\"");
printf "%10d , %16s, %16s, %16s\n", $4, HTYPE, $5, sf[2];
}
}
/Total heap size/ {
doPrintOut=0;
}
' > $EXT_TAB_DIR/heapdump.txt


This is how this external table definition is defined for the trace file:

create table heapdump
(
   chunk_size integer
   , heap_type varchar2(16)
   , chunk_type varchar2(16)
   , alloc_reason varchar2(16)
)
organization external
(
type oracle_loader
default directory ext_tab_dir
access parameters
(
records delimited by newline
fields terminated by ','
lrtrim
)
location ('heapdump.txt')
);


 
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.


 

 

��  
 
 
Oracle Training at Sea
 
 
 
 
oracle dba poster
 

 
Follow us on Twitter 
 
Oracle performance tuning software 
 
Oracle Linux poster
 
 
 

 

Burleson is the American Team

Note: This Oracle documentation was created as a support and Oracle training reference for use by our DBA performance tuning consulting professionals.  Feel free to ask questions on our Oracle forum.

Verify experience! Anyone considering using the services of an Oracle support expert should independently investigate their credentials and experience, and not rely on advertisements and self-proclaimed expertise. All legitimate Oracle experts publish their Oracle qualifications.

Errata?  Oracle technology is changing and we strive to update our BC Oracle support information.  If you find an error or have a suggestion for improving our content, we would appreciate your feedback.  Just  e-mail:  

and include the URL for the page.


                    









Burleson Consulting

The Oracle of Database Support

Oracle Performance Tuning

Remote DBA Services


 

Copyright © 1996 -  2017

All rights reserved by Burleson

Oracle ® is the registered trademark of Oracle Corporation.

Remote Emergency Support provided by Conversational