Xtrace: an Oracle session trace browser (introduction)

Xtrace is a graphical tool that can navigate Oracle trace files, manipulate them, and optionally get them back as a text file. It actually makes (much) more, but in this first post we are going to focus on its basic browsing capabilities.

Let’s see the tool in action on the trace file produced by this simple PL/SQL block:

begin
  for r in (select * from t) loop
    null;
  end loop;
end;

The resulting trace file is

WAIT #2: nam='SQL*Net message from client' ela= 61126 driver id=1413697536 #bytes=1 p3=0 obj#=76357 tim=5789636384898
=====================
PARSING IN CURSOR #26 len=66 dep=0 uid=73 oct=47 lid=73 tim=5789636385129 hv=3421439103 ad='aeb809c8'
begin
  for r in (select * from t) loop
    null;
  end loop;
end;
END OF STMT
PARSE #26:c=0,e=153,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=5789636385122
BINDS #26:
=====================
PARSING IN CURSOR #28 len=15 dep=1 uid=73 oct=3 lid=73 tim=5789636386184 hv=1406298530 ad='a0503300'
SELECT * FROM T
END OF STMT
PARSE #28:c=0,e=804,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=5789636386181
BINDS #28:
EXEC #28:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=5789636386284
WAIT #28: nam='db file sequential read' ela= 19 file#=4 block#=59 blocks=1 obj#=76357 tim=5789636386383
WAIT #28: nam='db file sequential read' ela= 11 file#=4 block#=60 blocks=1 obj#=76357 tim=5789636386457
FETCH #28:c=0,e=243,p=2,cr=3,cu=0,mis=0,r=100,dep=1,og=1,tim=5789636386566
FETCH #28:c=0,e=54,p=0,cr=1,cu=0,mis=0,r=100,dep=1,og=1,tim=5789636386663
FETCH #28:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=5789636386693
EXEC #26:c=0,e=1543,p=2,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=5789636386746
WAIT #26: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=76357 tim=5789636387057
WAIT #26: nam='SQL*Net message from client' ela= 42743 driver id=1413697536 #bytes=1 p3=0 obj#=76357 tim=5789636429824
STAT #28 id=1 cnt=200 pid=0 pos=1 obj=76357 op='TABLE ACCESS FULL T (cr=4 pr=2 pw=0 time=363 us)'

