Systems Engineering and RDBMS

Trace Analyzer

Posted by decipherinfosys on March 29, 2007

Trace Analyzer is an Oracle utility and is used to generate a comprehensive report that can be used to troubleshoot common SQL performance issues, or functional issues requiring to find the values of bind variables using the raw SQL Trace files with binds/waits that are generated by EVENT 10046 with Levels 4, 8 or 12. You can refer NOTE: 224270 on Metalink for further reference on this utility.

From that Metalink Note, here is what this utility offers:

/********************************************************************************************************************************************/

Metalink Note: 224270:

The Trace Analyzer report includes, for any given Raw SQL Trace:

  1. Total User Elapsed Time (actual); Accounted Elapsed and CPU Times (same as TKPROF); WAIT Times (IDLE and NON-IDLE).
  2. Top 5 expensive SQL in terms of CPU, Elapsed, non-idle and idle wait times.
  3. Gaps of no tracing activity; Oracle Errors; End of Transactions (COMMIT or ROLLBACK).
  4. Summary of CALLs (PARSE, EXECUTE, FETCH) by USER/INTERNAL and RECURSIVE/NON-RECURSIVE (similar to TRCSUMMARY and last page of TKPROF).
  5. Summary of CALLs per Command Type (SELECT, INSERT, etc.) by USER/INTERNAL and RECURSIVE/NON-RECURSIVE.
  6. Summary of WAITs (IDLE and NON-IDLE) by USER/INTERNAL and RECURSIVE/NON-RECURSIVE (similar to TRCSUMMARY).
  7. Hottest 5 blocks (most times waited for)
  8. Summary of CPU, Elapsed Time and WAITs per SQL Statement (CURSOR).
  9. Summary of Physical Reads, Logical Reads, Number of Rows and Library Cache Misses per SQL Statement (CURSOR).
  10. For each SQL Statement (CURSOR).
    1. CURSOR_ID, Length, Address, Hash Value, Optimizer Goal, USER, Parsing Errors.
    2. SQL Statement Text.
    3. CALLs Summary, including CALLs Count, CPU Time, Elapsed Time, Physical Reads (disk), Logical Reads (query and current), Rows, and Library Cache Misses.
    4. Row Source Plan.
    5. Explain Plan (if SQL Trace is processed on same Instance where it was generated). Includes execution order.
    6. List of tables being accessed by SQL according to Explain Plan, and indexes for these tables. Includes CBO Stats: number of rows, blocks, sample size and last analyzed date.
    7. For listed indexes, their indexed columns and if the index is unique or not.
    8. WAIT EVENTs and corresponding details (ex: Table/Index names and count of accessed blocks).
    9. Bind Variables Values used for each Execution.
    10. Execution Performance of each set of Bind Variables Values.

/********************************************************************************************************************************************/

We used this utility recently to help us find duplicate SQLs that were being fired by the application code – those SQLs were being dynamically generated using an ORM (Object Relational Mapper) and the application was un-necessarily re-loading the same data again and again. This utility was used to identify the bind variable values to ensure that the statements were indeed duplicate and were then matched with the application code to see why there was a need to re-load the data. We were able to remove a lot of such redundant calls and that in the end helped improve the performance of the application significantly since there were savings not only on the network round trips and the database execution but also on the application tier.

Getting SQL Counts

Assuming that you have run the Trace Analyzer utility on the generated trace files (we have covered tracing in Oracle before in our blog posts – you can search for them if you want to read up on tracing in oracle), you can use these scripts to find out the repeated SQL. First, you need to find out the TRACE_ID value for you trace files. The following SQL will return you the TRACE_ID for your trace file output.

SQL> Select Trace_Id From Trca$Trace
Where Trace_Filename = ‘<trace filename>’;

Then you can use this script:

Set Pages 1000 Lines 120 Veri Off Feed Off Echo Off
DEF p_trace_id = &1;

