细说tkprof的使用方法
程序员文章站
2022-04-13 21:17:00
...
熟悉oracle的同学，对tkprof应该不会陌生。今天用到tkprof，有些语法变得模糊起来。查看文档，重新梳理有关tkprof的有关知识，加深记忆。 通过tkfprof可以非常方便的跟踪诊断sql语句的执行效率。结合explain plan的使用，更是如虎添翼。 sql trace为我们查看
熟悉oracle的同学，对tkprof应该不会陌生。今天用到tkprof，有些语法变得模糊起来。查看文档，重新梳理有关tkprof的有关知识，加深记忆。
通过tkfprof可以非常方便的跟踪诊断sql语句的执行效率。结合explain plan的使用，更是如虎添翼。
sql trace为我们查看某天sql 语句的性能信息提供了可能，通常sqltrace可以生成下面的统计信息：
Parse, execute, and fetch counts 解析 执行和抓取的动作数量CPU and elapsed times 花费在cpu和整个操作上的时间Physical reads and logical reads 物理读和逻辑读Number of rows processed 处理的记录数量Misses on the library cache 库缓存的丢失率Username under which each parse occurred 执行用户Each commit and rollback 每次的提交和回滚操作 （tkprofl不会处理这些信息）Wait event data for each SQL statement, and a summary for each trace file 针对每条sql语句和所有的sql语句生成事件信息数据除此之外，如果在sql trace期间，跟踪的语句游标已经关闭，sql trace还会提供如下的行源信息 Row operations showing the actual execution plan of each SQL statementNumber of rows, number of consistent reads, number of physical reads, number of physical writes, and time elapsed for each operation on a row 语法格式：
[oracle@oadata trace]$ tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
table=schema.tablename Use 'schema.tablename' with 'explain=' option. --手动生成explain plan时，存储中间信息的临时表，默认为PROF$PLAN_TABLE
explain=user/password Connect to ORACLE and issue EXPLAIN PLAN. --手动生成explain时，连接数据库的用户名和密码
print=integer List only the first 'integer' SQL statements.--仅仅处理前integer数量的sql语句，如果我们需要生成脚本，该参数对脚本中包含的sql数量是不影响的
aggregate=yes|no
insert=filename List SQL statements and data inside INSERT statements.--生成脚本，该脚本会创建表，并把相关统计信息插入表，从而可以在数据库中查看
sys=no TKPROF does not list SQL statements run as user SYS. --是否包含sys用户生成的信息，如递归sql
record=filename Record non-recursive statements found in the trace file. --生成脚本，脚本包含跟踪文件中的非递归sql语句
waits=yes|no Record summary for any wait events found in the trace file.--记录等待事件信息
sort=option Set of zero or more of the following sort options: --对语句进行排序
prscnt number of times parse was called
prscpu cpu time parsing
prsela elapsed time parsing
prsdsk number of disk reads during parse
prsqry number of buffers for consistent read during parse
prscu number of buffers for current read during parse
prsmis number of misses in library cache during parse
execnt number of execute was called
execpu cpu time spent executing
exeela elapsed time executing
exedsk number of disk reads during execute
exeqry number of buffers for consistent read during execute
execu number of buffers for current read during execute
exerow number of rows processed during execute
exemis number of library cache misses during execute
fchcnt number of times fetch was called
fchcpu cpu time spent fetching
fchela elapsed time fetching
fchdsk number of disk reads during fetch
fchqry number of buffers for consistent read during fetch
fchcu number of buffers for current read during fetch
fchrow number of rows fetched
userid userid of user that parsed the cursor
sql trace与执行计划： 如果在sqltrace期间，sql语句的游标已经关闭，sqltrace中会包含执行计划的相关信息
SQL> show user
USER 为 "SCOTT"
SQL> explain plan for select object_id,object_name,object_type from tab1 where object_id = 1000;
已解释。
SQL> select * from table(dbms_xplan.display());
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 2086140937
------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 41 | 1 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| TAB1 | 1 | 41 | 1 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IND1 | 1 | | 1 (0)| 00:00:01 |
------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
---------------------------------------------------
2 - access("OBJECT_ID"=1000)
Note
-----
- dynamic sampling used for this statement (level=2)
已选择18行。
SQL> alter session set sql_trace=true;
会话已更改。
SQL> alter session set tracefile_identifier='test1';
会话已更改。
SQL> select object_id,object_name,object_type from tab1 where object_id = 1000;
未选定行
跟踪文件：
******************************************************************************** SQL ID: 25kr54b04dq4v Plan Hash: 2086140937 select object_id,object_name,object_type from tab1 where object_id = 1000 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 2 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 0.00 0.00 0 2 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 0.00 0.00 0 4 0 0 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 83 Number of plan statistics captured: 1 --Rows (1st) Rows (avg) Rows (max) Row Source Operation ------------ ---------- ---------- --------------------------------------------------- -- 0 0 0 TABLE ACCESS BY INDEX ROWID TAB1 (cr=2 pr=0 pw=0 time=20 us cost=1 size=41 card=1) -- 0 0 0 INDEX RANGE SCAN IND1 (cr=2 pr=0 pw=0 time=16 us cost=1 size=0 card=1)(object id 101626) ********************************************************************************
如果游标没有关闭，则跟踪文件中不会包含该游标的执行计划信息。
SQL> Declare --Cursor C Is Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 1111; Object_Id Number; Object_Name Varchar2(30); Object_Type Varchar2(19); Begin Open C; Fetch C Into Object_Id,Object_Name,Object_Type; Dbms_Lock.Sleep(1000); Close C; 11 End;
******************************************************************************** SQL ID: dxz49cn75rxtz Plan Hash: 2086140937 SELECT OBJECT_ID,OBJECT_NAME,OBJECT_TYPE FROM TAB1 WHERE OBJECT_ID = 1111 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 2 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 0.00 0.00 0 3 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 0.00 0.00 0 5 0 1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 83 (recursive depth: 1) ********************************************************************************
如果之前sql语句已经执行过，则会包含执行计划
Declare --Cursor C Is Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 1000; Object_Id Number; Object_Name Varchar2(30); Object_Type Varchar2(19); Begin Open C; Fetch C Into Object_Id,Object_Name,Object_Type; Dbms_Lock.Sleep(1000); Close C; 11 End; 12 /
********************************************************************************
SQL ID: 9guk3zj6busz4 Plan Hash: 2086140937
SELECT OBJECT_ID,OBJECT_NAME,OBJECT_TYPE
FROM
TAB1 WHERE OBJECT_ID = 1000
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 2 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 4 0 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 TABLE ACCESS BY INDEX ROWID TAB1 (cr=2 pr=0 pw=0 time=19 us cost=1 size=41 card=1)
0 0 0 INDEX RANGE SCAN IND1 (cr=2 pr=0 pw=0 time=16 us cost=1 size=0 card=1)(object id 101626)
********************************************************************************
如果在跟踪文件中，不存在执行计划的相关信息，是否有其他的方法来生成执行计划那？当然有，利用explain参数选项就可以达到这个目的，测试tkprof会议explain指定的用户登录数据库，执行explain plan相关的语句来生成执行计划，并写入到跟踪文件：
SQL> Declare Cursor C Is Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000; Object_Id Number; Object_Name Varchar2(30); Object_Type Varchar2(19); Begin Open C; Fetch C Into Object_Id,Object_Name,Object_Type; Dbms_Lock.Sleep(1000); Close C; 11 End; 12 /
********************************************************************************
SQL ID: 9k9wj84nxpm6t Plan Hash: 2086140937
SELECT OBJECT_ID,OBJECT_NAME,OBJECT_TYPE
FROM
TAB1 WHERE OBJECT_ID = 2000
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 2 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 5 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 TABLE ACCESS (BY INDEX ROWID) OF 'TAB1' (TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'IND1' (INDEX)
********************************************************************************
tkprof会累计相同的sql语句信息，并在文件的最后累计所有语句的相关信息：
SQL> Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000;
OBJECT_ID OBJECT_NAME OBJECT_TYPE
---------- ------------------------------ -------------------
2000 V_$SQLSTATS_PLAN_HASH VIEW
SQL> Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000;
OBJECT_ID OBJECT_NAME OBJECT_TYPE
---------- ------------------------------ -------------------
2000 V_$SQLSTATS_PLAN_HASH VIEW
跟踪文件内容：
PARSING IN CURSOR #47244034021040 len=73 dep=0 uid=83 oct=3 lid=83 tim=1388022158115297 hv=2221247730 ad='c9810e20' sqlid='88tvucq26b37k' Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000 END OF STMT PARSE #47244034021040:c=3999,e=4256,p=0,cr=73,cu=0,mis=1,r=0,dep=0,og=1,plh=2086140937,tim=1388022158115296 EXEC #47244034021040:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022158115394 FETCH #47244034021040:c=0,e=41,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2086140937,tim=1388022158115541 FETCH #47244034021040:c=0,e=11,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022158115877 STAT #47244034021040 id=1 cnt=1 pid=0 pos=1 obj=101625 op='TABLE ACCESS BY INDEX ROWID TAB1 (cr=4 pr=0 pw=0 time=34 us cost=2 size=41 card=1)' STAT #47244034021040 id=2 cnt=1 pid=1 pos=1 obj=101626 op='INDEX RANGE SCAN IND1 (cr=3 pr=0 pw=0 time=28 us cost=1 size=0 card=1)' *** 2013-12-26 09:42:39.915 CLOSE #47244034021040:c=0,e=16,dep=0,type=0,tim=1388022159915788 ===================== PARSING IN CURSOR #47244034021040 len=73 dep=0 uid=83 oct=3 lid=83 tim=1388022159916048 hv=2221247730 ad='c9810e20' sqlid='88tvucq26b37k' Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000 END OF STMT PARSE #47244034021040:c=0,e=113,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022159916046 EXEC #47244034021040:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022159916171 FETCH #47244034021040:c=0,e=65,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2086140937,tim=1388022159916330 FETCH #47244034021040:c=0,e=139,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022159916721 STAT #47244034021040 id=1 cnt=1 pid=0 pos=1 obj=101625 op='TABLE ACCESS BY INDEX ROWID TAB1 (cr=4 pr=0 pw=0 time=65 us cost=2 size=41 card=1)' STAT #47244034021040 id=2 cnt=1 pid=1 pos=1 obj=101626 op='INDEX RANGE SCAN IND1 (cr=3 pr=0 pw=0 time=186 us cost=1 size=0 card=1)'
tkprof格式化跟踪文件后的内容：
SQL ID: 88tvucq26b37k Plan Hash: 2086140937
Select Object_Id,Object_Name,Object_Type
From
Tab1 Where Object_Id = 2000
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 73 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.00 0 8 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.00 0.00 0 81 0 2
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS BY INDEX ROWID TAB1 (cr=4 pr=0 pw=0 time=50 us cost=2 size=41 card=1)
1 1 1 INDEX RANGE SCAN IND1 (cr=3 pr=0 pw=0 time=107 us cost=1 size=0 card=1)(object id 101626)
insert和records使用示例： sqlplus中执行的脚本
SQL> select user from dual;
USER
------------------------------
SCOTT
SQL> select object_id ,object_name from tab1 where object_id select count(*) from tab1;
COUNT(*)
----------
73124
tkprof处理跟踪文件：
[oracle@oadata trace]$ tkprof *_test1.trc test1.txt insert=insert.sql record=record.sql
TKPROF: Release 11.2.0.3.0 - Development on 星期四 12月 26 10:10:06 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
[oracle@oadata trace]$ cat insert.sql
REM Edit and/or remove the following CREATE TABLE
REM statement as your needs dictate.
CREATE TABLE tkprof_table
(
date_of_insert DATE
,cursor_num NUMBER
,depth NUMBER
,user_id NUMBER
,parse_cnt NUMBER
,parse_cpu NUMBER
,parse_elap NUMBER
,parse_disk NUMBER
,parse_query NUMBER
,parse_current NUMBER
,parse_miss NUMBER
,exe_count NUMBER
,exe_cpu NUMBER
,exe_elap NUMBER
,exe_disk NUMBER
,exe_query NUMBER
,exe_current NUMBER
,exe_miss NUMBER
,exe_rows NUMBER
,fetch_count NUMBER
,fetch_cpu NUMBER
,fetch_elap NUMBER
,fetch_disk NUMBER
,fetch_query NUMBER
,fetch_current NUMBER
,fetch_rows NUMBER
,ticks NUMBER
,sql_statement LONG
);
set sqlterminator off
INSERT INTO tkprof_table VALUES
(
SYSDATE, 1, 0, 83, 1, 1000, 1321, 0, 0, 0, 1
, 1, 0, 40, 140733193388032, 0, 206158430208, 140733193388032, 140733193388032
, 2, 0, 20, 0, 0, 0, 1, 625
, 'select user from dual
')
/
INSERT INTO tkprof_table VALUES
(
SYSDATE, 2, 1, 83, 1, 0, 658, 0, 0, 0, 1
, 1, 2000, 1288, 140733193388032, 0, 0, 1, 0
, 1, 1000, 1824, 0, 69, 0, 1, 18354695
, 'SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param(''parallel_execution_enabled'', ''false'') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("TAB1") FULL("TAB1") NO_PARALLEL_INDEX("TAB1") */ :"SYS_B_2" AS C1, CASE WHEN "TAB1"."OBJECT_ID"<: then : else end as c2 from sample block seed samplesub insert into tkprof_table values sysdate opt_dyn_samp all_rows opt_param no_parallel no_parallel_index no_sql_tune nvl index ind1 c1 c3 where and rownum object_id tab1 ignore_where_clause full count set sqlterminator on trace cat record.sql select user dual>
使用tkprof和sql trace需要知识和经验的结合，现摘录官方文档中的部分内容，对你我或许有一定的启示作用：
Avoiding the Argument Trap
If you are not aware of the values being bound at run time, then it is possible to fall into the argument trap. EXPLAIN PLAN cannot determine the type of a bind variable from the text of SQL statements, and it always assumes that the type is varchar. If the bind variable is actually a number or a date, then TKPROF can cause implicit data conversions, which can cause inefficient plans to be executed. To avoid this situation, experiment with different data types in the query.
To avoid this problem, perform the conversion yourself.
Avoiding the Read Consistency Trap
The next example illustrates the read consistency trap. Without knowing that an uncommitted transaction had made a series of updates to the NAME column, it is very difficult to see why so many block visits would be incurred.
Cases like this are not normally repeatable: if the process were run again, it is unlikely that another transaction would interact with it in the same way.
SELECT name_id
FROM cq_names
WHERE name = 'FLOOR';
call count cpu elapsed disk query current rows
---- ----- --- ------- ---- ----- ------- ----
Parse 1 0.10 0.18 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.11 0.21 2 101 0 1
Misses in library cache during parse: 1
Parsing user id: 01 (USER1)
Rows Execution Plan
---- --------- ----
0 SELECT STATEMENT
1 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
2 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON_UNIQUE)
Avoiding the Schema Trap
This example shows an extreme (and thus easily detected) example of the schema trap. At first, it is difficult to see why such an apparently straightforward indexed query needs to look at so many database blocks, or why it should access any blocks at all in current mode.
SELECT name_id
FROM cq_names
WHERE name = 'FLOOR';
call count cpu elapsed disk query current rows
-------- ------- -------- --------- ------- ------ ------- ----
Parse 1 0.06 0.10 0 0 0 0
Execute 1 0.02 0.02 0 0 0 0
Fetch 1 0.23 0.30 31 31 3 1
Misses in library cache during parse: 0
Parsing user id: 02 (USER2)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT
2340 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
0 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON-UNIQUE)
Two statistics suggest that the query might have been executed with a full table scan. These statistics are the current mode block visits, plus the number of rows originating from the Table Access row source in the execution plan. The explanation is that the required index was built after the trace file had been produced, but before TKPROF had been run.
Generating a new trace file gives the following data:
SELECT name_id
FROM cq_names
WHERE name = 'FLOOR';
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 1 0.00 0.00 0 2 0 1
Misses in library cache during parse: 0
Parsing user id: 02 (USER2)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT
1 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
2 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON-UNIQUE)
One of the marked features of this correct version is that the parse call took 10 milliseconds of CPU time and 20 milliseconds of elapsed time, but the query apparently took no time at all to execute and perform the fetch. These anomalies arise because the clock tick of 10 milliseconds is too long relative to the time taken to execute and fetch the data. In such cases, it is important to get lots of executions of the statements, so that you have statistically valid numbers.
Avoiding the Time Trap
Sometimes, as in the following example, you might wonder why a particular query has taken so long.
UPDATE cq_names SET ATTRIBUTES = lower(ATTRIBUTES)
WHERE ATTRIBUTES = :att
call count cpu elapsed disk query current rows
-------- ------- -------- --------- -------- -------- ------- ----------
Parse 1 0.06 0.24 0 0 0 0
Execute 1 0.62 19.62 22 526 12 7
Fetch 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 1
Parsing user id: 02 (USER2)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT
2519 TABLE ACCESS (FULL) OF 'CQ_NAMES'
Again, the answer is interference from another transaction. In this case, another transaction held a shared lock on the table cq_names for several seconds before and after the update was issued. It takes a fair amount of experience to diagnose that interference effects are occurring. On the one hand, comparative data is essential when the interference is contributing only a short delay (or a small increase in block visits in the previous example). However, if the interference contributes only modest overhead, and if the statement is essentially efficient, then its statistics may not require analysis.
上一篇： 推荐个好东西swoole，php如虎添翼
下一篇： PHP实现守护进程的启动和终止操作