运行SQLT出现Latch:cache Buffer Chains的一种解决办法

这两天在一台10.2.0.4的数据库上面运行SQLT的报告，运行的很缓慢，大概等了1个小时还没出来，查看了一下执行SQLT会话的等待事件，显示latch:cache buffer chains。这里要说下，当SQLT运行的过程中，屏幕会有输出显示。如下所示： To actually diagnose the p

这两天在一台10.2.0.4的数据库上面运行SQLT的报告，运行的很缓慢，大概等了1个小时还没出来，查看了一下执行SQLT会话的等待事件，显示latch:cache buffer chains。这里要说下，当SQLT运行的过程中，屏幕会有输出显示。如下所示：

To actually diagnose the problem behind the disconnect, read ALERT
log and provide referenced traces to Support. After the root cause
of the disconnect is fixed then reset SQLT corresponding parameter.

To monitor progress, login into another session and execute:
SQL> SELECT * FROM SQLTXADMIN.sqlt$_log_v;

… collecting diagnostics details, please wait …

In case of a disconnect review log file in current directory
If running as SYS in 12c make sure to review sqlt_instructions.html first

当时我们就一直卡在这个界面，出不来。这里告诉我们如果要监控SQLT进程，可以查询SELECT * FROM SQLTXADMIN.sqlt$_log_v。我们登陆了另外一个会话，做了如下查询，显示下面的结果。

TIME     LINE
-------- ------------------------------------------------------------------------------------------------------------------------
14:31:19 sqlt$h: -> index_hc_PK_PD_SVC_DICT
14:31:19 sqlt$h:  column_hc_PD_SVC_DICT_EFF_DATE
14:31:19 sqlt$h:  column_hc_PD_SVC_DICT_EXP_DATE
14:31:19 sqlt$h:  column_hc_PD_SVC_DICT_MASTER_SERV_ID
14:31:19 sqlt$h:  column_hc_PD_SVC_DICT_SVC_ID
14:31:19 sqlt$h:  column_hc_PD_SVC_DICT_SVC_TYPE
14:31:19 sqlt$h:  main_report
14:31:19 sqlt$m: -> flags
14:31:19 sqlt$m: 
<p><font face="幼圆" size="3">可以看到我们在做sqlt$m: init_parameters_sys的时候卡住了。但是看到了这个信息，我们也不知道它的意思。于是，我们只能考虑做下10046。</font> </p>

