时间：2021-07-01 10:21:17 帮助过：31人阅读
这两天在一台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: <- 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_EFF_DATE 14:31:19 sqlt$h: -> column_hc_PD_SVC_DICT_EXP_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_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_ID 14:31:19 sqlt$h: -> column_hc_PD_SVC_DICT_SVC_TYPE 14:31:19 sqlt$h: <- column_hc_PD_SVC_DICT_SVC_TYPE 14:31:19 sqlt$h: <= health_check 14:31:19 sqlt$m: => main_report 14:31:19 sqlt$m: -> flags 14:31:19 sqlt$m: <- flags 14:31:19 sqlt$m: observations_sec 14:31:19 sqlt$m: sql_text_sec 14:31:20 sqlt$m: sql_identification_sec 14:31:20 sqlt$m: environment_sec 14:31:20 sqlt$m: cbo_environment_sec 14:31:20 sqlt$m: cbo_environment_mod 14:31:20 sqlt$m: cbo_environment_unmod 14:31:20 sqlt$m: bug_fix_control_sec 14:31:20 sqlt$m: bug_fix_control_sec_0 14:31:20 sqlt$m: bug_fix_control_sec_1 14:31:20 sqlt$m: system_stats_sec 14:31:20 sqlt$m: dbms_stats_setup_sec 14:31:21 sqlt$m: init_parameters_sec 14:31:21 sqlt$m: init_parameters_sec_FALSE 14:31:22 sqlt$m: init_parameters_sec_TRUE 14:31:23 sqlt$m: init_parameters_sys_mod 14:31:23 sqlt$m: init_parameters_sys
可以看到我们在做sqlt$m: init_parameters_sys的时候卡住了。但是看到了这个信息，我们也不知道它的意思。于是，我们只能考虑做下10046。
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的一种解决办法, 感谢原作者分享。