New Release! Announcing MR Tools (Method R Tools) version 2.1, our new production version of the trace file tools that we use every time we analyze an Oracle trace file. MR Tools is the perfect companion for the Method R Profiler. If you use tkprof, MR Tools will show you what you’ve been missing. Priced beginning at us$397 per userid.

No other tools (free or commercial) come close to the precision and trustworthiness of Method R software.

Alex Gorbachev · Pythian · Ottawa, Canada

MR Tools is a suite of software tools that we use every time we analyze an Oracle trace file, and is the star of our new Mastering Oracle Trace Data one-day course. The many improvements delivered in version 2.1 were designed to make performance analysis more delightful than ever before. The flexibility and power of these tools really do make you invincible!

We are excited to announce that we now ship binaries for both AIX PPC and HP-UX PA-RISC architectures, as well as 64-bit binaries for Linux, Windows, and Solaris.

The ultimate trace file query tool, mrskew, now ships with four new RC files. These are files which contain sets of command line arguments that make using mrskew easier than ever. The first of these files highlights the power of using new mrskew trace data variables. mrskew is so powerful that it now replaces the functionality of your old friend mrnl. The performance of mrnl has always been a problem, and now mrskew does mrnl’s job many times faster than mrnl ever did it.

$ mrskew --rc=mrnl TRHTSP01_ora_12242.trc
    LINE#         BEGIN-TIME           END-TIME      DURATION       UAFBC       UAFWC  TRACE-LINE                                                                                          
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
        1                  .                  .             .           .           .  Trace file /opt/oracle/diag/rdbms/trhtsp01/TRHTSP01/trace/TRHTSP01_ora_12242.trc                    
        2                  .                  .             .           .           .  Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production                        
        3                  .                  .             .           .           .  With the Partitioning, OLAP, Data Mining and Real Application Testing options                       
        4                  .                  .             .           .           .  ORACLE_HOME = /opt/oracle/product/11.2.0                                                            
        5                  .                  .             .           .           .  System name:    SunOS                                                                               
        6                  .                  .             .           .           .  Node name:      dotstodb032                                                                         
        7                  .                  .             .           .           .  Release:        5.10                                                                                
        8                  .                  .             .           .           .  Version:        Generic_141444-09                                                                   
        9                  .                  .             .           .           .  Machine:        sun4u                                                                               
       10                  .                  .             .           .           .  Instance name: TRHTSP01                                                                             
       11                  .                  .             .           .           .  Redo thread mounted by this instance: 1                                                             
       12                  .                  .             .           .           .  Oracle process number: 19                                                                           
       13                  .                  .             .           .           .  Unix process pid: 12242, image: oracle@dotstodb032 (TNS V1-V3)                                      
       14                  .                  .             .           .           .                                                                                                      
       15                  .                  .             .           .           .                                                                                                      
       16                  .                  .             .           .           .  *** 2010-10-18T17:46:39.956000                                                                      
       17                  .                  .             .           .           .  *** SESSION ID:(352.23) 2010-10-18T17:46:39.956000                                                  
       18                  .                  .             .           .           .  *** CLIENT ID:() 2010-10-18T17:46:39.956000                                                         
       19                  .                  .             .           .           .  *** SERVICE NAME:(SYS$USERS) 2010-10-18T17:46:39.956000                                             
       20                  .                  .             .           .           .  *** MODULE NAME:(SQL*Plus) 2010-10-18T17:46:39.956000                                               
       21                  .                  .             .           .           .  *** ACTION NAME:() 2010-10-18T17:46:39.956000                                                       
       22                  .                  .             .           .           .                                                                                                      
       23        9909.191218        9909.191258      0.000040           .   -0.000040  WAIT #18446744071472266944: nam='SQL*Net more data from dblink' ela= 40 driver id=1413697536 #bytes=
       24        9909.194368        9909.194408      0.000040           .   -0.000040  WAIT #18446744071472266944: nam='SQL*Net more data from dblink' ela= 40 driver id=1413697536 #bytes=
       25        9909.194368        9909.194408             .           .           .                                                                                                      
       26        9919.568835        9919.568859      0.000024           .    0.000024  CLOSE #18446744071463462000:c=0,e=24,dep=1,type=1,tim=9919568859                                    
       27        9919.568990        9919.569009      0.000019    0.000131    0.000019  PARSE #18446744071463460832:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3494626068,tim=991956900
       28        9919.569067        9919.569086      0.000019    0.000058    0.000019  EXEC #18446744071463460832:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3494626068,tim=9919569086
       29        9919.569122        9919.569150      0.000028    0.000036    0.000028  FETCH #18446744071463460832:c=0,e=28,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3494626068,tim=991956915
       30        9919.569188        9919.569194      0.000006    0.000038    0.000006  FETCH #18446744071463460832:c=0,e=6,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3494626068,tim=9919569194
       31        9919.569235        9919.569242      0.000007    0.000041    0.000007  CLOSE #18446744071463460832:c=0,e=7,dep=1,type=3,tim=9919569242                                     
       32        9919.569460        9919.569504      0.000044           .   -0.000044  WAIT #18446744071472266944: nam='control file sequential read' ela= 44 file#=0 block#=1 blocks=1 obj
       33        9919.569555        9919.569587      0.000032           .   -0.000032  WAIT #18446744071472266944: nam='control file sequential read' ela= 32 file#=1 block#=1 blocks=1 obj
       34        9919.569618        9919.569648      0.000030           .   -0.000030  WAIT #18446744071472266944: nam='control file sequential read' ela= 30 file#=2 block#=1 blocks=1 obj
       35        9919.569681        9919.569710      0.000029           .   -0.000029  WAIT #18446744071472266944: nam='control file sequential read' ela= 29 file#=0 block#=15 blocks=1 ob
       36        9919.569740        9919.569768      0.000028           .   -0.000028  WAIT #18446744071472266944: nam='control file sequential read' ela= 28 file#=0 block#=17 blocks=1 ob
       37        9919.569811        9919.569838      0.000027           .   -0.000027  WAIT #18446744071472266944: nam='control file sequential read' ela= 27 file#=0 block#=23 blocks=1 ob
       38        9919.569871        9919.569900      0.000029           .   -0.000029  WAIT #18446744071472266944: nam='control file sequential read' ela= 29 file#=0 block#=31 blocks=1 ob
       39        9919.569958        9919.570005      0.000047           .   -0.000047  WAIT #18446744071472266944: nam='db file sequential read' ela= 47 file#=17 block#=1 blocks=1 obj#=-1
       40        9919.570066        9919.570330      0.000264           .   -0.000264  WAIT #18446744071472266944: nam='Disk file operations I/O' ela= 264 FileOperation=2 fileno=0 filetyp
       41        9919.570394        9919.570415      0.000021           .   -0.000021  WAIT #18446744071472266944: nam='control file sequential read' ela= 21 file#=0 block#=1 blocks=1 obj
       42        9919.570448        9919.570468      0.000020           .   -0.000020  WAIT #18446744071472266944: nam='control file sequential read' ela= 20 file#=0 block#=15 blocks=1 ob
       43        9919.570499        9919.570518      0.000019           .   -0.000019  WAIT #18446744071472266944: nam='control file sequential read' ela= 19 file#=0 block#=17 blocks=1 ob
       44        9919.570549        9919.570577      0.000028           .   -0.000028  WAIT #18446744071472266944: nam='control file sequential read' ela= 28 file#=0 block#=282 blocks=1 o
       45        9919.570549        9919.570577             .           .           .                                                                                                      
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
TOTAL (45)     