Col Ad Head ‘Address’ Format a10 wrap
Col Hv Head ‘Hash|Value’ Format 9999999999 wrap
Col Sql_Text Head ‘Sql Text’ Format a75 wrap
Col Without_Binds head ‘Count|W/O Binds’ format 9999999
Col With_Binds head ‘Count|W/ Binds’ format 9999999
Ttitle “SQL Statements that are executed more than once with/without Bind values”
Brea On Cursor_Id On Ad On HV On Without_Binds On With_Binds
Select Trca$cursor.Ad,
Trca$cursor.Hv,
Trca$Sql_Counts.Without_Binds,
Trca$Sql_Counts.With_Binds,
Trim(Trca$sql_Text.Sql_Text) As Sql_Text
From Trca$cursor
Inner Join Trca$sql_Text
On Trca$cursor.Trace_Id = Trca$sql_Text.Trace_Id
And Trca$cursor.Cursor_Id = Trca$sql_Text.Cursor_Id
Inner Join (Select /*+rule */
Trca$parsing_In_Cursor.Trace_Id As Trace_Id,
Trca$parsing_In_Cursor.Cursor_Id As Cursor_Id,
Count(*) As Without_Binds,
0 As With_Binds
From Trca$parsing_In_Cursor
Where Trca$parsing_In_Cursor.Trace_Id = &&p_trace_id
And Not Exists
(Select 1
From Trca$binds
Where Trca$binds.Cursor_Id = Trca$parsing_In_Cursor.Cursor_Id
And Trca$binds.Trace_Id = Trca$parsing_In_Cursor.Trace_Id)
And Exists
(Select 1
From Trca$cursor
Where Trca$cursor.Cursor_Id = Trca$parsing_In_Cursor.Cursor_Id
And Trca$cursor.Trace_Id = Trca$parsing_In_Cursor.Trace_Id
And Trca$cursor.Uid$ <> 0)
Group By Trca$parsing_In_Cursor.Trace_Id,
Trca$parsing_In_Cursor.Cursor_Id
Having Count(*) > 1
Union
Select /*+rule */
Trca$parsing_In_Cursor.Trace_Id,
Trca$parsing_In_Cursor.Cursor_Id,
0,
Count(*)
From Trca$parsing_In_Cursor
Where Trca$parsing_In_Cursor.Trace_Id = &&p_trace_id
And Exists
(Select 1
From Trca$binds
Where Trca$binds.Cursor_Id = Trca$parsing_In_Cursor.Cursor_Id
And Trca$binds.Trace_Id = Trca$parsing_In_Cursor.Trace_Id)
And Exists
(Select 1
From Trca$cursor
Where Trca$cursor.Cursor_Id = Trca$parsing_In_Cursor.Cursor_Id
And Trca$cursor.Trace_Id = Trca$parsing_In_Cursor.Trace_Id
And Trca$cursor.Uid$ <> 0)
Group By Trca$parsing_In_Cursor.Trace_Id,
Trca$parsing_In_Cursor.Cursor_Id
Having Count(*) > 1) Trca$sql_counts
On Trca$Cursor.Trace_Id = Trca$Sql_Counts.Trace_Id
And Trca$Cursor.Cursor_Id = Trca$Sql_Counts.Cursor_Id
Where Trca$Cursor.Trace_Id = &&p_trace_id
Order By Trca$cursor.Cursor_Id, Trca$Sql_Text.piece
/

Usage:
Using SQL*Plus (log into Trace Analyzer repository)
SQL> start SqlCounts <trace_id>

Sample Output:
Hash Count Count
Address Value W/O Binds W/ Binds Sql Text
———- ———– ——— ——– —————————————————————-
8b85b778 1497648559 696 0 SELECT ADDRESS.ADDRESS_LINE_1 FROM ADDRESS

Where
Address: represents the SQL Address of the query, that can be joined with V$SQLAREA for any additional info. Should be used along with with Hash_Value. Please note that this value should be used with INSTR function.
Hash_Value: represents the SQL Hash Value of the query that can be joined with V$SQLAREA for any additional info. Should be used along with Address.
Count W/O Binds: represents the number of times the query is executed without bind values
Count W/ Binds: represents the number of times the query is executed with bind values.

Getting Repeated SQLs with Bind values

This script shown below displays information regarding the SQL that are executed more than once using the same bind value(s). The output of this script is in two parts.

1. Shows the text of the SQL that is being executed more than once along with CURSOR_ID, ADDRESS and HASH_VALUE information.
2. Shows the actual bind values used in the above queries along with the CURSOR_ID and #of Repeats. You have to match the bind value output to the above output using the Cursor_Id value

Set Pages 1000 Lines 120 Veri Off Feed Off Echo Off

DEF p_trace_id = &1;