<pre class="brush:php;toolbar:false">PARSING IN CURSOR #44 len=632 dep=1 uid=416 oct=3 lid=416 tim=35075498358274 hv=4132104666 ad='121339a8' 
SELECT S.END_INTERVAL_TIME, P.SNAP_ID, P.ISDEFAULT, P.ISMODIFIED, P.PARAMETER_NAME, P.INSTANCE_NUMBER, P.VALUE FROM SQLI$_DBA_HIST_PARAMETER P, SQLT$_DBA_HIS 
T_SNAPSHOT S, (SELECT /*+ NO_MERGE */ DISTINCT SNAP_ID, DBID FROM SQLT$_DBA_HIST_SQLSTAT WHERE STATEMENT_ID = :B1 ) ST WHERE P.STATEMENT_ID = :B1 AND P.STATE 
MENT_ID = S.STATEMENT_ID AND P.SNAP_ID = S.SNAP_ID AND P.DBID = S.DBID AND P.INSTANCE_NUMBER = S.INSTANCE_NUMBER AND (P.ISDEFAULT = 'FALSE' OR P.ISMODIFIED  'FALSE') AND P.SNAP_ID = ST.SNAP_ID AND P.DBID = ST.DBID ORDER BY S.END_INTERVAL_TIME DESC, P.ISDEFAULT, P.ISMODIFIED DESC, P.PARAMETER_NAME, P.INSTANCE_NU 
MBER 
END OF STMT 
PARSE #44:c=0,e=383,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=35075498358266 
EXEC #44:c=0,e=226,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=35075498358724 
*** 2014-05-08 14:31:45.742 
WAIT #44: nam='db file sequential read' ela= 1088 file#=2001 block#=581279 blocks=1 obj#=535668 tim=35075519750997 
WAIT #44: nam='db file sequential read' ela= 783 file#=2001 block#=586373 blocks=1 obj#=535670 tim=35075520009144 
WAIT #44: nam='db file sequential read' ela= 740 file#=2001 block#=579127 blocks=1 obj#=535670 tim=35075521390313 
WAIT #44: nam='db file sequential read' ela= 1135 file#=2001 block#=579635 blocks=1 obj#=535670 tim=35075522675155 
WAIT #44: nam='db file sequential read' ela= 1105 file#=2001 block#=581144 blocks=1 obj#=535670 tim=35075528124956 
WAIT #44: nam='db file sequential read' ela= 824 file#=2001 block#=577465 blocks=1 obj#=535668 tim=35075528795240 
WAIT #44: nam='db file sequential read' ela= 706 file#=2001 block#=580952 blocks=1 obj#=535668 tim=35075528935134 
*** 2014-05-08 14:31:58.642 
WAIT #44: nam='db file sequential read' ela= 850 file#=2001 block#=575871 blocks=1 obj#=535670 tim=35075532348467 
*** 2014-05-08 14:36:51.985 
WAIT #44: nam='latch: cache buffers chains' ela= 177 address=66109355216 number=122 tries=0 obj#=535670 tim=35075818825412 
*** 2014-05-08 14:41:07.053 
WAIT #44: nam='latch: cache buffers chains' ela= 119 address=66263337712 number=122 tries=0 obj#=535670 tim=35076067923552 
*** 2014-05-08 14:43:21.686 
WAIT #44: nam='latch: cache buffers chains' ela= 15 address=66046764704 number=122 tries=0 obj#=535670 tim=35076199404865 
*** 2014-05-08 15:04:11.215 
WAIT #44: nam='latch: cache buffers chains' ela= 43 address=66336324888 number=122 tries=0 obj#=535670 tim=35077419687444 
*** 2014-05-08 15:06:45.573 
WAIT #44: nam='latch: cache buffers chains' ela= 63 address=65975608120 number=122 tries=0 obj#=535670 tim=35077570432584 
*** 2014-05-08 15:09:39.477 
WAIT #44: nam='latch: cache buffers chains' ela= 223 address=66292257024 number=122 tries=0 obj#=535670 tim=35077740265783 
*** 2014-05-08 15:12:25.390 
WAIT #44: nam='latch: cache buffers chains' ela= 253 address=66066629152 number=122 tries=0 obj#=535670 tim=35077902295960 
*** 2014-05-08 15:24:24.368 
Received ORADEBUG command 'event 10046 trace name context forever,level 12' from process Unix process pid: 6764, image: 
*** 2014-05-08 15:24:42.767 
Received ORADEBUG command 'event 10046 trace name context off' from process Unix process pid: 6764, image: 
Received ORADEBUG command 'tracefile_name' from process Unix process pid: 6764, image: 

可以看到10046的等待主要是集中在latch: cache buffers chains上的。看了下运行SQL的执行计划。

