TRUNCATE语句时间过长的诊断
转自：http://yangtingkun.itpub.net/post/468/501762
在ITPUB上看到有人提问，为什么TRUNCATE语句要比DELETE慢，由于默认TRUNCATE要回收空间，且会将所有的脏块写回到数据文件，因此其实对于小数据量而言，TRUNCATE比DELETE慢也是正常的。不过这个例子中，TRUNCATE慢的有点离谱了。
[@more@]这是根据问题模拟的例子，表中只有5条记录，可以看到，TRUNCATE操作要比DELETE慢得多：
SQL> SET TIMING ON
SQL> DELETE T_BIG;
4 rows deleted.
Elapsed: 00:00:00.01
SQL> TRUNCATE TABLE T_BIG;
Table truncated.
Elapsed: 00:00:03.25
对于表中数据量不大的情况，TRUNCATE比DELETE慢一点是正常的，但是二者一般是同一个数量级的：
SQL> CREATE TABLE T_TRUNCATE (ID NUMBER);
Table created.
Elapsed: 00:00:00.06
SQL> INSERT INTO T_TRUNCATE VALUES (1);
1 row created.
Elapsed: 00:00:00.00
SQL> DELETE T_TRUNCATE;
1 row deleted.
Elapsed: 00:00:00.03
SQL> TRUNCATE TABLE T_TRUNCATE;
Table truncated.
Elapsed: 00:00:00.10
现在这个差别有点过大了，肯定不是简单的数据量较小就可以解释得通了。
这个问题的描述者除了给出TRUNCATE语句和DELETE语句的时间对比外，还对TRUNCATE语句设置了10046事件进行TRACE：
SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
Session altered.
Elapsed: 00:00:00.04
SQL> TRUNCATE TABLE T_BIG;
Table truncated.
Elapsed: 00:00:01.52
SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
Session altered.
Elapsed: 00:00:00.00
第二次运行TRUNCATE，虽然时间比第一次运行要短1/3，但是仍然要花费将近2秒的时间。
问题描述者通过TKPROF对得到的TRACE文件进行了格式化，并将格式化后的文件发到了论坛上，其中格式化后的结果类似于：
[oracle@yans1 udump]$ more trace_result.txt
TKPROF: Release 10.2.0.3.0 - Production on 星期四 7月 1 15:07:05 2010
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: test08_ora_20627.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
TRUNCATE TABLE T_BIG
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.36 1.47 4453 365 9211 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.37 1.48 4453 365 9211 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 74
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 4452 0.00 0.06
reliable message 5 0.00 0.00
enq: RO - fast object reuse 11 0.03 0.22
local write wait 2229 0.00 0.67
log file sync 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 10.76 10.76
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.36 1.47 4453 365 9211 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.37 1.48 4453 365 9211 0
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 2 0.00 0.00
SQL*Net message from client 2 10.76 16.52
db file sequential read 4452 0.00 0.06
reliable message 5 0.00 0.00
enq: RO - fast object reuse 11 0.03 0.22
local write wait 2229 0.00 0.67
log file sync 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 63 0.01 0.10 0 0 0 0
Execute 80 0.04 0.14 0 110 39 28
Fetch 36 0.00 0.02 1 246 0 29
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 179 0.06 0.27 1 356 39 57
Misses in library cache during parse: 20
Misses in library cache during execute: 20
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.01 0.01
10 user SQL statements in session.
70 internal SQL statements in session.
80 SQL statements in session.
Trace file: test08_ora_20627.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
10 user SQL statements in trace file.
70 internal SQL statements in trace file.
80 SQL statements in trace file.
28 unique SQL statements in trace file.
10848 lines in trace file.
12 elapsed seconds in trace file.
根据格式化后的TRACE信息可以判断：
Oracle的递归SQL的运行时间只占了很小的比重，绝大部分时间都是消耗在TRUNCATE语句上。
TRUNCATE语句居然产生了4000多的物理读和9000多的逻辑读，而表本身一共也没有那么多的BLOCK存在，即使表本身比较大，在第一次TRUNCATE之后，高水位线已经被收缩，现在表本身应该已经很小才对。
而TRUNCATE语句的主要等待事件是db file sequential read和local write wait，这两个等待时间一般和索引有关，而和表似乎关系不大。
仅根据现有的信息无法判断具体的原因，因此要求问题的描述者提供进一步的信息，包含表结构的DBMS_METADATA输出结果以及原始的TRACE文件。
其中DBMS_METADATA.GET_DDL的输出类似如下：
SQL> SET LONG 10000
SQL> SELECT DBMS_METADATA.GET_DDL('TABLE', 'T_BIG') FROM DUAL;
DBMS_METADATA.GET_DDL('TABLE','T_BIG')
--------------------------------------------------------------------------------
CREATE TABLE "TEST"."T_BIG"
( "OWNER" VARCHAR2(30),
"OBJECT_NAME" VARCHAR2(128),
"SUBOBJECT_NAME" VARCHAR2(30),
"OBJECT_ID" NUMBER,
"DATA_OBJECT_ID" NUMBER,
"OBJECT_TYPE" VARCHAR2(19),
"CREATED" DATE,
"LAST_DDL_TIME" DATE,
"TIMESTAMP" VARCHAR2(19),
"STATUS" VARCHAR2(7),
"TEMPORARY" VARCHAR2(1),
"GENERATED" VARCHAR2(1),
"SECONDARY" VARCHAR2(1),
PRIMARY KEY ("OBJECT_ID")
USING INDEX PCTFREE 10 INITRANS 2 MAXTRANS 255 COMPUTE STATISTICS
STORAGE(INITIAL 1073741824 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "GPO" ENABLE
) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 NOCOMPRESS LOGGING
STORAGE(INITIAL 973078528 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "GPO"
其中表和主键索引的初始化EXTENT的大小比较奇怪，既然表中记录很少，为什么表和主键的初始化INITIAL EXTENT会那么大。
进一步分析详细TRACE信息：
[oracle@yans1 udump]$ more test08_ora_20627.trc
/opt/ora10g/admin/test08/udump/test08_ora_20627.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, OLAP and Data Mining options
ORACLE_HOME = /opt/ora10g/product/10.2.0/db_1
System name: Linux
Node name: yans1
Release: 2.6.9-42.0.0.0.1.ELsmp
Version: #1 SMP Sun Oct 15 15:13:57 PDT 2006
Machine: x86_64
Instance name: test08
Redo thread mounted by this instance: 1
Oracle process number: 16
Unix process pid: 20627, image: oracle@yans1 (TNS V1-V3)
*** 2010-07-01 15:03:54.687
*** ACTION NAME:() 2010-07-01 15:03:54.673
*** MODULE NAME:(SQL*Plus) 2010-07-01 15:03:54.673
*** SERVICE NAME:(SYS$USERS) 2010-07-01 15:03:54.673
*** SESSION ID:(317.11354) 2010-07-01 15:03:54.673
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=147960 tim=1248015463547954
WAIT #3: nam='SQL*Net message from client' ela= 5759303 driver id=1650815232 #bytes=1 p3=0 obj#=147960 tim=1248015469321192
XCTEND rlbk=0, rd_only=1
=====================
PARSING IN CURSOR #10 len=20 dep=0 uid=74 oct=85 lid=74 tim=1248015469332441 hv=3136993528 ad='ff547c80'
TRUNCATE TABLE T_BIG
END OF STMT
PARSE #10:c=1000,e=9511,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1248015469330783
BINDS #10:
=====================
EXEC #5:c=2000,e=2298,p=0,cr=2,cu=2,mis=1,r=1,dep=1,og=4,tim=1248015469436750
STAT #5 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE OBJ$ (cr=2 pr=0 pw=0 time=264 us)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=37 op='INDEX RANGE SCAN I_OBJ2 (cr=2 pr=0 pw=0 time=21 us)'
WAIT #10: nam='db file sequential read' ela= 31 file#=51 block#=57365 blocks=1 obj#=147967 tim=1248015469436975
WAIT #10: nam='db file sequential read' ela= 14 file#=51 block#=57349 blocks=1 obj#=147967 tim=1248015469437058
WAIT #10: nam='db file sequential read' ela= 13 file#=51 block#=57350 blocks=1 obj#=147967 tim=1248015469437130
WAIT #10: nam='db file sequential read' ela= 13 file#=51 block#=57351 blocks=1 obj#=147967 tim=1248015469437182
WAIT #10: nam='db file sequential read' ela= 13 file#=51 block#=57352 blocks=1 obj#=147967 tim=1248015469437235
WAIT #10: nam='local write wait' ela= 466 file#=51 block#=57366 p3=0 obj#=147967 tim=1248015469563931
WAIT #10: nam='db file sequential read' ela= 21 file#=51 block#=57367 blocks=1 obj#=147967 tim=1248015469563995
WAIT #10: nam='local write wait' ela= 528 file#=51 block#=57367 p3=0 obj#=147967 tim=1248015469564616
WAIT #10: nam='db file sequential read' ela= 21 file#=51 block#=36885 blocks=1 obj#=147966 tim=1248015469564736
WAIT #10: nam='db file sequential read' ela= 18 file#=51 block#=36869 blocks=1 obj#=147966 tim=1248015469564800
WAIT #10: nam='db file sequential read' ela= 18 file#=51 block#=36870 blocks=1 obj#=147966 tim=1248015469564879
WAIT #10: nam='db file sequential read' ela= 20 file#=51 block#=36871 blocks=1 obj#=147966 tim=1248015469564939
WAIT #10: nam='db file sequential read' ela= 9 file#=51 block#=53256 blocks=1 obj#=147966 tim=1248015469688631
WAIT #10: nam='local write wait' ela= 249 file#=51 block#=53256 p3=0 obj#=147966 tim=1248015469688916
WAIT #10: nam='local write wait' ela= 263 file#=51 block#=36885 p3=0 obj#=147966 tim=1248015469689220
WAIT #10: nam='local write wait' ela= 259 file#=51 block#=36886 p3=0 obj#=147966 tim=1248015469689513
WAIT #10: nam='db file sequential read' ela= 11 file#=51 block#=36887 blocks=1 obj#=147966 tim=1248015469689562
WAIT #10: nam='local write wait' ela= 499 file#=51 block#=36887 p3=0 obj#
来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/14663377/viewspace-1035113/，如需转载，请注明出处，否则将追究法律责任。
转载于:http://blog.itpub.net/14663377/viewspace-1035113/
扫一扫
233
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
