Striving for Optimal Performance
  • Home
  • Blog
    • Archive
    • Categories
  • Troubleshooting Oracle Performance
    • Description
    • Structure
    • Table of Contents
    • Forewords
    • Reviews
    • Downloadable Files
    • Addenda and Errata
  • Publications
  • Public Appearances
    • Past Public Appearances
  • Contact
  • Search
  • About

Introduce TVD$XTAT

Oct24
2008
11 Comments Written by Christian Antognini

Trivadis Extended Tracefile Analysis Tool (TVD$XTAT) is a command-line tool. Like TKPROF, its main purpose is to take a raw SQL trace file as input and generate a formatted file as output.

Why Is TKPROF Not Enough?

In late 1999, I had my first encounter with extended SQL trace, through MetaLink note Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output (39817.1). From the beginning, it was clear that the information it provided was essential for understanding what an application is doing when it is connected to an Oracle database engine. At the same time, I was very disappointed that no tool was available for analyzing extended SQL trace files for the purpose of leveraging their content. I should note that TKPROF at that time did not provide information about wait events. After spending too much time manually extracting information from the raw trace files, I decided to write my own analysis tool: TVD$XTAT.

Currently, TKPROF provides information about wait events, but it still has three major problems that are addressed in TVD$XTAT:

  • As soon as the argument sort is specified, the relationship between SQL statements is lost.
  • Data is provided only in aggregated form. Consequently, useful information is lost.
  • No information about bind variables is provided.

TVD$XTAT is freeware. You can download it (presently, version 4.0 beta 7) from this page. TOP fully describes how to use it to identify performance problems. The installation is documented in the README file.

It goes without saying that all feedbacks about TVD$XTAT are highly welcome.

Posted in SQL Trace, TKPROF, TOP, TVD$XTAT
SHARE THIS Twitter Facebook Delicious StumbleUpon E-mail
← Invisible Indexes and Locks
Invisible Indexes and Hints →

9 Comments

  1. Tom
    October 27, 2008 at 07:48 | Permalink

    I just tried it. The output looks great. If I ran it for about a minute total. Here is some sample output.

    db file sequential read  35,251.232  396.785  159  221.706
    resmgr:cpu quantum  8,832.303  99.416  76  116.215
    reliable message  8,827.260  99.359  2  4,413.630
    SQL*Net message from client  84.396  0.950  8  10.550
    

    Could those seconds be right? It’s a lot of recursive calls of course. Could it be adding the time from all those calls up?

    1  DROP TABLE  44,104.432  496.436  1  44,104.432
    2  CREATE TABLE  8,864.621  99.779  2  4,432.310
    14  SELECT  18.790  0.212  1  18.790
    15  COMMIT  10.358  0.117  1  10.358
    
    Reply
  2. Martin Berger
    October 27, 2008 at 22:50 | Permalink

    Do you have a changelog from the old version 4.0 beta 5 (from august 2005)?

    Reply
  3. Christian Antognini
    October 28, 2008 at 11:20 | Permalink

    Hi Martin

    Up to now I did not keep a change log for the beta releases of version 4. The reason is quite simple: I did a lot of changes! So, either the change log would be very generic like “fixed bugs”… Or the list would be very long and very cryptic to most people. Of course, this will change starting with the next release.

    Cheers,
    Chris

    Reply
  4. Vijay
    October 30, 2008 at 16:38 | Permalink

    Hi Christian,

    I increased the -Xmx1024m while running 500MB trace file on WindowsXP, and this did not produce any output after 8 hours. What is maximum trace file size which you have tried(on windows or Linux/Unix)?

    If this works, I have 8GB Trace file to try out next.

    Many Thanks and Regards
    Vijay

    Reply
  5. Christian Antognini
    October 31, 2008 at 18:38 | Permalink

    Hi Vijay

    Processing several GB of trace data should not be a problem. Be careful, however, that only part of the processing depends on the size of the trace file. In fact, it is not uncommon to see that the XLST processing at the end consumes a lot of time. Also the needed memory is not at all proportional with the size of the trace file. Usually, the needed memory is (much) smaller than the trace file.

    To see what’s going on, I suggest you to set the logging level to INFO. To do so you have to uncomment the following lines in the file logging.properties:

    .level = INFO
    java.util.logging.ConsoleHandler.level = INFO

    At the same time put a comment in front of the following lines:

    #.level = WARNING
    #java.util.logging.ConsoleHandler.level = WARNING

    By doing so you see additional information during the processing. For example, you see how much time it takes to read and process the input trace file. On current CPUs it should be 1-2 minutes for 1,000,000 lines. The XSLT processing starts when you see the message “generating output file”. I guess, that your problem is there… If it’s the case, try to start TVD$XTAT with the option “-w” set to “no” and let me know what do you see…

    Cheers,
    Chris

    Reply
  6. Christian Antognini
    October 31, 2008 at 19:13 | Permalink

    Hi Tom

    I had a look to your trace file. Indeed, something is broken in that trace file…
    Let me give you an example (I added the line number in front of each line):

    27266  EXEC #14:c=0,e=119,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=4413547664
    27267  XCTEND rlbk=0, rd_only=0
    27268  WAIT #8: nam='reliable message' ela= 1421 channel context=1423150156 channel handle=1423124620
                    broadcast message=1424081612 obj#=63418 tim=4413549531
    27269  WAIT #8: nam='resmgr:cpu quantum' ela= 8827097632 location=2  =0  =0 obj#=63418 tim=4413548816

    If we compute the elapsed time between each tim, we have the following figures:
    - ela of line 27268 is 1421:

    4413549531-4413547664=1867

    - ela of line 27269 is 8827097632

    4413548816-4413549531=-715

    Cheers,
    Chris

    Reply
  7. Vijay
    November 2, 2008 at 03:05 | Permalink

    Hi Christian,

    I executed the program by changing warning to info and -Xmx1024m. Still I get Java heap space
    error.

    tvdxtat -i pcet5_ora_8486.trc -o pcet5_ora_8486.html

    701328 INFO 9900000 lines processed
    740875 INFO 10000000 lines processed
    792468 INFO 10100000 lines processed
    866234 INFO 10200000 lines processed
    1004578 INFO 10300000 lines processed
    Exception in thread “main” java.lang.OutOfMemoryError: Java heap space
    at java.util.HashMap.addEntry(Unknown Source)
    at java.util.HashMap.put(Unknown Source)
    at java.util.ListResourceBundle.loadLookup(Unknown Source)
    at java.util.ListResourceBundle.handleGetObject(Unknown Source)
    at java.util.ResourceBundle.getObject(Unknown Source)
    at java.util.ResourceBundle.getObject(Unknown Source)
    at java.util.ResourceBundle.getObject(Unknown Source)
    at java.text.DateFormatSymbols.initializeData(Unknown Source)
    at java.text.DateFormatSymbols.(Unknown Source)
    at java.text.DateFormatSymbols.getInstance(Unknown Source)
    at java.text.SimpleDateFormat.(Unknown Source)
    at java.text.SimpleDateFormat.(Unknown Source)
    at com.trivadis.xtat.h.k(Unknown Source)
    at com.trivadis.xtat.h.C(Unknown Source)
    at com.trivadis.xtat.q.a(Unknown Source)
    at com.trivadis.xtat.Main.main(Unknown Source)

    tvdxtat -i pcet5_ora_8486.trc -o pcet5_ora_8486.html -w no

    1038578 INFO 9900000 lines processed
    1085672 INFO 10000000 lines processed
    1145594 INFO 10100000 lines processed
    1227000 INFO 10200000 lines processed
    1368516 INFO 10300000 lines processed
    Exception in thread “main” java.lang.OutOfMemoryError: Java heap space
    at java.util.HashMap.addEntry(Unknown Source)
    at java.util.HashMap.put(Unknown Source)
    at java.util.ListResourceBundle.loadLookup(Unknown Source)
    at java.util.ListResourceBundle.handleGetObject(Unknown Source)
    at java.util.ResourceBundle.getObject(Unknown Source)
    at java.text.DateFormatSymbols.initializeData(Unknown Source)
    at java.text.DateFormatSymbols.(Unknown Source)
    at java.text.DateFormatSymbols.getInstance(Unknown Source)
    at java.text.SimpleDateFormat.(Unknown Source)
    at java.text.SimpleDateFormat.(Unknown Source)
    at com.trivadis.xtat.h.k(Unknown Source)
    at com.trivadis.xtat.h.C(Unknown Source)
    at com.trivadis.xtat.q.a(Unknown Source)
    at com.trivadis.xtat.Main.main(Unknown Source)

    Regards
    Vijay

    Reply
  8. Christian Antognini
    November 3, 2008 at 09:32 | Permalink

    Hi Vijay

    I would really like to do some tests with that trace file. Are you able to share it? If yes, can you put it on http://www.transferbigfiles.com/ or something similar?

    Thank you,
    Chris

    Reply
  9. Vijay
    November 3, 2008 at 12:41 | Permalink

    Hi Chris,

    Sorry, I am not able to share the trace file.

    Regards
    Vijay

    Reply
  1. SQL Profiler TVD$XTAT available | ora-solutions.net - Martin Decker on October 24, 2008 at 21:21
  2. Log Buffer #121: a Carnival of the Vanities for DBAs on October 31, 2008 at 18:02

Leave a Reply Cancel reply

Your email address will not be published. Required fields are marked *

*

*


four + 3 =

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>

EvoLve theme by Theme4Press  •  Powered by WordPress Striving for Optimal Performance