Introduce TVD$XTAT

24 October 2008 13 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.

SQL Trace, TKPROF, TOP, TVD$XTAT

13 Comments

2 Pings/Trackbacks

  1. SQL Profiler TVD$XTAT available | ora-solutions.net - Martin Decker SQL Profiler TVD$XTAT available | ora-solutions.net - Martin Decker
    24 October 2008    

    […] 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. Tom Tom
    27 October 2008    

    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
  3. Martin Berger Martin Berger
    27 October 2008    

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

    Reply
  4. Christian Antognini Christian Antognini
    28 October 2008    

    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
  5. Vijay Vijay
    30 October 2008    

    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
  6. Christian Antognini Christian Antognini
    31 October 2008    

    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
  7. Christian Antognini Christian Antognini
    31 October 2008    

    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
  8. Log Buffer #121: a Carnival of the Vanities for DBAs Log Buffer #121: a Carnival of the Vanities for DBAs
    31 October 2008    

    […] 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 […]

  9. Vijay Vijay
    2 November 2008    

    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
  10. Christian Antognini Christian Antognini
    3 November 2008    

    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
  11. Vijay Vijay
    3 November 2008    

    Hi Chris,

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

    Regards
    Vijay

    Reply
  12. Girish Girish
    6 July 2015    

    When I am trying to use TVD$XTAT I am getting below message what does it mean
    00:08:16 WARNING line 40113644 not processed
    00:08:16 WARNING line 40113645 not processed
    00:08:16 WARNING line 40113646 not processed
    00:08:16 WARNING line 40113647 not processed
    00:08:16 WARNING line 40113648 not processed
    00:08:16 WARNING line 40113649 not processed
    00:08:16 WARNING line 40113650 not processed
    00:08:16 WARNING line 40113651 not processed
    00:08:16 WARNING line 40113652 not processed
    00:08:16 WARNING line 40113653 not processed
    00:08:16 WARNING line 40113654 not processed
    00:08:16 WARNING line 40113655 not processed

    Reply
    • Christian Antognini Christian Antognini
      6 July 2015    

      Hi Girish

      that the 12 lines mentioned in the warnings are not recognized by TVD$XTAT. What do those lines contain?

      Best,
      Chris

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

Leave a Reply

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

This site uses Akismet to reduce spam. Learn how your comment data is processed.