Col Cursor_Id Head ‘Cur|Id’ Format 999
Col Address Head ‘Address’ Format a12
Col Hash_Value Head ‘Hash|Value’ Format 999999999999
Col Sql_Text Head ‘Sql Text’ Format a80
Ttitle “SQL Statements that are executed repeatedly with same Bind values”
Brea On Cursor_Id On Address On Hash_Value skip 1
Select /*+rule */
Trca$cursor.Cursor_Id As Cursor_Id,
Trca$cursor.Ad As Address,
Trca$cursor.Hv As Hash_Value,
Trca$sql_Text.Sql_Text As Sql_Text
From Trca$cursor Inner Join Trca$sql_Text
On Trca$cursor.Trace_Id = Trca$sql_Text.Trace_Id
And Trca$cursor.Cursor_Id = Trca$sql_Text.Cursor_Id
Where Trca$cursor.Trace_Id = &&p_Trace_Id
And Trca$cursor.Uid$ <> 0
And Exists
(Select 1
From Trca$parsing_In_Cursor,
Trca$binds
Where Trca$parsing_In_Cursor.Trace_Id = Trca$binds.Trace_Id
And Trca$parsing_In_Cursor.Line_Id = Trca$binds.Parsing_In_Cursor_Line_Id
And Trca$parsing_In_Cursor.Cursor_# = Trca$binds.Cursor_#
And Trca$parsing_In_Cursor.Cursor_Id = Trca$binds.Cursor_Id
And Trca$parsing_In_Cursor.Trace_Id = Trca$cursor.Trace_Id
And Trca$parsing_In_Cursor.Cursor_Id = Trca$cursor.Cursor_Id
Group By Trca$parsing_In_Cursor.Trace_Id,
Trca$parsing_In_Cursor.Cursor_Id,
Trca$parsing_In_Cursor.Ad,
Trca$parsing_In_Cursor.Hv,
Trca$binds.Binds
Having Count(*) > 1)
Order By Trca$cursor.Cursor_Id,
Trca$sql_Text.Piece Asc
/
Ttitle Off
Ttitle “Bind Value Information for above Statement’s Cursor Id”
Col Bind_Value Head ‘Bind|Value’ Form a80
Col Repeat_Count head ‘# of|Repeats’ form 999,999,999
Select /*+rule */
Trca$parsing_In_Cursor.Cursor_Id As Cursor_Id,
Trca$binds.Binds As Bind_Value,
Count(*) As Repeat_Count
From Trca$parsing_In_Cursor,
Trca$binds
Where Trca$parsing_In_Cursor.Trace_Id = Trca$binds.Trace_Id
And Trca$parsing_In_Cursor.Line_Id = Trca$binds.Parsing_In_Cursor_Line_Id
And Trca$parsing_In_Cursor.Cursor_# = Trca$binds.Cursor_#
And Trca$parsing_In_Cursor.Cursor_Id = Trca$binds.Cursor_Id
And Trca$parsing_In_Cursor.Trace_Id = &&p_Trace_Id
And Exists
(Select 1
From Trca$cursor
Where Trca$cursor.Cursor_Id = Trca$parsing_In_Cursor.Cursor_Id
And Trca$cursor.Trace_Id = Trca$parsing_In_Cursor.Trace_Id
And Trca$cursor.Uid$ <> 0)
Group By Trca$parsing_In_Cursor.Trace_Id,
Trca$parsing_In_Cursor.Cursor_Id,
Trca$parsing_In_Cursor.Ad,
Trca$parsing_In_Cursor.Hv,
Trca$binds.Binds
Having Count(*) > 1
/

clear breaks columns
undef 1 p_trace_id

Usage:
Using SQL*Plus (log into Trace Analyzer repository)
SQL> start SqlRepeatsWithBinds.sql <trace_id>

Sample Output:

Cur Hash
Id Address Value Sql Text
—- ———— ————- —————————————————————————
14 8f2b83f8 4008304268 SELECT USER_MASTER.USER_NAME
FROM USER_MASTER
WHERE ( (((( USER_MASTER.ID = :1 ) AND ( USER_MASTER.CO = :2 ) )
AND (USER_MASTER.DIV = :3 )) AND (USER_MASTER.TYPE = :4 ))
AND ( USER_MASTER.VAL_FLAG = :5 ) )

Cur Bind # of
Id Value Repeats
—- ——————————————————————————– ————
14 0:”100″ 1:”100″ 2:”100″ 3:101 4:”L” 348
0:”100″ 1:”100″ 2:”100″ 3:101 4:”U” 348

Please do note that the same can be achieved by doing code instrumentation at the application layer to shell out the statements to a file and then just running a parser against it to present it in a readable format. This client was using an in-house built data access layer and had that functionality also baked into the product so that was also used to shell out the statements along with the bind values to a text file and then using perl, we were able to parse through that file and present it in the right format and the output was the same as shown above.

One Response to “Trace Analyzer”

  1. […] files into single trace file. Once all the files are combined into one file, we can run tkprof or trace analyzer on the file to collect more meaningful data. Basic syntax for trcsess utility is as […]

Sorry, the comment form is closed at this time.

 
%d bloggers like this: