首页 » ORACLE 9i-23ai » Troubleshooting “latch: row cache objects” case and Event 10089 to do.
Troubleshooting “latch: row cache objects” case and Event 10089 to do.
“row cache objects”是序列化latch，用于保护对SGA中dictionary cache的访问。 只要是参考dictionary cache中的元数据对象，就会获取此latch。 Row Cache Objects Latch 是 shared pool latch 相关，目的是为访问Oracle中缓存的 data dictionary area的用户进程提供数据保护。
这里记录一个11.2.0.3 RAC环境中的案例， 几年前写过一篇分析脚本《Tuning ‘latch: row cache objects’ Event》
SQL> @sw "select sid from v$session where event='latch: row cache objects'"
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------- ------------------- ------------------- ------------------------------------------
557 WAITING latch: row cache objects 47722 0 address= number= 280 tries= 0 0xC0000015B3ABB538: row cache objects[c8]
0xC0000015B3ABB538
16325 WAITING latch: row cache objects 3555 0 address= number= 280 tries= 0 0xC0000015B3ABB538: row cache objects[c8]
0xC0000015B3ABB538
948 WAITING latch: row cache objects 5190 0 address= number= 280 tries= 0 0xC0000015B3ABB538: row cache objects[c8]
0xC0000015B3ABB538
1363 WAITING latch: row cache objects 12934 0 address= number= 280 tries= 0 0xC0000015B3ABB538: row cache objects[c8]
0xC0000015B3ABB538
1622 WAITING latch: row cache objects 27639 0 address= number= 280 tries= 0 0xC0000015B3ABB538: row cache objects[c8]
0xC0000015B3ABB538
717 WAITING latch: row cache objects 64778 0 address= number= 280 tries= 0 0xC0000015B3ABB538: row cache objects[c8]
0xC0000015B3ABB538
SQL> select * from v$latch_children where addr='C0000015B3ABB538';
ADDR LATCH# CHILD# LEVEL# NAME HASH GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS SLEEP1 SLEEP2 SLEEP3 SLEEP4 SLEEP5 SLEEP6 SLEEP7 SLEEP8 SLEEP9 SLEEP10 SLEEP11 WAIT_TIME
---------------- ---------- ---------- ---------- ---------------------------------------------------------------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
C0000015B3ABB538 280 8 4 row cache objects 2412510220 2086493595 593790459 155653120 47042 3177 0 0 451293450 0 0 0 0 0 0 0 0 0 0 0 6.1216E+12
SQL> select * from x$kqrst where kqrstcln=8;
ADDR INDX INST_ID KQRSTCID KQRSTSNO KQRSTTYP KQRSTTXT KQRSTCSZ KQRSTOSZ KQRSTFCS KQRSTUSG KQRSTGRQ KQRSTGMI KQRSTSRQ KQRSTSMI KQRSTSCO KQRSTMRQ KQRSTMFL Child# KQRSTILR KQRSTIFR KQRSTISR
---------------- ---------- ---------- ---------- ---------- ---------- -------------------------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ------ ---------- ---------- ----------
C0000015B3ABA1C0 7 1 10 0 1 dc_users 101 0 0 101 4153788437 49022 0 0 0 413 413 8 48800 7 47468
C0000015B3ABAD00 52 1 7 0 2 dc_users 0 0 0 0 0 0 0 0 0 0 0 8 0 0 0
C0000015B3ABAE40 57 1 7 1 2 dc_users 50 0 0 50 3329238869 14418 0 0 0 0 0 8 0 0 0
C0000015B3ABAE80 58 1 7 2 2 dc_users 0 0 0 0 0 0 0 0 0 0 0 8 0 0 0
SQL> oradebug setorapid 1601
Oracle pid: 1601, Unix process pid: 29755, image: oracle@qdyyc1
SQL> oradebug short_stack;
SQL> oradebug setorapid 1601
Oracle pid: 1601, Unix process pid: 29755, image: oracle@qdyyc1
SQL> oradebug short_stack;
ksedsts()+544<-ksdxfstk()+48<-ksdxcb()+3216<-sspuser()+688<-<kernel><-_pw_wait()+48<-pw_wait()+112<-sskgpwwait()+432<-skgpwwait()+320<-kslges()+2208<-kslgetl()+784<-kqreqd()+448<-kqrprl()+384<-ktatminextsz()+1024<-qerhjComputeFanoutAndBPS()+480<-kkejnc()+4176<-kkojnp()+19488<-kkocnp()+96<-kkooqb()+3120<-kkoqbc()+4304<-apakkoqb()+384<-apaqbdDescendents()+896<-apaqbdList()+160<-apaqbdDescendents()+1088<-apaqbdList()+160<-apaqbdDescendents()+496<-apaqbdList()+160<-apaqbdDescendents()+496<-apaqbdList()+160<-apaqbdDescendents()+496<-apaqbd()+128<-apadrv()+1664<-opitca()+4832<-kksSetBindType()+13504<-kksfbc()+11872<-opiexe()+5104<-kpoal8()+4624<-opiodr()+2416<-ttcpip()+2416<-opitsk()+2960<-opiino()+1696<-opiodr()+2416<-opidrv()+1616<-sou2o()+256<-opimai_real()+656<-ssthrdmain()+576<-main()+336<-main_opd_entry()+80
SQL> oradebug short_stack;
ksedsts()+544<-ksdxfstk()+48<-ksdxcb()+3216<-sspuser()+688<-<kernel><-kcbgtcr()+4145<-ktrget3()+1632<-ktrget2()+160<-kdst_fetch()+1344<-kdstf11001010000km()+1600<-kdsttgr()+3344<-qertbFetch()+1520<-rwsfcd()+320<-qerhjFetch()+1040<-rwsfcd()+320<-qerhjFetch()+1616<-rwsfcd()+320<-qeruaFetch()+848<-qervwFetch()+352<-qersoProcessULS()+496<-qersoFetch()+896<-qervwFetch()+352<-qergsFetch()+4112<-opifch2()+9600<-kpoal8()+7360<-opiodr()+2416<-ttcpip()+2416<-opitsk()+2960<-opiino()+1696<-opiodr()+2416<-opidrv()+1616<-sou2o()+256<-opimai_real()+656<-ssthrdmain()+576<-main()+336<-main_opd_entry()+80
SQL> oradebug short_stack;
ksedsts()+544<-ksdxfstk()+48<-ksdxcb()+3216<-sspuser()+688<-<kernel><-_read_sys()+48<-_read()+224<-$cold_skgfqio()+880<-ksfd_skgfqio()+208<-ksfd_io()+1168<-ksfdread()+304<-kcfrbd1()+1248<-kcbzib()+2464<-kcbgtcr()+14336<-ktrget3()+1632<-ktrget2()+160<-kdsgrp()+336<-qetlbr()+432<-qertbFetchByRowID()+1728<-qerjotFetch()+1504<-qerjotFetch()+1504<-qervwFetch()+352<-rwsfcd()+320<-qerhjFetch()+2080<-rwsfcd()+320<-qeruaFetch()+848<-$cold_qervwFetch()+2384<-qersoProcessULS()+496<-qersoFetch()+896<-qervwFetch()+352<-qergsFetch()+4112<-opifch2()+9600<-kpoal8()+7360<-opiodr()+2416<-ttcpip()+2416<-opitsk()+2960<-opiino()+1696<-opiodr()+2416<-opidrv()+1616<-sou2o()+256<-opimai_real()+656<-ssthrdmain()+576<-main()+336<-main_opd_entry()+80
SQL> oradebug short_stack;
ksedsts()+544<-ksdxfstk()+48<-ksdxcb()+3216<-sspuser()+688<-<kernel><-kkoiop()+96<-kkoiop()+304<-kkobrfio()+368<-kkoij2()+1360<-kkoixj()+704<-kkotap()+11120<-kkoiqb()+16704<-kkooqb()+1104<-kkoqbc()+4304<-apakkoqb()+384<-apaqbdDescendents()+896<-apaqbd()+128<-kkqctCostTransfQB()+608<-kkqctdrvJPPD()+2288<-kkqjpdctr()+2736<-kkqctInterleaveJPPD()+368<-kkqctdrvSU()+3920<-kkqutruns()+736<-kkqutruns()+208<-kkqutruns()+208<-kkqutruns()+208<-kkqutruns()+432<-kkqutruns()+240<-kkqutruns()+240<-kkqudrv()+784<-kkqctdrvTD()+2240<-kkqdrv()+5360<-kkqctdrvIT()+1424<-apadrv()+3376<-opitca()+4832<-kksFullTypeCheck()+144<-rpiswu2()+1120<-kksSetBindType()+4640<-kksfbc()+11872<-opiexe()+5104<-kpoal8()+4624<-opiodr()+2416<-ttcpip()+2416<-opitsk()+2960<-opiino()+1696<-opiodr()+2416<-opidrv()+1616<-sou2o()+256<-opimai_real()+656<-ssthrdmain()+576<-main()+336<-main_opd_entry()+80
SQL> oradebug short_stack;
ksedsts()+544<-ksdxfstk()+48<-ksdxcb()+3216<-sspuser()+688<-<kernel><-_write_sys()+48<-write()+176<-$cold_skgfqio()+784<-ksfd_skgfqio()+208<-ksfd_io()+1168<-ksfdread()+304<-kcfrbd1()+1248<-kcbzib()+2464<-kcbgtcr()+14336<-ktrget3()+1632<-ktrget2()+160<-kdsgrp()+336<-qetlbr()+432<-qertbFetchByRowID()+1728<-qerjotFetch()+3664<-qerjotFetch()+3664<-qervwFetch()+352<-rwsfcd()+320<-qerhjFetch()+2080<-rwsfcd()+320<-qeruaFetch()+848<-qervwFetch()+352<-qersoProcessULS()+496<-qersoFetch()+896<-qervwFetch()+352<-qergsFetch()+4112<-opifch2()+9600<-kpoal8()+7360<-opiodr()+2416<-ttcpip()+2416<-opitsk()+2960<-opiino()+1696<-opiodr()+2416<-opidrv()+1616<-sou2o()+256<-opimai_real()+656<-ssthrdmain()+576<-main()+336<-main_opd_entry()+80
SQL> col cache# head "Cache|no" form 999
SQL> col parameter head "Parameter" form a25
SQL> col type head "Type" form a12
SQL> col subordinate# head "Sub|ordi|nate" form 9999
SQL> col rcgets head "Cache|Gets" form 999999999999
SQL> col rcmisses head "Cache|Misses" form 999999999999
SQL> col rcmodifications head "Cache|Modifica|tions" form 999999999999
SQL> col rcflushes head "Cache|Flushes" form 999999999999
SQL> col kqrstcln head "Child#" form 999
SQL> col lagets head "Latch|Gets" form 999999999999
SQL> col lamisses head "Latch|Misses" form 999999999999
SQL> col laimge head "Latch|Immediate|gets" form 999999999999
SQL>
SQL> select dc.kqrstcid CACHE#, dc.kqrsttxt PARAMETER, decode(dc.kqrsttyp, 1,'PARENT','SUBORDINATE') type,
2 decode(dc.kqrsttyp, 2, kqrstsno, null) subordinate#,
3 dc.kqrstgrq rcgets, dc.kqrstgmi rcmisses, dc.kqrstmrq rcmodifications, dc.kqrstmfl rcflushes, dc.kqrstcln,
4 la.gets lagets, la.misses lamisses, la.immediate_gets laimge
5 from x$kqrst dc,
6 v$latch_children la
7 where dc.inst_id = userenv('instance')
8 and la.child# = dc.kqrstcln
9 and la.name = 'row cache objects'
10 order by rcgets desc;
Sub Cache Latch
Cache ordi Cache Cache Modifica Cache Latch Latch Immediate
no Parameter Type nate Gets Misses tions Flushes Child# Gets Misses gets
----- ------------------------- ------------ ----- ------------- ------------- ------------- ------------- ------ ------------- ------------- -------------
10 dc_users PARENT 3734912072 48997 413 413 8 819920633 250124586 47007
8 dc_objects PARENT 3620833881 130864169 2454725 2441251 9 2558015670 2412030590 3164403
7 dc_users SUBORDINATE 1 3314778444 14412 0 0 8 819920633 250124586 47007
2 dc_segments PARENT 2419992098 208986999 5565215 5565144 4 409661609 261272169 14687358
16 dc_histogram_defs PARENT 1339720402 51147414 1146382 1123333 13 956389160 3386779019 8520219
0 dc_tablespaces PARENT 1152376656 14361 0 0 5 3457243305 3385062240 16133
3 dc_rollback_segments PARENT 566714092 2910 1509 1508 1 1492039470 1286974917 85
16 dc_histogram_data SUBORDINATE 0 503513763 946170 3141 2354 13 956389160 3386779019 8520219
14 dc_profiles PARENT 358817542 795 1 1 18 1076461125 4088737 1358
16 dc_histogram_data SUBORDINATE 1 289546279 296203 3031 2044 13 956389160 3386779019 8520219
6 dc_files PARENT 214370418 148014 15 15 7 644323538 320328 12272
SQL> select * from v$latch_misses where parent_name='row cache objects' and WTR_SLP_COUNT>1 order by 4;
PARENT_NAME WHERE NWFAIL_COUNT SLEEP_COUNT WTR_SLP_COUNT LONGHOLD_COUNT LOCATION
-------------------- -------------------------------------------------------------------------------- ------------ ----------- ------------- -------------- --------------------------------------------------------------------------------
....
row cache objects kqrigt 0 33041 13374 0 kqrigt
row cache objects kqrbip 0 60479 26413 0 kqrbip
row cache objects kqrso 0 1143654 1491449 0 kqrso
row cache objects kqreqd 0 35450260 71020564 0 kqreqd
row cache objects kqrpre: find obj 0 76579666 129201124 0 kqrpre: find obj
row cache objects kqreqd: reget 0 120729099 32281153 0 kqreqd: reget
# AWR
Load Profile
| Per Second | Per Transaction | Per Exec | Per Call | |
|---|---|---|---|---|
| DB Time(s): | 177.0 | 0.3 | 0.01 | 0.00 |
| DB CPU(s): | 59.9 | 0.1 | 0.00 | 0.00 |
| Redo size: | 2,367,829.5 | 3,705.1 | ||
| Logical reads: | 2,942,702.4 | 4,604.6 | ||
| Block changes: | 13,108.5 | 20.5 | ||
| Physical reads: | 34,802.0 | 54.5 | ||
| Physical writes: | 709.6 | 1.1 | ||
| User calls: | 54,072.2 | 84.6 | ||
| Parses: | 1,338.6 | 2.1 | ||
| Hard parses: | 217.0 | 0.3 | ||
| W/A MB processed: | 135.0 | 0.2 | ||
| Logons: | 9.4 | 0.0 | ||
| Executes: | 26,684.2 | 41.8 | ||
| Rollbacks: | 260.7 | 0.4 | ||
| Transactions: | 639.1 |
Top 5 Timed Foreground Events
| Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
|---|---|---|---|---|---|
| latch: row cache objects | 892,736 | 112,098 | 126 | 34.94 | Concurrency |
| DB CPU | 108,645 | 33.86 | |||
| db file sequential read | 24,567,158 | 57,141 | 2 | 17.81 | User I/O |
| db file scattered read | 1,797,235 | 8,206 | 5 | 2.56 | User I/O |
| gc cr grant 2-way | 11,853,598 | 6,796 | 1 | 2.12 | Cluster |
Dictionary Cache Stats
- “Pct Misses” should be very low (< 2% in most cases)
- “Final Usage” is the number of cache entries being used
| Cache | Get Requests | Pct Miss | Scan Reqs | Pct Miss | Mod Reqs | Final Usage |
|---|---|---|---|---|---|---|
| dc_awr_control | 38 | 0.00 | 0 | 2 | 1 | |
| dc_files | 27,488 | 0.00 | 0 | 0 | 859 | |
| dc_global_oids | 8,523 | 0.18 | 0 | 0 | 30 | |
| dc_histogram_data | 67,542 | 0.98 | 0 | 0 | 820 | |
| dc_histogram_defs | 45,560,366 | 0.05 | 0 | 0 | 13,260 | |
| dc_object_grants | 1,628 | 3.44 | 0 | 0 | 313 | |
| dc_objects | 90,488,082 | 0.02 | 0 | 3 | 5,801 | |
| dc_profiles | 31,701 | 0.00 | 0 | 0 | 4 | |
| dc_rollback_segments | 591,873 | 0.00 | 0 | 0 | 2,556 | |
| dc_segments | 5,818,659 | 1.39 | 0 | 128 | 82,721 | |
| dc_sequences | 537 | 56.42 | 0 | 537 | 5 | |
| dc_table_scns | 25 | 36.00 | 0 | 5 | 5 | |
| dc_tablespaces | 60,356,706 | 0.00 | 0 | 0 | 36 | |
| global database name | 17,606 | 0.01 | 0 | 0 | 1 | |
| outstanding_alerts | 99 | 100.00 | 0 | 0 | 0 | |
| sch_lj_oids | 6 | 0.00 | 0 | 0 | 1 |
Wait Event Histogram
| % of Waits | |||||||||
| Event | Total Waits | <1ms | <2ms | <4ms | <8ms | <16ms | <32ms | <=1s | >1s |
|---|---|---|---|---|---|---|---|---|---|
| latch: row cache objects | 894.8K | 23.6 | 2.6 | 1.8 | 1.5 | 1.6 | 2.5 | 66.3 | .0 |
Latch Miss Sources
| Latch Name | Where | NoWait Misses | Sleeps | Waiter Sleeps |
|---|---|---|---|---|
| row cache objects | kqreqd: reget | 0 | 563,517 | 128,828 |
| row cache objects | kqrpre: find obj | 0 | 255,237 | 554,836 |
| row cache objects | kqreqd | 0 | 102,913 | 236,755 |
| row cache objects | kqrso | 0 | 1,092 | 2,518 |
| row cache objects | kqrbip | 0 | 88 | 9 |
| row cache objects | kqrbgl | 0 | 66 | 46 |
## hanganalyze trace show blocker
and is blocked by
=> Oracle session identified by:
{
instance: 1 (weejar.weejar1)
os id: 25694
process id: 8158, oracle@qdyyc1
session id: 17647
session serial #: 51605
}
which is not in a wait:
{
last wait: 0.000000 sec ago
blocking: 5 sessions
current sql: select * from (select row_.*, rownum rownum_ from ( select distinct m.prodname, m.privname, m.privna, decode((select count(1)
from anbob.****vilege t, anbob.***scriber s where s.****umber = :1
short stack: ksedsts()+544<-ksdxfstk()+48<-ksdxcb()+3216<-sspuser()+688<-<kernel><-_pw_wait()+48<-pw_wait()+112<-sskgpwwait()+432<-skgpwwait()+320<-kslges()+2208<-kslgetl()+784<-kqreqd()+
448<-kqrprl()+384<-ktatminextsz()+1024<-qerhjComputeFanoutAndBPS()+480<-kkejnc()+4176<-kkojnp()+19488<-kkocnp()+96<-kkooqb()+3120<-kkoqbc()+4304<-apakkoqb()+384<-apaqbdDescendents()+896<-apaqbdList()+
160<-apaqbdDescendents()+496<-apaqbd()+128<-kkqctCostTransfQB()+608<-kkqctdrvJPPD()+2288<-kkqjpdctr()+2736<-qksqbApplyToQbcLoc()+864<-qksqbApplyT
wait history:
1. event: ‘latch: row cache objects’
time waited: 0.360363 sec
wait id: 34094 p1: ‘address’=0xc0000015b3abb538
p2: ‘number’=0x118
p3: ‘tries’=0x0
* time between wait #1 and #2: 0.034827 sec
这个案例主要的问题
1. hard parse & soft parse 太高
2. 相关的BUG 有
Bug 13902396 Hash joins cause “row cache objects” latch gets and “shared pool” latch gets
Bug 17799716 High row cache requests for a query with many indexes
不过从上面看当时一个bloker会话正在执行的SQL表上索引是不少(10+), 而且与bug 17799716 call stack有些相似。是在当前版本中当执行计划用不同索引cost相同时，排序索引名称取第一个， 在11.2.0.3[|4]中CBO引入的更多的查询转换所以会持有更长时间的row cache latch比10g时。 解决方法如改SQL降硬解析使用绑定变量；修改优化器为10.2.0.4；使用event 10089 level 1;
SQL> alter system set events ‘10089 trace name context forever, level 1’;
SQL> alter system set event = ‘10089 trace name context forever, level 1’ scope=spfile
What ‘s Event 10089 level 1
Event 10089 level 1: CBO disable index sorting.
默认情况 下CBO 使用 排除决策的方法，当两个执行计划中index 的cost相同时，使用索引名称字母排序选择第一个索引. 使用10053 event 可以看到是当两个执行计划中两个索引COST相同时如何选择索引。默认10089 event没有配置，而是使用索引名称排除的， 但是当启用了event 10089 level 1, CBO就不会在当cost相同时使用index name排序，而是改为按index created 创建时间排序。 这个event 有助于降低”get” row cache dc_objects的竞争。
微信扫一扫，打赏作者吧～
对不起，这篇文章暂时关闭评论。