Understanding SQL Trace, TKPROF and Execution Plan for beginners Carlos Sierra
Agenda • Motivation • SQL Trace • TKPROF • Execution Plan
Motivation • My report is taking too long… • One Materialize View is sudently hanging... • This page is taking long since last upgrade... • It runs faster on my development instance... • Everything is slow, then the DBA has to fix it... • Where to start?
SQL Trace • Performance information on individual SQL • CPU and Elapsed Time • Wait Events • Execution Plan • Rows processed • Call count (parse, execute and fetch) • Physical and Logical reads
Tracing Process 1. Turn SQL Trace on 2. Execute some SQL or PL/SQL 3. Turn SQL Trace off 4. Find Trace File 5. Aggregate Trace into a Summary report (TKPROF) 6. Review Trace and TKPROF
Turning SQL Trace on and off • DBMS_SESSION.SESSION_TRACE_ENABLE – WAITS (default TRUE) – BINDS (default FALSE) – PLAN_STAT (default NULL) • NEVER • FIRST_EXECUTION (equivalent to NULL) • ALL_EXECUTIONS • DBMS_SESSION.SESSION_TRACE_DISABLE
Other ways to turn Trace on and off • DBMS_SESSION.SET_SQL_TRACE(TRUE|FALSE) • ALTER SESSION SET SQL_TRACE = TRUE|FALSE • ALTER SESSION SET EVENT 10046 • DBMS_MONITOR.SESSION_TRACE_ENABLE or DIS • ALTER SYSTEM SET EVENTS 'sql_trace [sql:&&sql_id] bind=true, wait=true'; • ORADEBUG • Oracle Enterprise Manager (OEM)
Alter Session • ALTER SESSION SET – SQL_TRACE = [ TRUE | FALSE ] – EVENTS ‘10046 trace name context forever, level N’ • N = 1: all executions (10g-) or 1st execution (11g+) • N = 4: Binds • N = 8: Waits • N = 12 = 4 + 8 • N = 16: each execution (11g+) • N = 64: 1st + each where DB time > 1min (11.2.0.2+)
Finding SQL Trace • Get Trace Filename from V$DIAG_INFO (11g+) • Get Trace Directory from USER_DUMP_DEST (10g-) – Use V$DIAG_INFO on 11g and 12c
Sample SQL over Sample HR Schema
GettingSQLTrace
MOS39817.1
TKPROF • Inputs a SQL Trace • Outputs an aggregated TKPROF report • Example: – tkprof trace_file.trc tkprof.txt • Sort (optional): – sort=(exeela,fchela)
GettingaTKPROF
• Rows returned on 1st execution, in average and max • Consistent reads, physical reads/writes, etc.
• Metrics include aggregates of sub-operations • Rows processed (returned by operations)
• Wait events (enabled by default on API used) • Useful to understand gap between CPU and Elapsed
Execution Plan • Set of steps to execute a SQL statement – Mostly Access Operations and Joins • Better understood by correlating Plan to SQL • Hard to read without predicate information • Column projection also eases understanding • Figuring out execution order can be a challenge!
Common Access Operations • Table access – Full – By ROWID • Index access – Full – Range – Unique
Join Types • Equijoin • Outer-join • Semi-join • Anti-join • Cross-join • Self-join
Name the Subquery In-line View Scalar SQ Non-correlated SQ Correlated SQ
Join Methods • Nested Loop – Small sets – Index access • Hash Join – Medium to large sets – Equality predicates • Sort Merge Join
Nested Loop
Hash Join
Sort Merge Join
Getting Predicates and Projection • Use DBMS_XPLAN • DISPLAY (from PLAN_TABLE) – FORMAT: ADVANCED • DISPLAY_CURSOR (from Memory thus actual plan) – FORMAT: ADVANCED ALLSTATS LAST • SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY%());
Two Tables Join
Five Tables Join
e2(6) ▻ e1(7) ▻ jh(8) ▻ d(12) ▻ l(14) 1. e2 ▻ e1 : hj(3) 2. ▻ jh : nl(2) 3. ▻ d : nl(1) semi pp 4. ▻ l : nl(11)
SQLDeveloper
TKPROF
Summary • Trace shows performance information per SQL • Trace and TKPROF do not require additional license • Trace includes Execution Plan when Cursor closes • DBMS_XPLAN provides Predicates and Projection • Understand first what the SQL does • Then correlate SQL to Execution Plan • Focus where the Time is spent!
References • My Oracle Support (MOS) – 39817.1 Interpreting Raw SQL_TRACE output – 376442.1 How to Collect 10046 Trace (SQL_TRACE) Diagnostics for Performance Issues • https://oracle-base.com/articles/misc/sql-trace- 10046-trcsess-and-tkprof • Oracle Documentation • Google
Questions
The End • http://carlos-sierra.net/ – Blog and downloads • carlos.sierra.usa@gmail.com – Questions and follow-up • Keep learning!

