In the previous blog post<\/a> I showed how a DML can hold a redo copy latch for a very long time if private strands aren’t used. Since recursive statements during logon bypass private strands, this can cause serious latch wait cascades. In particular, most of this time is spent in the function kcbklbc, which links a changed block to the checkpoint queue.<\/p>\n Unlike redo copy latch, checkpoint queue latch latch is being held very briefly. This indicates that the block is linked very fast, and that the extra time is spent elsewhere. That overhead is the main focus of this article.<\/p>\n With DTrace, we can trace offsets [1]<\/a>. An offset is the position of the instruction in bytes relative to the function start. As we shall see, we can get useful information by analyzing an offset trace even without disassembling the code. In addition to offsets, the following script traces latch allocations within the function.<\/p>\n Here are the most relevant parts of a huge trace:<\/p>\n The first column is the timing in microseconds relative to the function entry. The cut out parts are marked with “…”.<\/p>\n The latch names can be obtained from the database:<\/p>\n From the trace above, we can observe following:<\/p>\n There were 1080 loop iterations:<\/p>\n The number of the iterations coincides with the undocumented parameter _db_block_lru_latches:<\/p>\n Each LRU latch protects a working data set [2]<\/a>. There are indeed 1080 working data sets:<\/p>\n The loop iterates over the working data sets. I doublecheked that by changing the parameter value and verifying that the number of iterations changed accordingly.<\/p>\n So, the more working data sets, the longer redo copy latch is being held. As the number of working data sets is proportional to the number of CPUs, the problem is worse on larger servers.<\/p>\n Further, there are two types of iterations: with 7 and 13 instructions. This variation reveals a conditional branching. Three instructions must be for the loop control and three for the branching. This leaves us with just a few instructions doing the actual work – they calculate the sum of values obtained by dereferencing several pointers in the SGA.<\/p>\n The reads in the loop aren’t protected by a latch. This means that consistency isn’t critical. Jonathan Lewis<\/a> pointed out that the result might be consumed by an advisor. Below are all advisor parameters:<\/p>\n _db_advise_mttr was the first choice, because I previously discovered that the loop isn’t being executed if fast_start_mttr_target = 0. The program indeed doesn’t iterate through the working data sets after disabling the MTTR advisor (_db_mttr_advice = OFF). Simply put, on a large server with many CPUs redo copy latch waits can be massively reduced by disabling the MTTR advisor.<\/p>\n What data exactly does the MTTR advisor code read?<\/p>\n Each working data set has two checkpoint queues. Even though the pointers to them are contained in the working data set structure, they are, sadly, not externalized in x$kcbwds. But we can get them with a debugger by peeking into the following addresses (at least on 19.7): x$kcbwds.addr+0xa0 and x$kcbwds.addr+0x1a8, for example:<\/p>\n We can confirm, that the addresses above are pointing to the checkpoint queues:<\/p>\n The MTTR advisor code collects the values which are at 0x10 offset and sums them.<\/p>\n Jonathan<\/a> pointed out that those values are probably the number of blocks in the checkpoint queue. In the example above, there aren’t any blocks on the observed checkpoint queues.<\/p>\n The MTTR advisor code is only executed after a block was linked to the checkpoint queue. There are also kcbklbc executions that don’t link any blocks and, therefore, hold the redo copy latch only for a very short time. Such cases are recognized by the absence of checkpoint queue latch latch allocations.<\/p>\n In conclusion, DMLs bypassing private strands can piggyback data collection for the MTTR advisor. That code is executed immediately after linking a changed block to the checkpoint queue. The function iterates over the working data set array while holding a redo copy latch. This isn’t a big problem on a database containing a small number of working data sets. But, since the number of working data sets is proportional to the number of CPUs, logon storms can cause serious latch wait cascades on large servers. It’s something to keep in mind when migrating to a bigger server or configuring hyper-threading, especially when the application doesn’t use static connection pools.<\/p>\n The MTTR advisor code is the root cause for the following bug: MTTR advisor data gathering can cause redo copy latch contention on servers with many CPUs. Checkpoint queue internals. An example of analyzing a compiled function in a proprietary code without disassembling it. Continue Reading Assembly Tracing<\/h1>\n
#pragma D option dynvarsize=32m\n#pragma D option quiet\n\npid$target:oracle:kcbklbc:0\n{\n self->started = timestamp ;\n ustack();\n self->kcbklbc = 1;\n}\n\npid$target:oracle:kslgetl:entry,\npid$target:oracle:kslfre:entry\n\/ self->kcbklbc \/\n{\n printf(\"%s %s %X\\n\", probefunc, probename, arg0);\n}\n\npid$target:oracle:kcbklbc:\n{\n printf(\"%d offset: %s\\n\", ( timestamp - self->started ) \/ 1000, probename);\n}\n\npid$target:oracle:kcbklbc:return\n{\n self->kcbklbc = 0 ;\n}<\/code><\/pre>\n..\n1<\/span> offset: 0\n3 offset: 2\n6 offset: 3\n...\n453 offset: 882\nkslgetl entry 9E551EB8 --> acquired checkpoint queue latch latch\n462 offset: 887\n...\n1048 offset: 4ac\nkslfre entry 9E551EB8 --> released checkpoint queue latch latch\n1057 offset: 4b1\n...\n1403 offset: d1d\nkslfre entry 9C438688 --> released object queue header operation latch\n1424<\/span> offset: d22\n...\n1539 offset: f13\n1543 offset: f17\n1555 offset: f1b\n1566 offset: f23\n1571 offset: f41\n1575 offset: f45\n1579 offset: f48<\/span>\n1581 offset: f13\n1583 offset: f17\n1585 offset: f1b\n1588 offset: f23\n1590 offset: f41\n1592 offset: f45\n1594 offset: f48\n1596 offset: f13\n1598 offset: f17\n1600 offset: f1b\n1610 offset: f23\n1613 offset: f41\n1615 offset: f45\n1618 offset: f48\n...\n10012 offset: f13\n10015 offset: f17\n10017 offset: f1b\n10021 offset: f23\n10023 offset: f25\n10025 offset: f2c\n10027 offset: f33\n10041 offset: f37\n10044 offset: f3a\n10053 offset: f3e\n10055 offset: f41\n10058 offset: f45\n10060 offset: f48<\/span>\n10063 offset: f13\n10066 offset: f17\n10068 offset: f1b\n10077 offset: f23\n10080 offset: f25\n10083 offset: f2c\n10086 offset: f33\n10095 offset: f37\n10098 offset: f3a\n10107 offset: f3e\n10111 offset: f41\n10113 offset: f45\n10116 offset: f48\n10118 offset: f13\n10120 offset: f17\n10122 offset: f1b\n10125 offset: f23\n...\n30261<\/span> offset: return<\/code><\/pre>\nselect name,addr from v$latch_children where addr like '%9E551EB8' or addr like '%9C438688';\n\nNAME ADDR\n---------------------------------------------------------------- ----------------\ncheckpoint queue latch 000000009E551EB8\nobject queue header operation 000000009C438688<\/code><\/pre>\n\n
Working data sets array<\/h1>\n
grep f13 kcbklbc.log | wc -l\n1080<\/code><\/pre>\nselect a.ksppinm name,b.ksppstvl value \n from sys.x$ksppi a, sys.x$ksppcv b\nwhere a.indx = b.indx and b.ksppstvl = '1080'\n;\n\nNAME\n--------------------------------------------------------------------------------\nVALUE\n--------------------------------------------------------------------------------\n_db_block_lru_latches\n1080<\/code><\/pre>\nselect count(*) from x$kcbwds;\n\n COUNT(*)\n----------\n 1080<\/code><\/pre>\nMTTR advisor<\/h1>\n
@pd2.sql<\/a> %advi%\nShow all parameters and session values from x$ksppi\/x$ksppcv...\n\n NUM N_HEX NAME VALUE DESCRIPTION\n---------- ----- -------------------------------------------------------- ------------------------------ ---------------------------------------------------------------------------------------------------\n 1825 721 db_cache_advice OFF Buffer cache sizing advisory\n 1826 722 _db_cache_advice_sample_factor 4 cache advisory sampling factor\n 1827 723 _db_cache_advice_max_size_factor 2 cache advisory maximum multiple of current size to similate\n 1828 724 _db_cache_advice_sanity_check FALSE cache simulation sanity check\n 1829 725 _db_cache_advice_hash_latch_multiple 16 cache advisory hash latch multiple\n 1830 726 _db_mttr_advice ON MTTR advisory\n 1833 729 _db_mttr_partitions 0 number of partitions for MTTR advisory\n 2690 A82 _simulate_io_wait 0 Simulate I\/O wait to test segment advisor\n 2851 B23 _compression_advisor 0 Compression advisor\n 3245 CAD _library_cache_advice TRUE whether KGL advice should be turned on\n 3246 CAE _kglsim_maxmem_percent 5 max percentage of shared pool size to be used for KGL advice\n 3888 F30 _smm_advice_log_size 0 overwrites default size of the PGA advice workarea history log\n 3889 F31 _smm_advice_enabled TRUE if TRUE, enable v$pga_advice\n 3972 F84 _sta_control 0 SQL Tuning Advisory control parameter\n 3973 F85 _enable_automatic_sqltune TRUE Automatic SQL Tuning Advisory enabled parameter\n 4252 109C _partition_advisor_srs_active true enables sampling based partitioning validation<\/code><\/pre>\nCheckpont queues<\/h1>\n
select addr from x$kcbwds where rownum=1;\n\nADDR\n----------------\n000000009E49B868<\/code><\/pre>\n(gdb) x\/x 0x9E49B868+0xa0\n0x9e49b908: 0x9e4dceb8\n(gdb) x\/x 0x9E49B868+0x1a8\n0x9e49ba10: 0x9e4dcf18<\/code><\/pre>\n@fcha.sql<\/a> 0x9e4dceb8\n\nLOC KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR\n--- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ----------------\nSGA 000000009E4DCEA8 1 1 Checkpoint queu 48 perm 0 000000009E0CD000\n\n@fcha.sql<\/a> 0x9e4dcf18\n\nLOC KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR\n--- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ----------------\nSGA 000000009E4DCF08 1 1 Checkpoint queu 48 perm 0 000000009E0CD000<\/code><\/pre>\n(gdb) x\/d 0x9e4dceb8+0x10\n0x9e4dcec8: 0\n(gdb) x\/d 0x9e4dcf18+0x10\n0x9e4dcf28: 0<\/code><\/pre>\nConclusion<\/h1>\n
References<\/h1>\n
\n
Update on October 2, 2020<\/h1>\n
\nBug 29924088 : 18.4 – HIGH CONCURRENCY FROM UPDATE USER$ – SQL_ID 9ZG9QD9BM4SPU<\/p>\n","protected":false},"excerpt":{"rendered":"