PLAN_TABLE_OUTPUT 
------------------------------------------------------------------------------------------------------------------------------------------------------ 
SQL_ID  f2u123bv4pufu, child number 0 
------------------------------------- 
SELECT S.END_INTERVAL_TIME, P.SNAP_ID, P.ISDEFAULT, P.ISMODIFIED, P.PARAMETER_NAME, P.INSTANCE_NUMBER, 
P.VALUE FROM SQLI$_DBA_HIST_PARAMETER P, SQLT$_DBA_HIST_SNAPSHOT S, (SELECT /*+ NO_MERGE */ DISTINCT 
SNAP_ID, DBID FROM SQLT$_DBA_HIST_SQLSTAT WHERE STATEMENT_ID = :B1 ) ST WHERE P.STATEMENT_ID = :B1 AND 
P.STATEMENT_ID = S.STATEMENT_ID AND P.SNAP_ID = S.SNAP_ID AND P.DBID = S.DBID AND P.INSTANCE_NUMBER = 
S.INSTANCE_NUMBER AND (P.ISDEFAULT = 'FALSE' OR P.ISMODIFIED  'FALSE') AND P.SNAP_ID = ST.SNAP_ID AND 
P.DBID = ST.DBID ORDER BY S.END_INTERVAL_TIME DESC, P.ISDEFAULT, P.ISMODIFIED DESC, P.PARAMETER_NAME, 
P.INSTANCE_NUMBER 
Plan hash value: 1007730285 
---------------------------------------------------------------------------------------------------------------- 
| Id  | Operation                        | Name                        | Rows  | Bytes | Cost (%CPU)| Time     | 
---------------------------------------------------------------------------------------------------------------- 
|   0 | SELECT STATEMENT                 |                             |       |       |    64 (100)|          | 
|   1 |  SORT ORDER BY                   |                             |    81 | 60426 |    64   (5)| 00:00:01 | 
|*  2 |   HASH JOIN                      |                             |    81 | 60426 |    63   (4)| 00:00:01 | 
|*  3 |    TABLE ACCESS FULL             | SQLT$_DBA_HIST_SNAPSHOT     |  2172 |   137K|     9   (0)| 00:00:01 | 
|   4 |    NESTED LOOPS                  |                             |   303 |   201K|    53   (2)| 00:00:01 | 
|   5 |     VIEW                         |                             |    23 |   598 |     7  (15)| 00:00:01 | 
|   6 |      HASH UNIQUE                 |                             |    23 |   897 |     7  (15)| 00:00:01 | 
|   7 |       TABLE ACCESS BY INDEX ROWID| SQLT$_DBA_HIST_SQLSTAT      |    23 |   897 |     6   (0)| 00:00:01 | 
|*  8 |        INDEX RANGE SCAN          | SQLT$_DBA_HIST_SQLSTAT_N1   |     9 |       |     2   (0)| 00:00:01 | 
|*  9 |     TABLE ACCESS BY INDEX ROWID  | SQLI$_DBA_HIST_PARAMETER    |    13 |  8515 |     2   (0)| 00:00:01 | 
|* 10 |      INDEX RANGE SCAN            | SQLI$_DBA_HIST_PARAMETER_N1 |   202 |       |     1   (0)| 00:00:01 | 
---------------------------------------------------------------------------------------------------------------- 
Predicate Information (identified by operation id): 
--------------------------------------------------- 
   2 - access("P"."STATEMENT_ID"="S"."STATEMENT_ID" AND "P"."SNAP_ID"="S"."SNAP_ID" AND 
              "P"."DBID"="S"."DBID" AND "P"."INSTANCE_NUMBER"="S"."INSTANCE_NUMBER") 
   3 - filter("S"."STATEMENT_ID"=:B1) 
   8 - access("STATEMENT_ID"=:B1) 
   9 - filter((("P"."ISMODIFIED"'FALSE' OR "P"."ISDEFAULT"='FALSE') AND "P"."SNAP_ID"="ST"."SNAP_ID")) 
  10 - access("P"."STATEMENT_ID"=:B1 AND "P"."DBID"="ST"."DBID") 
Note 
----- 
   - dynamic sampling used for this statement

按道理来说这个语句应该运行很快才对，怎么会出这种问题了，看到是动态采样的。于是我就想收集了一下这几个表的统计信息。发现统计信息居然还是锁住的。于是强行解锁把这几个表的统计信息收集了。

SQL> exec dbms_stats.UNLOCK_TABLE_STATS(ownname=>'SQLTXPLAIN',TABNAME=>'SQLI$_DBA_HIST_PARAMETER'); 
PL/SQL procedure successfully completed. 
SQL> exec dbms_stats.GATHER_TABLE_STATS(ownname=>'SQLTXPLAIN',TABNAME=>'SQLI$_DBA_HIST_PARAMETER'); 
PL/SQL procedure successfully completed.
SQL> exec dbms_stats.UNLOCK_TABLE_STATS(ownname=>'SQLTXPLAIN',TABNAME=>'SQLT$_DBA_HIST_SQLSTAT'); 
PL/SQL procedure successfully completed. 
SQL>  exec dbms_stats.GATHER_TABLE_STATS(ownname=>'SQLTXPLAIN',TABNAME=>'SQLT$_DBA_HIST_SQLSTAT'); 
PL/SQL procedure successfully completed. 
SQL> exec dbms_stats.UNLOCK_TABLE_STATS(ownname=>'SQLTXPLAIN',TABNAME=>'SQLT$_DBA_HIST_SNAPSHOT'); 
PL/SQL procedure successfully completed. 
SQL> exec dbms_stats.GATHER_TABLE_STATS(ownname=>'SQLTXPLAIN',TABNAME=>'SQLT$_DBA_HIST_SNAPSHOT'); 
PL/SQL procedure successfully completed.