Understanding SQL Trace, TKPROF and Execution Plan for beginners

  • 1.
    Understanding SQL Trace,TKPROF and Execution Plan for beginners Carlos Sierra
  • 2.
    Agenda • Motivation • SQLTrace • TKPROF • Execution Plan
  • 3.
    Motivation • My reportis taking too long… • One Materialize View is sudently hanging... • This page is taking long since last upgrade... • It runs faster on my development instance... • Everything is slow, then the DBA has to fix it... • Where to start?
  • 4.
    SQL Trace • Performanceinformation on individual SQL • CPU and Elapsed Time • Wait Events • Execution Plan • Rows processed • Call count (parse, execute and fetch) • Physical and Logical reads
  • 5.
    Tracing Process 1. TurnSQL Trace on 2. Execute some SQL or PL/SQL 3. Turn SQL Trace off 4. Find Trace File 5. Aggregate Trace into a Summary report (TKPROF) 6. Review Trace and TKPROF
  • 6.
    Turning SQL Traceon and off • DBMS_SESSION.SESSION_TRACE_ENABLE – WAITS (default TRUE) – BINDS (default FALSE) – PLAN_STAT (default NULL) • NEVER • FIRST_EXECUTION (equivalent to NULL) • ALL_EXECUTIONS • DBMS_SESSION.SESSION_TRACE_DISABLE
  • 7.
    Other ways toturn Trace on and off • DBMS_SESSION.SET_SQL_TRACE(TRUE|FALSE) • ALTER SESSION SET SQL_TRACE = TRUE|FALSE • ALTER SESSION SET EVENT 10046 • DBMS_MONITOR.SESSION_TRACE_ENABLE or DIS • ALTER SYSTEM SET EVENTS 'sql_trace [sql:&&sql_id] bind=true, wait=true'; • ORADEBUG • Oracle Enterprise Manager (OEM)
  • 8.
    Alter Session • ALTERSESSION SET – SQL_TRACE = [ TRUE | FALSE ] – EVENTS ‘10046 trace name context forever, level N’ • N = 1: all executions (10g-) or 1st execution (11g+) • N = 4: Binds • N = 8: Waits • N = 12 = 4 + 8 • N = 16: each execution (11g+) • N = 64: 1st + each where DB time > 1min (11.2.0.2+)
  • 9.
    Finding SQL Trace •Get Trace Filename from V$DIAG_INFO (11g+) • Get Trace Directory from USER_DUMP_DEST (10g-) – Use V$DIAG_INFO on 11g and 12c
  • 10.
    Sample SQL overSample HR Schema
  • 11.
  • 15.
  • 16.
    TKPROF • Inputs aSQL Trace • Outputs an aggregated TKPROF report • Example: – tkprof trace_file.trc tkprof.txt • Sort (optional): – sort=(exeela,fchela)
  • 17.
  • 21.
    • Rows returnedon 1st execution, in average and max • Consistent reads, physical reads/writes, etc.
  • 22.
    • Metrics includeaggregates of sub-operations • Rows processed (returned by operations)
  • 23.
    • Wait events(enabled by default on API used) • Useful to understand gap between CPU and Elapsed
  • 24.
    Execution Plan • Setof steps to execute a SQL statement – Mostly Access Operations and Joins • Better understood by correlating Plan to SQL • Hard to read without predicate information • Column projection also eases understanding • Figuring out execution order can be a challenge!
  • 25.
    Common Access Operations •Table access – Full – By ROWID • Index access – Full – Range – Unique
  • 26.
    Join Types • Equijoin •Outer-join • Semi-join • Anti-join • Cross-join • Self-join
  • 27.
    Name the Subquery In-lineView Scalar SQ Non-correlated SQ Correlated SQ
  • 28.
    Join Methods • NestedLoop – Small sets – Index access • Hash Join – Medium to large sets – Equality predicates • Sort Merge Join
  • 29.
  • 30.
  • 31.
  • 32.
    Getting Predicates andProjection • Use DBMS_XPLAN • DISPLAY (from PLAN_TABLE) – FORMAT: ADVANCED • DISPLAY_CURSOR (from Memory thus actual plan) – FORMAT: ADVANCED ALLSTATS LAST • SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY%());
  • 33.
  • 35.
  • 36.
    e2(6) ▻ e1(7)▻ jh(8) ▻ d(12) ▻ l(14) 1. e2 ▻ e1 : hj(3) 2. ▻ jh : nl(2) 3. ▻ d : nl(1) semi pp 4. ▻ l : nl(11)
  • 37.
  • 38.
  • 39.
    Summary • Trace showsperformance information per SQL • Trace and TKPROF do not require additional license • Trace includes Execution Plan when Cursor closes • DBMS_XPLAN provides Predicates and Projection • Understand first what the SQL does • Then correlate SQL to Execution Plan • Focus where the Time is spent!
  • 40.
    References • My OracleSupport (MOS) – 39817.1 Interpreting Raw SQL_TRACE output – 376442.1 How to Collect 10046 Trace (SQL_TRACE) Diagnostics for Performance Issues • https://oracle-base.com/articles/misc/sql-trace- 10046-trcsess-and-tkprof • Oracle Documentation • Google
  • 41.
  • 42.
    The End • http://carlos-sierra.net/ –Blog and downloads • carlos.sierra.usa@gmail.com – Questions and follow-up • Keep learning!

Editor's Notes

  • #39 NSO: Nested Subquery Optimization