SQL Trace and TKPROF let you to accurately assess the efficiency of the SQL statements when an application runs. For best results, use these tools with EXPLAIN PLAN rather than using EXPLAIN PLAN alone.

Trace File and TKPROF Utility

The SQL Trace facility and TKPROF let you accurately assess the efficiency of the SQL statements an application runs. For best results, use these tools with EXPLAIN PLAN rather than using EXPLAIN PLAN alone

SQL trace

  • When enabled writes detailed information about all database calls and operations to a trace file.
  • Can be enabled/disabled for individual sessoion or for entire instance
  • Values of bind variables can also be set
  • SQL trace files are text files. They are extremely verbose, repetitive, and cryptic
  • You should use dedicated server mode when tracing a database session with SQL trace.
  • There is a over-head on database about 10 to 15% when you enabled SQL trace.
  • Trace files generated immediately after instance startup contain data that reflects the activity of the startup process. In particular, they reflect a disproportionate amount of I/O activity as caches in the system global area (SGA) are filled. For the purposes of tuning, ignore such trace files.

TKPROF [Transient Kernel Profiler]

  • It essentially formats a trace file into a more readable format for performance analysis.
  • Each SQL statement is displayed in the report, along with
    1. counts of how many times it was parsed, executed, and fetched.
    2. CPU time, elapsed time,
    3. logical reads, physical reads,
    4. rows processed are also reported, along with information about recursion level and misses in the library cache.

  • TKPROF will not connect to the database.
  • Before you can use TKPROF, you need to generate a trace file and locate it.