收集完了再次运行，SQLT的结果集就出来了。然后查看了一下新的执行计划。发现确实有改变。SQLT$_DBA_HIST_SQLSTAT从索引范围扫描变成了全表扫描。执行计划由nested loop变成了hash join。

PLAN_TABLE_OUTPUT 
------------------------------------------------------------------------------------------------------------------------------------------------------ 
SQL_ID  f2u123bv4pufu, child number 0 
------------------------------------- 
SELECT S.END_INTERVAL_TIME, P.SNAP_ID, P.ISDEFAULT, P.ISMODIFIED, P.PARAMETER_NAME, 
P.INSTANCE_NUMBER, P.VALUE FROM SQLI$_DBA_HIST_PARAMETER P, SQLT$_DBA_HIST_SNAPSHOT S, (SELECT /*+ 
NO_MERGE */ DISTINCT SNAP_ID, DBID FROM SQLT$_DBA_HIST_SQLSTAT WHERE STATEMENT_ID = :B1 ) ST WHERE 
P.STATEMENT_ID = :B1 AND P.STATEMENT_ID = S.STATEMENT_ID AND P.SNAP_ID = S.SNAP_ID AND P.DBID = 
S.DBID AND P.INSTANCE_NUMBER = S.INSTANCE_NUMBER AND (P.ISDEFAULT = 'FALSE' OR P.ISMODIFIED  
'FALSE') AND P.SNAP_ID = ST.SNAP_ID AND P.DBID = ST.DBID ORDER BY S.END_INTERVAL_TIME DESC, 
P.ISDEFAULT, P.ISMODIFIED DESC, P.PARAMETER_NAME, P.INSTANCE_NUMBER 
Plan hash value: 72767641 
-------------------------------------------------------------------------------------------------------------- 
| Id  | Operation                      | Name                        | Rows  | Bytes | Cost (%CPU)| Time     | 
-------------------------------------------------------------------------------------------------------------- 
|   0 | SELECT STATEMENT               |                             |       |       |    72 (100)|          | 
|   1 |  SORT ORDER BY                 |                             |     1 |   698 |    72   (5)| 00:00:01 | 
|*  2 |   HASH JOIN                    |                             |     1 |   698 |    71   (3)| 00:00:01 | 
|*  3 |    HASH JOIN                   |                             |     1 |   667 |    57   (4)| 00:00:01 | 
|*  4 |     TABLE ACCESS BY INDEX ROWID| SQLI$_DBA_HIST_PARAMETER    |     1 |   655 |     0   (0)|          | 
|*  5 |      INDEX RANGE SCAN          | SQLI$_DBA_HIST_PARAMETER_N1 |     1 |       |     0   (0)|          | 
|   6 |     VIEW                       |                             |   707 |  8484 |    56   (2)| 00:00:01 | 
|   7 |      HASH UNIQUE               |                             |   707 | 12019 |    56   (2)| 00:00:01 | 
|*  8 |       TABLE ACCESS FULL        | SQLT$_DBA_HIST_SQLSTAT      |  2078 | 35326 |    55   (0)| 00:00:01 | 
|*  9 |    TABLE ACCESS FULL           | SQLT$_DBA_HIST_SNAPSHOT     |  2174 | 67394 |    14   (0)| 00:00:01 | 
-------------------------------------------------------------------------------------------------------------- 
Predicate Information (identified by operation id): 
--------------------------------------------------- 
   2 - access("P"."STATEMENT_ID"="S"."STATEMENT_ID" AND "P"."SNAP_ID"="S"."SNAP_ID" AND 
              "P"."DBID"="S"."DBID" AND "P"."INSTANCE_NUMBER"="S"."INSTANCE_NUMBER") 
   3 - access("P"."SNAP_ID"="ST"."SNAP_ID" AND "P"."DBID"="ST"."DBID") 
   4 - filter(("P"."ISMODIFIED"'FALSE' OR "P"."ISDEFAULT"='FALSE')) 
   5 - access("P"."STATEMENT_ID"=:B1) 
   8 - filter("STATEMENT_ID"=:B1) 
   9 - filter("S"."STATEMENT_ID"=:B1)

原文地址：运行SQLT出现Latch:cache Buffer Chains的一种解决办法, 感谢原作者分享。