Even for this artificially simple trace file, it takes a lot of effort to read and understand it; for example, it takes a while to associate the recursive SQL lines to the execution of the PL/SQL blocks (the “EXEC #26” line).

With Xtrace, the trace reading experience is remarkably much better:



Note the indentation by recursive level (which is provided out-of-the -box) and the color of the lines by statement (that takes perhaps a minute in order to be set up).
You can try this example live by pressing the “Launch” button above if you are interested; in particular, try the “Options” button of the middle pane, and the “set color” popup menus of the top pane.

Suggestion: you might even check the hyperlinks that links together the lines; for example, the xct pointer that links the SQL recursive calls to the parent “EXEC #26” (check the interactive manual for more information).

You can also get the trace back as a text file, if so desired:

000 line zero
001 xtrace: log file 'E:\localCVS30\TrilogyLectures\MioSitoWeb\xtrace\dist\xtrace.log'
002 VIRTUAL CALL #-4: 'null call - ignore this'
003 VIRTUAL CALL #-4: 'null call - ignore this'
004 +WAIT #2: nam='SQL*Net message from client' xe=ela=61126 p1='driver id'=1413697536 p2='#bytes'=1 p3=''=0 xphy=0 obj#=76357 tim=5789636384898
005 VIRTUAL CALL #-8: 'wait-for-client'
006 VIRTUAL CALL #-5: 'client-message-received'
007 ---------------------PARSING IN CURSOR #26: len=66 dep=0 uid=73 oct=47 lid=73 tim=5789636385129 hv=3421439103 ad='0eb809c8'
    begin
      for r in (select * from t) loop
        null;
      end loop;
    end;
    END OF STMT
008 PARSE #26: mis=0 r=0 dep=0 og=1 tim=5789636385122 e=153 c=0 p=0 cr=0 cu=0
009 BINDS #26:
010   ---------------------PARSING IN CURSOR #28: len=15 dep=1 uid=73 oct=3 lid=73 tim=5789636386184 hv=1406298530 ad='00503300'
      SELECT * FROM T
      END OF STMT
011   PARSE #28: mis=1 r=0 dep=1 og=1 tim=5789636386181 e=804 c=0 p=0 cr=0 cu=0
012   BINDS #28:
013   EXEC  #28: mis=0 r=0 dep=1 og=1 tim=5789636386284 e=64 c=0 p=0 cr=0 cu=0
014   +WAIT #28: nam='db file sequential read' xe=ela=19 p1='file#'=4 p2='block#'=59 p3='blocks'=1 xphy=1 obj#=76357 tim=5789636386383
015   +WAIT #28: nam='db file sequential read' xe=ela=11 p1='file#'=4 p2='block#'=60 p3='blocks'=1 xphy=1 obj#=76357 tim=5789636386457
016   FETCH #28: mis=0 r=100 dep=1 og=1 tim=5789636386566 e=243 c=0 p=2 cr=3 cu=0
017   FETCH #28: mis=0 r=100 dep=1 og=1 tim=5789636386663 e=54 c=0 p=0 cr=1 cu=0
018   FETCH #28: mis=0 r=0 dep=1 og=1 tim=5789636386693 e=3 c=0 p=0 cr=0 cu=0
019 EXEC  #26: mis=0 r=1 dep=0 og=1 tim=5789636386746 e=1543 c=0 p=2 cr=4 cu=0
020 -WAIT #26: nam='SQL*Net message to client' xe=ela=2 p1='driver id'=1413697536 p2='#bytes'=1 p3=''=0 xphy=0 obj#=76357 tim=5789636387057
021 +WAIT #26: nam='SQL*Net message from client' xe=ela=42743 p1='driver id'=1413697536 p2='#bytes'=1 p3=''=0 xphy=0 obj#=76357 tim=5789636429824
022 VIRTUAL CALL #-8: 'wait-for-client'
023 VIRTUAL CALL #-5: 'client-message-received'
024   STAT  #28: id=1 pid=0 pos=1 obj=76357 op='TABLE ACCESS FULL T' cnt=200 avg(cnt)=200.0 card=n/a cr=4 avg(cr)=4.0 cost=n/a pr=2 pw=0 time=363 size=n/a xnexecs=1 xstatn=0 xplannum=0
025
026 VIRTUAL CALL #-4: 'null call - ignore this'

This can be obtained using the “save as text“ popup menu of the middle pane.

We are going to keep exploring Xtrace in the upcoming posts.


  1. Alberto Dell’Era’s Oracle blog » Xtrace: an Oracle session trace browser – exec flow

    Monday, May 17, 2010

    [...] introduced Xtrace in this post; the Xtrace home page contains the tool (which can be used online or downloaded) – and a manual for [...]

  2. Kamus

    Sunday, May 23, 2010

    But … How can I use this utility to open a specified log file? I just double click it and it opens an ora11gr2_ora_2776_xtrace_exec_flow_11_2_0_1.trc for me? why?

  3. Alberto Dell'Era

    Sunday, May 23, 2010

    @Kamus

    That’s because you clicked on the “launch” button on the “exec flow” post, a button that is designed to browse the file I used as an example in the post.

    If you want to process your own file, try clicking on the “launch” button on the main page:
    http://www.adellera.it/xtrace/
    (also linked as the “xtrace” tab above)

    and the tool will ask you to select a trace file as input.

    Another option, perhaps less convenient: download xtrace.jar from the main page, and then, from the command line:
    java -jar xtrace.jar mytracefile.trc

  4. Blogroll Report 02/04 /2010 – 09/04/2010 « Coskan’s Approach to Oracle

    Monday, July 19, 2010

    [...] 9-XTRACE session trace browser to browse in a tracefile Alberto Dell’era-Xtrace: an Oracle session trace browser (introduction) [...]

  5. Satheesh

    Sunday, July 1, 2012

    Thanks for providing such a great tool. I tried to use the tool for my trace file but it is getting failed with below error. Could you please suggest how to fix it

    java.lang.NumberFormatException: For input string: “1844674406941641933000″
    at java.lang.NumberFormatException.forInputString(Unknown Source)
    at java.lang.Long.parseLong(Unknown Source)
    at java.lang.Long.parseLong(Unknown Source)
    at xtrace.e.k.b(Unknown Source)
    at xtrace.e.k.m(Unknown Source)
    at xtrace.e.k.q(Unknown Source)
    at xtrace.e.k.b(Unknown Source)
    at xtrace.e.i.b(Unknown Source)
    at xtrace.Xtrace.main(Unknown Source)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at com.sun.javaws.Launcher.executeApplication(Unknown Source)
    at com.sun.javaws.Launcher.executeMainClass(Unknown Source)
    at com.sun.javaws.Launcher.doLaunchApp(Unknown Source)
    at com.sun.javaws.Launcher.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

  6. Alberto Dell'Era

    Tuesday, July 10, 2012

    Hi Satheesh,

    please send me the trace file at alberto.dellera@gmail.com, so that I can investigate the issue

    thanks
    Alberto

Leave a Comment

Please enclose SQL code inside the tag pair [sql] ... [/sql]

Subscribe without commenting

Links (alphabetical order)

Blogroll (alphabetical order)

Blog Aggregators (alphabetical order)


Switch to our mobile site