Using the SQL Trace Facility and TKPROF

  1. Set initialization parameters for trace file management.
  2. Enable the SQL Trace facility for the desired session, and run the application.
  3. Run TKPROF to translate the trace file created in Step 2 into a readable output file. This step can optionally create a SQL script that can be used to store the statistics in a database.
  4. Interpret the output file created in Step 3.
  5. Optionally, run the SQL script produced in Step 3 to store the statistics in the database.

    Step: 1 -initialization parameters

    Parameter Description
    TIMED_STATISTICS Parameter enabled detailed timing information to trace file.
    MAX_DUMP_FILE_SIZE Specify the size of trace file. When reaches the maximum size, the server process stops writing trace information to the trace file.
    USER_DUMP_DEST initialization parameter is default location of SQL trace file

     

    Timed_statistics

    select name,value from v$parameter 
    where name like 'timed%'
    Find the existing value of the parameter
    ALTER SYSTEM SET timed_statistics = TRUE;
    Set Timed_statistics parameter (Instance level)
    ALTER SESSION SET timed_statistics = TRUE|FALSE;
    Set Timed_statistics parameter (Session level)

     

    User_dump_dest

    select value from v$parameter
    where name = 'user_dump_dest';

    Obtain the directory name of the trace file

    Step: 2 -Enable SQL Trace

    ALTER SYSTEM SET sql_trace = TRUE;

    Every Session will be traced. (Instance Level)

    ALTER SESSION SET sql_trace = TRUE|FALSE;
    EXECUTE DBMS_SESSION.SET_SQL_TRACE(TRUE);
    Enable SQL trace in current session (Session Level)
    First "grant alter session to scott;"
    EXECUTE SYS.dbms_system.set_sql_trace_in_session 
    (<SID>, <serial#>, TRUE|FALSE);
    To Enable SQL trace in another session (Session Level)
    SELECT SID,SERIAL#, USERNAME FROM V$SESSION;
    To find SID and SERIAL# to use in procedure

    Step: 3 -Run / Format using TKPROF

    TKPROF does not report COMMITs and ROLLBACKs that are recorded in the trace file.

    Syntax
    TKPROF (Trace_filename) (output_filename) [waits=yes|no] [sort=OPTION]
    [print=n] [aggregate=yes|no] [INSERT=filename3] [sys=yes|no]
    [TABLE=schema.TABLE] [EXPLAIN=user/password] [record=filename4] [width=n]

     

    [waits=yes|no]                    
    Record summary for any wait events in trace file Default is YES.

    [print=n]
    Lists only the first integer sorted SQL statements from the output file. If you omit this parameter, then TKPROF lists all traced SQL statements to output file.

    [aggregate=yes|no]

    If specify AGGREGATE = NO, then TKPROF does not aggregate multiple users of the same SQL text.

    [insert=filename3]

    Creates a SQL script that stores the trace file statistics in the database. This script creates a table and inserts a row of statistics for each traced SQL statement into the table.


    [sys=yes|no]                       
    :SQL statements issued by user SYS, or recursive SQL statement, into the output file default is YES. if set NO SQL statement by user SYS will omit in outout file.

    [table=schema.table]
    Specifies the schema and name of the table into which TKPROF temporarily places execution plans before writing them to the output file. If table already exists, it deletes all rows in the table, uses it for the EXPLAIN PLAN statement and then deletes those rows. If this table does not exist, then TKPROF creates it, uses it, and then drops it.

    [explain=user/password]
    Determines the execution plan for each SQL statement in the trace file and writes these execution plans to the output file. TKPROF determines execution plans by issuing the EXPLAIN PLAN statement after connecting to Oracle with the user and password specified in this parameter

    [record=filename4]
    Creates a SQL script with the specified filename4 with all of the nonrecursive SQL in the trace file.

    [width=n]
    integer controls the output line width of some TKPROF output, such as the explain plan.

    [sort=option]
    Sorts traced SQL statements in descending order of specified sort option before listing them into the output file. If you omit this parameter, then TKPROF lists statements into the output file in order of first use. modes of sort

    PRSCNT Number of times parsed.
    PRSCPU CPU time spent parsing.
    PRSELA Elapsed time spent parsing.
    PRSDSK Number of physical reads from disk during parse.
    PRSQRY Number of consistent mode block reads during parse.
    PRSCU Number of current mode block reads during parse.
    PRSMIS Number of library cache misses during parse.
    EXECNT Number of executes.
    EXECPU CPU time spent executing.
    EXEELA Elapsed time spent executing.
    EXEDSK Number of physical reads from disk during execute.
    EXEQRY Number of consistent mode block reads during execute.
    EXECU Number of current mode block reads during execute.
    EXEROW Number of rows processed during execute.
    EXEMIS Number of library cache misses during execute.
    FCHCNT Number of fetches.
    FCHCPU CPU time spent fetching.
    FCHELA Elapsed time spent fetching.
    FCHDSK Number of physical reads from disk during fetch.
    FCHQRY Number of consistent mode block reads during fetch.
    FCHCU umber of current mode block reads during fetch.
    FCHROW Number of rows fetched.

     

    Examples of TKPROF Statement

    The following statement prints the 10 statements in the trace file that have generated the most physical I/O and SYS=NO omit recursive SQL statements.

    TKPROF ora53269.trc ora53269.prf SORT = (PRSDSK, EXEDSK, FCHDSK) 
    PRINT = 10 SYS=NO

     

    Step: 4 - Interpreting TKPROF Output

    SELECT table_name
    FROM user_tables
    ORDER BY table_name
    Misses in library cache during parse: 1
    Optimizer goal: CHOOSE
    Parsing user id: RSCHRAG [recursive depth: 0]

     

    4.1 CALL Column Values

    CALL ValueMeaning
    PARSE Translates the SQL statement into an execution plan
    (security authorization, existence of tables, columns, and other referenced objects.)
    EXECUTE

    Actual execution of the statement. For INSERT, UPDATE, and DELETE, modifies the data. For SELECT, identifies the selected rows.

    FETCH Retrieves rows returned by a query. Fetches are only performed for SELECT statements.

     

    4.2 SQL Trace Statistics for all Parses, Executes, and all Fetches.

    SQL Trace StatisticMeaning
    COUNT Number of times a statement was parsed, executed, or fetched.
    CPU Total CPU time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if TIMED_STATISTICS is not turned on.
    ELAPSED Total elapsed time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if TIMED_STATISTICS is not turned on.
    DISK Total number of data blocks physically read from the datafiles on disk for all parse, execute, or fetch calls.
    QUERY Total number of buffers retrieved in consistent mode for all parse, execute, or fetch calls. Usually, buffers are retrieved in consistent mode for queries.
    CURRENT Total number of buffers retrieved in current mode. Buffers are retrieved in current mode for statements such as INSERT, UPDATE, and DELETE.

     

    4.3 SQL Trace Statistics for the ROWS Column

    SQL Trace StatisticMeaning
    ROWS Total number of rows processed by the SQL statement. This total does not include rows processed by subqueries of the SQL statement.
    For SELECT statements, the number of rows returned appears for the fetch step. For UPDATE, DELETE, and INSERT statements, the number of rows processed appears for the execute step.
    Note:The row source counts are displayed when a cursor is closed. In SQL*Plus, there is only one user cursor, so each statement executed causes the previous cursor to be closed; therefore, the row source counts are displayed. PL/SQL has its own cursor handling and does not close child cursors when the parent cursor is closed. Exiting (or reconnecting) causes the counts to be displayed.

     

    4.4 Row Source Operations

    Provide number of rows processed for each operation executed on the rows and additional information, such as physical reads and writes.

    call      count cpu   elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    Parse 1 0.01 0.02 0 0 0 0
    Execute 1 0.00 0.00 0 0 0 0
    Fetch 14 0.59 0.99 0 33633 0 194
    ------- ------ -------- ---------- ---------- ---------- ----------
    total 16 0.60 1.01 0 33633 0 194

    cr     specifies consistent reads performed by the row source

    r       specifies physical reads performed by the row source

    w     specifies physical writes performed by the row source time specifies time in microseconds

     

    4.5 Wait Event Information

    If wait event information exists, the TKPROF output includes a section similar to the following:

    Elapsed times include waiting ON following events:    
    Event waited ON Times Max. Wait Total Waited
    ---------------------------------------- Waited ---------- ------------
    db file sequential READ 8084 0.12 5.34
    direct path WRITE 834 0.00 0.00
    direct path WRITE temp 834 0.00 0.05
    db file parallel READ 8 1.53 5.51
    db file scattered READ 4180 0.07 1.45
    direct path READ 7082 0.00 0.05
    direct path READ temp 7082 0.00 0.44
    rdbms ipc reply 20 0.00 0.01
    SQL*Net message TO client 1 0.00 0.00
    SQL*Net message FROM client 1 0.00 0.00

    Wait events are summed for the entire trace file at the end of the file.

    To ensure that wait events information is written to the trace file for the session, run the following SQL statement:

    ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';

    4.6 Understanding Recursive Calls

    Sometimes, in order to execute a SQL statement Oracle issue additional statements. Such statements are called recursive calls or recursive SQL statements.

    For example, if you insert a row into a table that does not have enough space to hold that row, then Oracle makes recursive calls to allocate the space dynamically. Recursive calls are also generated when data dictionary information is not available in the data dictionary cache and must be retrieved from disk.

    You can suppress the listing of Oracle internal recursive calls (for example, space management) in the output file by setting the SYS command-line parameter to NO.

    When recursion is involved, the TKPROF report will indicate the depth of the recursion next to the parsing user.

    Use of database triggers and stored procedures can also cause recursion. Suppose an application inserts a row into a table that has a database trigger. When the trigger fires, its statements run at a recursion depth of one. If the trigger invokes a stored procedure, the recursion depth could increase to two. This could continue through any number of levels.

     

    4.7 Library Cache Misses in TKPROF

    TKPROF also lists the number of library cache misses resulting from parse and execute steps for each SQL statement. There was a miss in the library cache (SQL statement was not already in the shared pool)

     

    4.8 Identification of User Issuing the SQL Statement in TKPROF

    TKPROF also lists the user ID of the user issuing each SQL statement. If the SQL Trace input file contained statistics from multiple users and the statement was issued by more than one user, then TKPROF lists the ID of the last user to parse the statement. The user ID of all database users appears in the data dictionary in the column ALL_USERS.USER_ID

     

    4.9 CHOOSE optimizer goal

    the CHOOSE optimizer goal was used to develop the execution plan, and the parsing was performed in the RSCHRAG schema.

    Deciding Which Statements to Tune

    You need to find which SQL statements use the most CPU or disk resource. If the TIMED_STATISTICS parameter is on, then you can find high CPU activity in the CPU column

    1. Compare the number of parses to number of executions.
      A well-tuned system will have one parse per n executions of a statement and will eliminate the re-parsing of the same statement.

    2. Search for SQL statements that do not use bind variables (:variable).
      These statements should be modified to use bind variables.

    3. Identify those statements that perform full table scans, multiple disk reads, and high CPU consumption. These performance benchmarks are defined by the DBA and need to be tailored to each database. What may be considered a high number of disk reads for an OLTP application may not even be minimal for a data warehouse implementation.

    With the exception of locking problems and inefficient PL/SQL loops, neither the CPU time nor the elapsed time is necessary to find problem statements. The key is the number of block visits. You can find high disk activity in the disk column.

    SELECT * FROM emp, dept  WHERE emp.deptno = dept.deptno; 
    call   count      cpu    elapsed     disk    query current    rows
    ---- ------- ------- --------- -------- -------- ------- ------
    Parse 11 0.08 0.18 0 0 0 0
    Execute 11 0.23 0.66 0 3 6 0
    Fetch 35 6.70 6.83 100 12326 2 824
    ------------------------------------------------------------------
    total 57 7.01 7.67 100 12329 8 826

    Misses IN library cache during parse: 0

    If it is acceptable to have 7.01 CPU seconds and to retrieve 824 rows, then you need not look any further at this trace output.

    You can also see that 10 unnecessary parse call were made (because there were 11 parse calls for this one statement) and that array fetch operations were performed. A large gap between CPU and elapsed timings indicates Physical I/Os (PIOs).

    Go to top
    JSN Boot template designed by JoomlaShine.com