Oct 24 2008

Introduce TVD$XTAT

Tag: SQL Trace, TKPROF, TOP, TVD$XTAT — Christian Antognini @ 3:56 pm

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.

11 Responses to “Introduce TVD$XTAT”

  1. Pingback: SQL Profiler TVD$XTAT available | ora-solutions.net - Martin Decker
    October 24th, 2008 at 9:21 pm

    [...] saw that Christian Antognini has finally released TVD$XTAT which can now be downloaded from his webpage. I am looking forward to experimenting with [...]

  2. Comment: Tom
    October 27th, 2008 at 7:48 am

    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

  3. Comment: Martin Berger
    October 27th, 2008 at 10:50 pm

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

  4. Comment: Christian Antognini
    October 28th, 2008 at 11:20 am

    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

  5. Comment: Vijay
    October 30th, 2008 at 4:38 pm

    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

  6. Pingback: Log Buffer #121: a Carnival of the Vanities for DBAs
    October 31st, 2008 at 6:02 pm

    [...] week brings us the introduction of a new beta version (4.0 beta 7) of TVD$XTAT, Christian Antognini’s freeware  tool for working with raw SQL [...]

  7. Comment: Christian Antognini
    October 31st, 2008 at 6:38 pm

    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

  8. Comment: Christian Antognini
    October 31st, 2008 at 7:13 pm

    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

  9. Comment: Vijay
    November 2nd, 2008 at 3:05 am

    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

  10. Comment: Christian Antognini
    November 3rd, 2008 at 9:32 am

    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

  11. Comment: Vijay
    November 3rd, 2008 at 12:41 pm

    Hi Chris,

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

    Regards
    Vijay

Leave a Reply

All comments are filtered by Akismet and then moderated by me. So, it should be no surprise that spam and anything wholly inappropriate has no chance of making it onto the site. To send questions or comments not related to this blog post please use the contact form.

Your name (required)

Your email (will not be published) (required)

Your website

Your message (please wrap code examples in <pre> tags)