Next, the --ebucket option has been replaced by an RC file called p10:

$ mrskew --rc=p10 --name=FETCH *.trc
       RANGE {min <= e < max}    DURATION       %  CALLS       MEAN        MIN        MAX
-----------------------------  ----------  ------  -----  ---------  ---------  ---------
 1.     0.000000     0.000001    0.000000    0.0%  3,588   0.000000   0.000000   0.000000
 2.     0.000001     0.000010                                                            
 3.     0.000010     0.000100                                                            
 4.     0.000100     0.001000                                                            
 5.     0.001000     0.010000                                                            
 6.     0.010000     0.100000    1.864003    0.4%    162   0.011506   0.010000   0.060000
 7.     0.100000     1.000000  215.097441   50.3%    277   0.776525   0.107984   0.990000
 8.     1.000000    10.000000  184.575456   43.1%    117   1.577568   1.000000   9.218750
 9.    10.000000   100.000000   26.296875    6.1%      1  26.296875  26.296875  26.296875
10.   100.000000 1,000.000000                                                            
11. 1,000.000000         +INF                                                            
-----------------------------  ----------  ------  -----  ---------  ---------  ---------
                   TOTAL (11)  427.833775  100.0%  4,145   0.103217   0.000000  26.296875

The histogram buckets in powers of ten is exactly what you’re going to need for calls like fetch and SQL*Net message from client, but what if you want to analyze disk reads? Those buckets aren’t quite what you’re going to want, so we provide two additional files called disk and ssd:

