查看SQL执行计划的方法 (ORACLE）
2017-09-10 本文已影响296人
6chen
查看执行计划的命令有很多种，但是，其实究其原理无非是通过如下四种途径：
- 查询PLAN_TABLE$表，并将表中的记录格式化成执行计划
- 查询SQL相关动态性能视图，并将其中的记录格式化成执行计划
- 通过AWR将Shared Pool中的内容转存到 AWR Repository 中，然后调用Repository中的信息，格式化成执行计划
- 通过执行SQL语句时的TRACE文件查看查看执行计划
执行计划的种类可以分为两种，一种是EXPLAIN PLAN一种是EXECUTED PLAN。EXPLAIN PLAN是在真正执行之前的解释型计划，而EXECUTED PALN是实际SQL执行过后保存的实际执行计划。相对准确的是执行过后的执行计划，而解释型的执行计划是为了分析和计算用的。
而平时常用的查看执行计划的命令有如下几种：
- EXPLAIN PLAN
- DBMS_XPLAN
- SQLPLUS AUTOTRACE
- 10046 EVENT
- 10053 EVENT （针对执行计划的生成过程进行详细分析时使用）
1. EXPLAIN PLAN
使用方法：
explain plan for <SQL STATEMENT>;
select * from table(dbms_xplan.display);
这种方法是典型的对PLAN_TABLE$进行格式化的方法。所使用的PLAN_TABLE$是一个GLOBAL TEMPORARY TABLE。关于GLOBAL TEMPORARY TABLE的特点这里不多解释。
例子：
SCOTT@dbec11g 02:36:10> explain plan for select * from emp;
Explained.
SCOTT@dbec11g 02:36:24> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------
Plan hash value: 3956160932
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 14 | 532 | 3 (0)| 00:00:01 |
| 1 | TABLE ACCESS FULL| EMP | 14 | 532 | 3 (0)| 00:00:01 |
--------------------------------------------------------------------------
8 rows selected.
2. DBMS_XPLAN
DBMS_XPALN是一个对执行计划进行格式化的包，里面提供了很多函数，常用的如下：
- dbms_xplan.display
- dbms_xplan.display_cursor
- dbms_xplan.display_awr
使用方法：
select * from table(dbms_xplan.display);
select * from table(dbms_xplan.display_cursor(null, null, 'advanced'));
select * from table(dbms_xplan.display_cursor(<SQL_ID/HASH_VALUE>, CHILD_CURSOR_NUMBER, 'advanced'));
select * from table(dbms_xplan.display_awr(<SQL_ID>));
dbms_xplan.display是从PLAN_TABLE$中查询执行计划。
dbms_xplan.display_cursor是从Shared Pool中查询执行计划。
dbms_xplan.display_awr是从AWR的Repository中查询执行计划。
例子：
SCOTT@dbec11g 02:37:35> select count(*) from emp;
COUNT(*)
----------
14
SCOTT@dbec11g 02:37:46> select * from table(dbms_xplan.display_cursor(null, null, 'advanced'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------
SQL_ID g59vz2u4cu404, child number 0
-------------------------------------
select count(*) from emp
Plan hash value: 2937609675
-------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | 1 (100)| |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | INDEX FULL SCAN| PK_EMP | 14 | 1 (0)| 00:00:01 |
-------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
2 - SEL$1 / EMP@SEL$1
Outline Data
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------
-------------
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.1')
DB_VERSION('11.2.0.1')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
INDEX(@"SEL$1" "EMP"@"SEL$1" ("EMP"."EMPNO"))
END_OUTLINE_DATA
*/
Column Projection Information (identified by operation id):
-----------------------------------------------------------
1 - (#keys=0) COUNT(*)[22]
39 rows selected.
关于使用dbms_xplan.display_cursor通过SQL_ID或HASH_VALUE查看执行计划和使用dbms_xplan.display_awr的方法不做详细解释
3. SQLPLUS AUTOTRACE
AUTOTRACE是SQLPLUS中提供的功能，只在SQLPLUS中有效。
语法如下：
SET AUTOTRACE {OFF|ON|TRACEONLY} [EXPLAIN] [STATISTICS]
在使用命令的时候可以应用如下的缩写：
AUTOTRACE --> AUTOT
TRACEONLY --> TRACE
EXPLAIN --> EXP
STATISTICS --> STAT
当使用SET AUTOTRACE TRACEONLY EXPLAIN的时候，查看某一个select语句的执行计划时，它其实是不执行的，因为命令的本身要求看的就是解释型计划。而使用AUTOTRACE命令查看INERT, UPDATE, DELETE语句的执行计划时，该语句都是执行后的真实执行计划。而除了SET AUTOTRACE TRACEONLY EXPLAIN计划以外的其他命令，若显示了执行时资源的消耗情况的话，该语句其实都是执行过的语句，因为只有执行过了才能看到执行过程中的资源消耗情况。但是，要注意的是语句中如果有绑定变量的话，显示的执行计划也会不准确，这个时候就需要使用10046 EVENT来查看准确的执行计划。
例子：
SCOTT@dbec11g 02:38:17> set autot on
SCOTT@dbec11g 02:41:45> select count(*) from emp;
COUNT(*)
----------
14
Execution Plan
----------------------------------------------------------
Plan hash value: 2937609675
-------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 1 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | INDEX FULL SCAN| PK_EMP | 14 | 1 (0)| 00:00:01 |
-------------------------------------------------------------------
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
1 consistent gets
0 physical reads
0 redo size
346 bytes sent via SQL*Net to client
475 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SCOTT@dbec11g 02:41:52> set autot off
4. 10046 EVENT
10046 EVENT中不仅显示了执行计划，也包含了执行过程中每一步执行时的具体情况，例如，每一步中耗费的逻辑读、物理读等信息。
使用方法1：
-- 开启10046
alter session set events '10046 trace name context forever, level 12';
...execute some SQL Statement...
-- 关闭10046
alter session set events '10046 trace name context off';
-- 查看DUMP文件的路径
select value from v$diag_info where name='Default Trace File';
使用方法2（需要sys权限）：
-- 对当前会话使用oradebug命令
oradebug setmypid;
-- 开启10046
oradebug event 10046 trace name context forever, level 12;
...execute some SQL Statement...
-- 关闭10046
oradebug event 10046 trace name context off;
-- 查看DUMP文件的路径
oradebug tracefile_name;
得到的TRACE文件的格式是裸格式（Raw Trace），内容并不直观，所以需要用TKPROF命令进行格式化。
关于TKPROF命令的使用方法可以直接输入tkprof查看使用帮助文档。
10046 Event Level
level 1 SQL Trace
level 4 SQL Trace + Bind Variable
level 8 SQL Trace + Wait Event
level 12 SQL Trace + Bind Variable + Wait Event
如果只想查看level 1的SQL Trace信息，也可以使用如下方法：
alter session set sql_trace = true;
...execute some SQL Statement...
alter session set sql_trace = false;
例子：
SCOTT@dbec11g 02:42:54> alter session set events '10046 trace name context forever, level 12';
Session altered.
SCOTT@dbec11g 02:43:21> select count(*) from emp;
COUNT(*)
----------
14
SCOTT@dbec11g 02:43:32> alter session set events '10046 trace name context off';
Session altered.
SCOTT@dbec11g 02:43:38> select value from v$diag_info where name='Default Trace File';
VALUE
---------------------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/dbec11g/dbec11g/trace/dbec11g_ora_8666.trc
在命令行中查看Raw Trace文件：
[oracle@dbec-lnx-svr ~]$ cat /u01/app/oracle/diag/rdbms/dbec11g/dbec11g/trace/dbec11g_ora_8666.trc
Trace file /u01/app/oracle/diag/rdbms/dbec11g/dbec11g/trace/dbec11g_ora_8666.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/dbecrdb11g
System name: Linux
Node name: dbec-lnx-svr
Release: 3.8.13-16.2.1.el6uek.x86_64
Version: #1 SMP Thu Nov 7 17:01:44 PST 2013
Machine: x86_64
Instance name: dbec11g
Redo thread mounted by this instance: 1
Oracle process number: 24
Unix process pid: 8666, image: oracle@dbec-lnx-svr
*** 2016-03-26 14:43:21.899
*** SESSION ID:(8.58671) 2016-03-26 14:43:21.899
*** CLIENT ID:() 2016-03-26 14:43:21.899
*** SERVICE NAME:(dbec11g) 2016-03-26 14:43:21.899
*** MODULE NAME:(SQL*Plus) 2016-03-26 14:43:21.899
*** ACTION NAME:() 2016-03-26 14:43:21.899
WAIT #8: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=540 tim=1458971001898756
*** 2016-03-26 14:43:32.193
WAIT #8: nam='SQL*Net message from client' ela= 10294485 driver id=1413697536 #bytes=1 p3=0 obj#=540 tim=1458971012193806
CLOSE #8:c=0,e=23,dep=0,type=1,tim=1458971012193924
=====================
PARSING IN CURSOR #10 len=24 dep=0 uid=84 oct=3 lid=84 tim=1458971012195125 hv=2295140356 ad='aec63070' sqlid='g59vz2u4cu404'
select count(*) from emp
END OF STMT
PARSE #10:c=1000,e=1152,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2937609675,tim=1458971012195124
EXEC #10:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2937609675,tim=1458971012195268
WAIT #10: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3=0 obj#=540 tim=1458971012195344
FETCH #10:c=0,e=33,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2937609675,tim=1458971012195414
STAT #10 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 pw=0 time=0 us)'
STAT #10 id=2 cnt=14 pid=1 pos=1 obj=73202 op='INDEX FULL SCAN PK_EMP (cr=1 pr=0 pw=0 time=0 us cost=1 size=0 card=14)'
WAIT #10: nam='SQL*Net message from client' ela= 802 driver id=1413697536 #bytes=1 p3=0 obj#=540 tim=1458971012196336
FETCH #10:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2937609675,tim=1458971012196385
WAIT #10: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=540 tim=1458971012196418
*** 2016-03-26 14:43:38.378
WAIT #10: nam='SQL*Net message from client' ela= 6181927 driver id=1413697536 #bytes=1 p3=0 obj#=540 tim=1458971018378369
CLOSE #10:c=0,e=16,dep=0,type=0,tim=1458971018378473
=====================
PARSING IN CURSOR #17 len=55 dep=0 uid=84 oct=42 lid=84 tim=1458971018378623 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #17:c=0,e=104,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1458971018378622
EXEC #17:c=1000,e=402,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1458971018379098
格式化后查看：
[oracle@dbec-lnx-svr ~]$ tkprof /u01/app/oracle/diag/rdbms/dbec11g/dbec11g/trace/dbec11g_ora_8666.trc ~/dbec11g_ora_8666.txt
TKPROF: Release 11.2.0.1.0 - Development on Sat Mar 26 14:47:13 2016
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
[oracle@dbec-lnx-svr ~]$ cat dbec11g_ora_8666.txt
TKPROF: Release 11.2.0.1.0 - Development on Sat Mar 26 14:47:13 2016
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: /u01/app/oracle/diag/rdbms/dbec11g/dbec11g/trace/dbec11g_ora_8666.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
SQL ID: g59vz2u4cu404
Plan Hash: 2937609675
select count(*)
from
emp
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=1 pr=0 pw=0 time=0 us)
14 INDEX FULL SCAN PK_EMP (cr=1 pr=0 pw=0 time=0 us cost=1 size=0 card=14)(object id 73202)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 6.18 6.18
********************************************************************************
SQL ID: 06nvwn223659v
Plan Hash: 0
alter session set events '10046 trace name context off'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Parsing user id: 84
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 1 0 1
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 10.29 16.47
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/diag/rdbms/dbec11g/dbec11g/trace/dbec11g_ora_8666.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
2 user SQL statements in trace file.
0 internal SQL statements in trace file.
2 SQL statements in trace file.
2 unique SQL statements in trace file.
50 lines in trace file.
6 elapsed seconds in trace file.
