Latch waits are well instrumented in Oracle database. We can see for how long a process was waiting for a latch. We can also identify the latch holder. But it’s difficult to observe a problem from the blockers perspective. We don’t know for how long the blocker was holding the latch. We also don’t have a broader context.<\/p>\n
I closed this gap with the DTrace script trace_latches.d<\/a>. The script traces the calls to the relevant Oracle C functions. In particular, latches are acquired and released by calling kslgetl and kslfre, respectively [1]<\/a>. The latch address is passed by the first argument. DTrace prints the latch address and the call stack whenever a latch is requested or released.<\/p>\n For instance, I was tracing a process which executed a simple insert followed by a commit:<\/p>\n Below is the excerpt from the trace file:<\/p>\n You have to query the database for the latch name:<\/p>\n This is tedious, as a process typically allocates many latches. I wrote a Perl program to eliminate that toil. It enriches the trace with the latch name.<\/p>\n First, create the mapping file:<\/p>\n The mapping file contains the address of each latch. Beware that those addresses change after a database restart.<\/p>\n Then, postprocess the captured trace:<\/p>\n Now we can see the latch name for each latch operation:<\/p>\n I tested the described methodology on a latch contention problem discussed on Twitter<\/a>. The root blockers were holding redo copy latches during logon while executing “update user$ spare6” – the last logon time update. There were around 50 logons per seconds.<\/p>\n With trace_latches.d<\/a> we can measure for how long a process was holding a latch. But how do we get the process ID of a new process? We can’t query the PID, because the entries in v$session and v$process haven’t been created yet. Instead, we have to pause the dedicated process immediately after forking. I scripted the solution: stop_forked.d<\/a> stops the execution in the authentication function kpoauth and prints the PID. Then you have all the time in the world to run trace_latches.d<\/a>.<\/p>\n A redo copy latch was indeed held for almost 6ms:<\/p>\n That’s extremely long for a latch – the elapsed time is normally measured in microseconds. The stack shows that the latch was acquired by an update. But how do we know that it is the originally reported update? We can set a conditional breakpoint when the latch is acquired and look at the active sessions. The following query generates the breakpoint command that we can copy into the gdb.<\/p>\n As you can see, it’s the same statement.<\/p>\n Frits Hoogland<\/a> noticed the function kcrfw_redo_gen_ext on the stack and concluded that private strands haven\u2019t been used. Since private strands aren’t used, a redo copy latch has to be allocated before copying data into the redo buffer. Interestingly, private strands are used if we run the same statement in sqlplus. In other words, private strands aren’t used only during the logon.<\/p>\n Inserted on October 12, 2020: The block changes are deferred until commit when private strands are being used. The Oracle C function kcrfw_redo_gen_ext is called during commit to perform block changes. A kcrfw_redo_gen_ext function call during DML indicates that the private strands were bypassed. [3]<\/a><\/ins><\/p>\n The almost entire time of holding the latch is being spent in kcbklbc. We can prove this by extending trace_latches.d<\/a> as follows:<\/p>\n The extension above measures the time spent in kcbklbc:<\/p>\n The kcbklbc annotation is “kernel cache buffers checkpoint queue manipulation link buffer into ckpt queue” [2]<\/a>.<\/p>\n The function is called whenever a redo copy latch gets allocated. In most cases it runs quickly. For example, it took only 61 microseconds for a commit:<\/p>\n The logon update seems like a special case. The execution branches to a code path taking up much more time. Interestingly, the execution doesn’t take nearly that long after a database restart:<\/p>\n But after a couple of minutes the code for special handling gets executed again. I still haven’t figured out what that special handling is, and what triggers it.<\/p>\n I wrote a DTrace script for measuring for how long each latch was being held. The script also provides the context by printing the stack when a latch is acquired or released. I’m not aware of a database trace that shows similar information.<\/p>\n update user$ during logon doesn\u2019t use private strands. Consequently, it allocates a redo copy latch and can hold it for several milliseconds. That’s an extremely long time to occupy a latch. The most of that time the process is being busy with manipulating the checkpoint queues. That can cause serious wait cascades during logon storms. The best protection is a proper connection pooling.<\/p>\n Jonathan Lewis<\/a> pointed out that a DML execution under SYS on behalf on another user as a part of the internal code generally bypasses private strands. It’s easy to show that also insert aud$ copies the data directly into the public redo buffer:<\/p>\n kcbklbc runs for long only when executed during update user$.<\/p>\n However, if fast_start_mttr_target=0 kcbklbc always runs fast.<\/p>\n Thanks to Frits Hoogland for the additional explanation on kcrfw_redo_gen_ext<\/a>.<\/p>\n I investigated the relevant MTTR advisor internals in the subsequent blog post<\/a>.<\/p>\n Tracing latches with OS tools, case study: redo copy contention caused by a logon storm Continue Reading dtrace -s trace_latches.d<\/a> -p 8451<\/span> > latches.trc<\/code><\/pre>\n@whoami\n\nSADDR SPID SID SERIAL# PID\n---------------- ------------------------ ---------- ---------- ----------\nPROCESS\n------------------------\n00000000C859B3A8 8451<\/span> 5214 50407 13\n7820\n\ninsert into t values (1);\ncommit<\/span> ;<\/code><\/pre>\nkslgetl: 0X14EE2C028 0 0x0 3925\n\noracle`kslgetl\noracle`kcrfw_redo_gen_ext+0x39f\noracle`kcb_commit_main+0xc11\noracle`kcb_commit<\/span>+0x107\noracle`ktiCommitCleanout+0x257\noracle`kticmt+0x64c\noracle`ktucmt+0x21f\noracle`ktcCommitTxn_new+0x402\noracle`ktcCommitTxn+0x5b\noracle`ktdcmt+0x86\noracle`k2lcom+0x99\noracle`k2send+0x514\noracle`xctctl+0x64\noracle`xctCommitTxn+0x305\noracle`kksExecuteCommand+0x4fd\noracle`opiexe+0x339a\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`ttcpip+0x5f3\noracle`opitsk+0x9ec\n-----------------\n\n\nkslfre: 0X14EE2C028<\/span> 0 0x0 5135376848\n\noracle`kslfre\noracle`kcrfw_redo_gen_ext+0x1094\noracle`kcb_commit_main+0xc11\noracle`kcb_commit<\/span>+0x107\noracle`ktiCommitCleanout+0x257\noracle`kticmt+0x64c\noracle`ktucmt+0x21f\noracle`ktcCommitTxn_new+0x402\noracle`ktcCommitTxn+0x5b\noracle`ktdcmt+0x86\noracle`k2lcom+0x99\noracle`k2send+0x514\noracle`xctctl+0x64\noracle`xctCommitTxn+0x305\noracle`kksExecuteCommand+0x4fd\noracle`opiexe+0x339a\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`ttcpip+0x5f3\noracle`opitsk+0x9ec\nlatch elapsed[us]: 285, on cpu[us]: 280<\/code><\/pre>\nselect name from v$latch_children where addr = lpad('14EE2C028<\/span>',16,'0');\n\n\nNAME\n----------------------------------------------------------------\nredo copy<\/code><\/pre>\nsqlplus -s \/nolog << EOD\nconnect \/ as sysdba\nset pagesize 0\nset linesize 200\nspool latches.map\nselect '0X'||ltrim(addr,'0'), name from v\\$latch\nunion \nselect '0X'||ltrim(addr,'0'), name from v\\$latch_children ;\nEOD<\/code><\/pre>\nprocess_latches_trace.pl<\/a> latches.trc latches.map<\/code><\/pre>\nkslgetl: redo copy<\/span> 0X14EE2C028 0 0x0 3925\n\noracle`kslgetl\noracle`kcrfw_redo_gen_ext+0x39f\noracle`kcb_commit_main+0xc11\noracle`kcb_commit+0x107\noracle`ktiCommitCleanout+0x257\noracle`kticmt+0x64c\noracle`ktucmt+0x21f\noracle`ktcCommitTxn_new+0x402\noracle`ktcCommitTxn+0x5b\noracle`ktdcmt+0x86\noracle`k2lcom+0x99\noracle`k2send+0x514\noracle`xctctl+0x64\noracle`xctCommitTxn+0x305\noracle`kksExecuteCommand+0x4fd\noracle`opiexe+0x339a\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`ttcpip+0x5f3\noracle`opitsk+0x9ec\n-----------------\n\n\nkslfre: redo copy<\/span> 0X14EE2C028 0 0x0 5135376848\n\noracle`kslfre\noracle`kcrfw_redo_gen_ext+0x1094\noracle`kcb_commit_main+0xc11\noracle`kcb_commit+0x107\noracle`ktiCommitCleanout+0x257\noracle`kticmt+0x64c\noracle`ktucmt+0x21f\noracle`ktcCommitTxn_new+0x402\noracle`ktcCommitTxn+0x5b\noracle`ktdcmt+0x86\noracle`k2lcom+0x99\noracle`k2send+0x514\noracle`xctctl+0x64\noracle`xctCommitTxn+0x305\noracle`kksExecuteCommand+0x4fd\noracle`opiexe+0x339a\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`ttcpip+0x5f3\noracle`opitsk+0x9ec\nlatch elapsed[us]: 285, on cpu[us]: 280<\/code><\/pre>\nRedo copy latch<\/h1>\n
Logon trace<\/h2>\n
dtrace -ws stop_forked.d<\/a> '\"DB1\"'\nDB: DB1, pid: 4254\n\ndtrace -s trace_latches.d<\/a> -p 4254 > latches.trc\n\nprocess_latches_trace.pl<\/a> latches.trc latches.map<\/code><\/pre>\n...\nkslfre: redo copy 0X14EE2FF70 0 0x0 12905805352\n\noracle`kslfre\noracle`kcrfw_redo_gen_ext+0x1094\noracle`kcbchg1_main+0x1b7f\noracle`kcbchg1+0xe2\noracle`ktuchg2+0x911\noracle`ktbchg2+0x113\noracle`kdu_array_flush_retry+0xc6d\noracle`kdu_array_flush1+0x50\noracle`qerupFetch+0x45c\noracle`updaul+0x678\noracle`updThreePhaseExe+0x14e\noracle`updexe+0x1ec\noracle`opiexe+0x30fc\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`kpoodrc+0x26\noracle`rpiswu2+0x2d6\noracle`kpoodr+0x2bb\noracle`upirtrc+0x1089\noracle`kpurcsc+0x6e\nlatch elapsed[us]: 5976<\/span>, on cpu[us]: 5953\n...<\/code><\/pre>\nset define off\nselect \n 'b kslgetl if $rdi >= 0X'||min(addr)||' && $rdi <= 0X' || max(addr) \n gdb_breakpoint\n from v$latch_children where name='redo copy' ;\n\nGDB_BREAKPOINT\n---------------------------------------------------------------------\nb kslgetl if $rdi >= 0X000000014EE2B530 && $rdi <= 0X000000014EE37ED8<\/code><\/pre>\n@ashtop<\/a> sql_id \"program like 'sql%'\" &5min\n\n Total Distinct\n Seconds AAS %This SQL_ID FIRST_SEEN LAST_SEEN Execs Seen\n--------- ------- ------- ------------- ------------------- ------------------- ----------\n 72 .2 96% | 9zg9qd9bm4spu 2020-06-01 18:27:25 2020-06-01 18:28:37 1\n\n\n@awr_sqlid<\/a> 9zg9qd9bm4spu\n\n DBID SQL_ID SQL_TEXT COMMAND_TYPE CON_DBID CON_ID\n---------- ------------- -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ------------ ---------- ----------\n 510006313 9zg9qd9bm4spu update user$ set spare6=DECODE(to_char(:2, 'YYYY-MM-DD'), '0000-00-00', to_date(NULL), :2) where user#=:1 6 510006313 0<\/code><\/pre>\nPrivate strands<\/h2>\n
kcbklbc<\/h2>\n
pid$target:oracle:kcbklbc:entry\n{\n self->start_kcbklbc = timestamp ;\n}\n\npid$target:oracle:kcbklbc:return\n\/ self->start_kcbklbc \/\n{\n printf(\"kcbklbc[us]: %d\\n\", (timestamp - self->start_kcbklbc)\/1000 ) ;\n ustack();\n self->start_kcbklbc = 0 ;\n}<\/code><\/pre>\nkcbklbc[us]: 5995<\/span>\n\noracle`kcbklbc+0x3a1\noracle`kcbchg1_main+0x1b7f\noracle`kcbchg1+0xe2\noracle`ktuchg2+0x911\noracle`ktbchg2+0x113\noracle`kdu_array_flush_retry+0xc6d\noracle`kdu_array_flush1+0x50\noracle`qerupFetch+0x45c\noracle`updaul+0x678\noracle`updThreePhaseExe+0x14e\noracle`updexe+0x1ec\noracle`opiexe+0x30fc\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`kpoodrc+0x26\noracle`rpiswu2+0x2d6\noracle`kpoodr+0x2bb\noracle`upirtrc+0x1089\noracle`kpurcsc+0x6e\noracle`kpuexec+0x1e9a\n\n\nkslfre: redo copy<\/span> 0X14EE2E8A8 0 0x0 12899699752\n\noracle`kslfre\noracle`kcrfw_redo_gen_ext+0x1094\noracle`kcbchg1_main+0x1b7f\noracle`kcbchg1+0xe2\noracle`ktuchg2+0x911\noracle`ktbchg2+0x113\noracle`kdu_array_flush_retry+0xc6d\noracle`kdu_array_flush1+0x50\noracle`qerupFetch+0x45c\noracle`updaul+0x678\noracle`updThreePhaseExe+0x14e\noracle`updexe+0x1ec\noracle`opiexe+0x30fc\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`kpoodrc+0x26\noracle`rpiswu2+0x2d6\noracle`kpoodr+0x2bb\noracle`upirtrc+0x1089\noracle`kpurcsc+0x6e\nlatch elapsed[us]: 6313, on cpu[us]: 6280<\/code><\/pre>\nkcbklbc[us]: 61\n\noracle`kcbklbc+0x3a1\noracle`kcb_commit_main+0xc11\noracle`kcb_commit+0x107\na.out`ktiCommitCleanout+0x257\na.out`kticmt+0x64c\na.out`ktucmt+0x21f\na.out`ktcCommitTxn_new+0x402\na.out`ktcCommitTxn+0x5b\na.out`ktdcmt+0x86\na.out`k2lcom+0x99\na.out`k2send+0x514\na.out`xctctl+0x64\na.out`xctCommitTxn+0x305\na.out`kksExecuteCommand+0x4fd\noracle`opiexe+0x339a\na.out`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`ttcpip+0x5f3\noracle`opitsk+0x9ec\noracle`opiino+0x4a8\n\n\nkslfre: redo copy 0X14EE2DC00 0 0x0 5135376848\n\noracle`kslfre\noracle`kcrfw_redo_gen_ext+0x1094\noracle`kcb_commit_main+0xc11\noracle`kcb_commit+0x107\na.out`ktiCommitCleanout+0x257\na.out`kticmt+0x64c\na.out`ktucmt+0x21f\na.out`ktcCommitTxn_new+0x402\na.out`ktcCommitTxn+0x5b\na.out`ktdcmt+0x86\na.out`k2lcom+0x99\na.out`k2send+0x514\na.out`xctctl+0x64\na.out`xctCommitTxn+0x305\na.out`kksExecuteCommand+0x4fd\noracle`opiexe+0x339a\na.out`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`ttcpip+0x5f3\noracle`opitsk+0x9ec\nlatch elapsed[us]: 192, on cpu[us]: 161<\/code><\/pre>\nkcbklbc[us]: 14\n\noracle`kcbklbc+0x3a1\noracle`kcbchg1_main+0x1b7f\noracle`kcbchg1+0xe2\noracle`ktuchg2+0x911\noracle`ktbchg2+0x113\noracle`kdu_array_flush_retry+0xc6d\noracle`kdu_array_flush1+0x50\noracle`qerupFetch+0x45c\noracle`updaul+0x678\noracle`updThreePhaseExe+0x14e\noracle`updexe+0x1ec\noracle`opiexe+0x30fc\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`kpoodrc+0x26\noracle`rpiswu2+0x2d6\noracle`kpoodr+0x2bb\noracle`upirtrc+0x1089\noracle`kpurcsc+0x6e\noracle`kpuexec+0x1e9a<\/code><\/pre>\nSummary<\/h1>\n
Updates<\/h1>\n
June 8th, 2020<\/h2>\n
Recursive DML<\/h3>\n
oracle`kcrfw_redo_gen_ext<\/span>\noracle`kcbchg1_main+0x1b7f\noracle`kcbchg1+0xe2\noracle`ktuchg2+0x911\noracle`ktbchg2+0x113\noracle`kdtchg+0x477\noracle`kdtwrp+0xac3\noracle`kdtInsRow<\/span>+0x389\noracle`qerltcNoKdtBufferedInsRowCBK+0x16d\noracle`qerltcSingleRowLoad+0x137\noracle`qerltcFetch+0x1dc\noracle`insexe+0x33e\noracle`opiexe+0x1d8d\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`kpoodrc+0x26\noracle`rpiswu2+0x2d6\noracle`kpoodr+0x2bb\noracle`upirtrc+0x1089\noracle`kpurcsc+0x6e<\/code><\/pre>\nkcbklbc<\/h3>\n
kcbklbc[us]: 44<\/span>\noracle`kcbklbc+0x3a1\noracle`kcbchg1_main+0x1b7f\noracle`kcbchg1+0xe2\noracle`ktuchg2+0x911\noracle`ktbchg2+0x113\noracle`kdtchg+0x477\noracle`kdtwrp+0xac3\noracle`kdtInsRow<\/span>+0x389\noracle`qerltcNoKdtBufferedInsRowCBK+0x16d\noracle`qerltcSingleRowLoad+0x137\noracle`qerltcFetch+0x1dc\noracle`insexe+0x33e\noracle`opiexe+0x1d8d\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`kpoodrc+0x26\noracle`rpiswu2+0x2d6\noracle`kpoodr+0x2bb\noracle`upirtrc+0x1089\noracle`kpurcsc+0x6e\n\nkcbklbc[us]: 2<\/span>\noracle`kcbklbc+0x3a1\noracle`kcbchg1_main+0x1b7f\noracle`kcbchg1+0xe2\noracle`ktucmt+0xcfe\noracle`ktcCommitTxn_new+0x402\noracle`ktcCommitTxn<\/span>+0x5b\noracle`audend+0x79\noracle`auddft_internal+0xf6f\noracle`audStatement+0x951\noracle`kpolnb+0x3ef0\noracle`kpoauth+0x419\noracle`opiodr+0x439\noracle`ttcpip+0x5f3\noracle`opitsk+0x9ec\noracle`opiino+0x4a8\noracle`opiodr+0x439\noracle`opidrv+0x33f\noracle`sou2o+0x97\noracle`opimai_real+0x121\noracle`ssthrdmain+0x26b\n\nkcbklbc[us]: 5011<\/span>\noracle`kcbklbc+0x3a1\noracle`kcbchg1_main+0x1b7f\noracle`kcbchg1+0xe2\noracle`ktuchg2+0x911\noracle`ktbchg2+0x113\noracle`kdu_array_flush_retry+0xc6d\noracle`kdu_array_flush1+0x50\noracle`qerupFetch+0x45c\noracle`updaul+0x678\noracle`updThreePhaseExe+0x14e\noracle`updexe<\/span>+0x1ec\noracle`opiexe+0x30fc\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`kpoodrc+0x26\noracle`rpiswu2+0x2d6\noracle`kpoodr+0x2bb\noracle`upirtrc+0x1089\noracle`kpurcsc+0x6e\noracle`kpuexec+0x1e9a<\/code><\/pre>\nOctober 12th, 2020<\/h2>\n
kcrfw_redo_gen_ext<\/h3>\n
MTTR Advisor<\/h3>\n
References<\/h1>\n
\n