$ mrskew --rc=disk --name='db file sequential read' *.trc
RANGE {min <= e < max}       DURATION       %    CALLS      MEAN       MIN       MAX
----------------------  -------------  ------  -------  --------  --------  --------
 1.     0ms      5ms        73.330965    0.6%  130,538  0.000562  0.000000  0.004998
 2.     5ms     10ms       170.527234    1.4%   21,056  0.008099  0.005000  0.009999
 3.    10ms     15ms       705.394040    5.7%   63,238  0.011155  0.010000  0.014999
 4.    15ms     20ms       218.273184    1.8%   12,665  0.017234  0.015000  0.019999
 5.    20ms     25ms       206.972439    1.7%    9,456  0.021888  0.020000  0.024999
 6.    25ms     50ms       409.345601    3.3%   12,222  0.033493  0.025001  0.049979
 7.    50ms    100ms       284.400684    2.3%    4,152  0.068497  0.050000  0.099992
 8.   100ms  1,000ms     3,769.015905   30.7%    9,246  0.407637  0.100000  0.999762
 9. 1,000ms     +INF     6,457.480332   52.5%    3,006  2.148197  1.000601  5.473023
----------------------  -------------  ------  -------  --------  --------  --------
TOTAL (9)               12,294.740384  100.0%  265,579  0.046294  0.000000  5.473023

So, 3,006 read calls with more than 1-second latency apiece?! Time to talk to the SAN administrator!

If you’re running solid state disks, your histogram will more useful with these buckets in microsecond time ranges:

$ mrskew --rc=ssd --name='db file sequential read' *.trc
RANGE {min <= e < max}         DURATION       %    CALLS      MEAN       MIN       MAX
------------------------  -------------  ------  -------  --------  --------  --------
 1.       0µs       15µs       0.000072    0.0%   27,385  0.000000  0.000000  0.000014
 2.      15µs       25µs       0.001500    0.0%       75  0.000020  0.000015  0.000024
 3.      25µs       50µs       0.009314    0.0%      281  0.000033  0.000025  0.000049
 4.      50µs      100µs       0.005241    0.0%       71  0.000074  0.000050  0.000099
 5.     100µs      500µs      25.671234    0.2%   61,552  0.000417  0.000102  0.000499
 6.     500µs    1,000µs      15.659694    0.1%   25,787  0.000607  0.000500  0.000999
 7.   1,000µs   10,000µs     202.511144    1.6%   36,443  0.005557  0.001000  0.009999
 8.  10,000µs       +INF  12,050.882185   98.0%  113,985  0.105723  0.010000  5.473023
------------------------  -------------  ------  -------  --------  --------  --------
TOTAL (8)                 12,294.740384  100.0%  265,579  0.046294  0.000000  5.473023

Ouch! If your SSD array gives you those kind of results, you’d better have a serious talk with your vendor! It’s pretty obvious those files were from a system without SSD.

The best thing about RC files? You can make your own. They can store any command line options you want, and using the four RC files we ship, it’s easy to get started.

There are lots more new features as well, including a new --sort option that lets you sort mrskew output any way you want. Visit the MR Tools Change Log for a complete list.

The MR Tools suite is available at our online store.

Comments (1)

Subscribe to this comment's feed

Show/Hide comments

..., Great Article!!! As part of the performance enginee

January 04, 2012     

Great Article!!! As part of the performance engineering team of a large SAN vendor... I am very interested in getting prepared for when those serious talks with customers might occur .... Your tool is the 1st I have seen that can truthfully: #1. Identify the constraint. (What is the resource limiting the system from attaining more of its goal ?) #2. Exploit the constraint to its fullest. ( Is the constraining resource as busy as possible, exclusively on what task is most valuable to business ? ) #3. Subordinate all other processes to the decisions made in Step #2. (How can we align all tasks so they give the constraining resource everything it needs?) #4: Elevate the constraint. (Can we tune the SQL statement in context so that its use of constraining resource is more efficient. If TRUE and it does not give us all the improvement we need, then how can we acquire more of the resource (Hybrid in this case: move the hot pages in SSD)? If you could provide the recipe to reproduce these numbers...it would surely help all of us to enable the system to attain more of its goal. drew

drew sliwkowski | 65.206.2.68

Show/Hide comment form

Name

Email

Comment

smaller | bigger

Subscribe via email (Registered users only)

Write the displayed characters

Add Comment