Private strands reduce contention on the public redo log buffer. Without them a process would have to write to public redo buffer more frequently and compete with other processes. [1]<\/a><\/p>\n Message Advanced Queues (AQ) and alerts can prevent processes from using private strands.<\/p>\n For example, the following transaction isn’t using private strands:<\/p>\n x$ktcxb<\/i> is the SQL interface to the transaction table. The un<\/ins>set 13th bit of the bitmap ktcxbflg<\/i> indicates that the transaction is using a private strand.<\/p>\n In-memory undo (IMU) buffer is a prerequisite for using a private strand [2]<\/a>. But in my case, the process couldn’t allocate it:<\/p>\n x$ktifp<\/i> externalizes the IMU pool:<\/p>\n All IMU buffers are currently occupied – none of them has ktifptxflg<\/i> set to zero.<\/p>\n According to v$transaction<\/i> there aren’t any open transactions:<\/p>\n But who then has allocated all IMU buffers?<\/p>\n To answer this question, I selected transactions from the fixed table x$ktcxb<\/i> instead of v$transaction<\/i>. I also joined the result with the IMU buffer fixed table x$ktifp<\/i> and v$session<\/i>:<\/p>\n The transactions above look strange:<\/p>\n It’s unusual to leave the 2nd bit of ktcxbflg<\/i> unset. v$transaction<\/i>, by the way, filters such transactions out:<\/p>\n Let’s compare the transactions above with a regular transaction:<\/p>\n The 2nd bit of ktcxbflg<\/i> is set, and the transaction is using some redo space.<\/p>\n What has produced the transactions holding the IMU buffers?<\/p>\n Based on the wait events pipe get<\/i> and Streams AQ: waiting for messages in the queue<\/i> we can conclude that the sessions have been involved in inter-process communication. The errorstack for these wait events provides more details.<\/p>\n The PL\/SQL process was waiting on an AQ.<\/p>\n We can reproduce this behavior with the test case from the Tim Hall’s tutorial<\/a>:<\/p>\n There were no incoming messages. Simply put, the dequeue procedure creates a transaction and allocates an IMU buffer. This transaction remains open during the whole waiting time.<\/p>\n This process was waiting for an alert.<\/p>\n Also here, we can easily reproduce the behavior:<\/p>\n Similarly, the session holds the allocated IMU buffer while waiting for an alert.<\/p>\n In both cases, the session is waiting for an incoming message\/alert. Even though it’s an idle wait, the process started a pseudo-transaction which allocated 72 bytes in the IMU buffer. It’s a non-obvious and undocumented behavior. Many such processes could use up the IMU pool. Consequently, “real” transactions wouldn’t be able to use private strands.<\/p>\n The banking application Avaloq is particularly at risk as it heavily relies on AQ and alerts. For example, our production database has more than 350 job queue processes waiting for a message.<\/p>\n We need enough IMU buffers to handle the peak load. The number of IMU buffers can’t be explicitly specified. It’s rather derived from the transactions<\/i> parameter (#IMU buffers = 0.1 * transactions<\/i>).<\/p>\n There is another undocumented quirk related to public redo buffers. A process sometimes counts dirty buffers on all working data sets while holding a redo copy latch to prepare the information for the MTTR advisor. As the number of working data sets equals the number of CPUs, larger servers suffer more. [3]<\/a><\/p>\n Our primary goal is to reduce public redo buffer writes. But you can disable the MTTR advisor to alleviate the redo copy latch contention, until increasing the transactions<\/i> parameter.<\/p>\n We’ve been occasionally hitting ORA-00600: [krcput_overwrite]. The affected Avaloq test databases had the transactions parameter set so low, that processes weren’t using private strands.<\/p>\n The error has being thrown in the Oracle function krcput<\/i>:<\/p>\n krcput<\/i> writes changed block addresses into the block change tracking buffer [4]<\/a>, and its caller kcrfw_redo_gen_ext<\/i> copies changes to the public redo buffer. [5]<\/a><\/p>\n According to the support note Bug 30295790 – DB Crashes with ORA-00600 [krcput_overwrite] (Doc ID 30295790.8)<\/i> it’s a concurrency issue: “DBA buffers are updated by CTWR as well as multiple foreground process to read and write krcpe entries in it.”<\/p>\n In other words, the problem occurs during concurrent writes to the public redo log buffer. Private strands reduce these calls, and help avoid the bug.<\/p>\n Private strands reduce contention on the public redo buffer and improve scalability. A process that hasn’t allocated an IMU buffer can’t use private strands.<\/p>\n A process waiting for an AQ message or an alert allocates an IMU buffer and holds it while waiting. Many such processes could use up the IMU pool. That would prevent other sessions from using private strands, and cause performance issues. This problem is worse on servers with more CPUs, because the MTTR advisor code protected by redo copy latch takes more time to complete.<\/p>\n The banking application Avaloq needs a thorough consideration, because it configures many background job queue processes to wait for AQ messages and alerts. Set the transactions<\/i> parameter high enough to ensure that private strands are being used during the peak load.<\/p>\n A correction: The unset (not the set) 13th bit in x$ktcxb.ktcxbflg indicates that the private strands are being used. Thanks to Kun Sun<\/a> for pointing this out.<\/p>\n The fix for the bug 30295790 DB Crashes with ORA-00600 [krcput_overwrite]<\/i> is included in 19.9 19.9.0.0.DBRU:201020 (OCT 2020).<\/p>\n","protected":false},"excerpt":{"rendered":" A process waiting on an Advanced Queue or alert allocates an in-memory undo buffer and holds it as long as it’s waiting, even when there aren’t any incoming mesages. Many such processes can prevent private strands usage.create table t (n number);\ninsert into t values (1);\n\nselect decode(bitand(ktcxbflg, 4096),0,1,0) used_private_strand\n from x$ktcxb, v$session\n where ktcxbses = saddr and sid = userenv('sid');\n\nUSED_PRIVATE_STRAND\n-------------------\n 0<\/code><\/pre>\nIn-memory undo buffers<\/h1>\n
select n.name, s.value from v$statname n, v$sesstat s \n where n.statistic# = s.statistic# and s.sid = userenv('SID') \n and n.name like '%IMU%' and value != 0 ;\n\nNAME VALUE\n---------------------------------------------------------------- ----------\nIMU pool not allocated 1<\/code><\/pre>\nselect ktifptxflg, count(*) from x$ktifp group by ktifptxflg ;\n\nKTIFPTXFLG COUNT(*)\n---------- ----------\n 7 64\n 1 107<\/code><\/pre>\nselect count(*) from v$transaction ;\n\n COUNT(*)\n----------\n 0<\/code><\/pre>\ncolumn sid format 9999\ncolumn minutes format 9999999\ncolumn program format a23\ncolumn event format a48\n\nselect \n sid, \n round(( sysdate - to_date(ktcxbstm,'mm\/dd\/rr hh24:mi:ss') ) * 24 * 60) \n minutes, \n decode(bitand(ktcxbflg,2),2,1,0) bit2,\n to_number(ktifprpc,'xxxxxxxxxxxxxxxx') -\n to_number(ktifprpb,'xxxxxxxxxxxxxxxx') redo_bytes,\n to_number(ktifpupc, 'xxxxxxxxxxxxxxxx') - \n to_number(ktifpupb, 'xxxxxxxxxxxxxxxx') undo_bytes,\n program, \n event\n from x$ktifp, x$ktcxb, v$session ses \n where ktifpxcb = ktcxbxba and ktcxbses = saddr\n order by ktcxbstm desc ;\n\n SID MINUTES BIT2 REDO_BYTES UNDO_BYTES PROGRAM EVENT\n----- -------- ----- ---------- ---------- ----------------------- ------------------------------------------------\n...\n 1536 47 0 0 72 oracle@serverxx (J07T) Streams AQ: waiting for messages in the queue\n 333 47 0 0 72 oracle@serverxx (J08S) Streams AQ: waiting for messages in the queue\n 1098 47 0 0 72 oracle@serverxx (J06I) Streams AQ: waiting for messages in the queue\n 98 47 0 0 72 oracle@serverxx (J089) Streams AQ: waiting for messages in the queue\n 1462 47 0 0 72 oracle@serverxx (J03X) Streams AQ: waiting for messages in the queue\n 730 47 0 0 72 oracle@serverxx (J02N) Streams AQ: waiting for messages in the queue\n 787 47 0 0 72 oracle@serverxx (J02T) Streams AQ: waiting for messages in the queue\n 839 47 0 0 72 oracle@serverxx (J07Z) Streams AQ: waiting for messages in the queue\n 1422 47 0 0 72 oracle@serverxx (J03V) Streams AQ: waiting for messages in the queue\n 114 47 0 0 72 oracle@serverxx (J07R) Streams AQ: waiting for messages in the queue\n 55 47 0 0 72 oracle@serverxx (J07Y) Streams AQ: waiting for messages in the queue\n 1343 47 0 0 72 oracle@serverxx (J07M) pipe get\n 54 47 0 0 72 oracle@serverxx (J01E) Streams AQ: waiting for messages in the queue\n 1425 47 0 0 72 oracle@serverxx (J010) Streams AQ: waiting for messages in the queue\n 394 47 0 0 72 oracle@serverxx (J04Z) Streams AQ: waiting for messages in the queue\n 918 47 0 0 72 oracle@serverxx (J00C) Streams AQ: waiting for messages in the queue\n 593 47 0 0 72 oracle@serverxx (J002) Streams AQ: waiting for messages in the queue\n 1265 47 0 0 72 oracle@serverxx (J06Y) Streams AQ: waiting for messages in the queue\n 1216 47 0 0 72 oracle@serverxx (J04C) Streams AQ: waiting for messages in the queue\n 177 47 0 0 72 oracle@serverxx (J068) Streams AQ: waiting for messages in the queue\n 809 47 0 0 72 oracle@serverxx (J008) Streams AQ: waiting for messages in the queue\n 1436 47 0 0 72 oracle@serverxx (J07L) Streams AQ: waiting for messages in the queue\n 1496 47 0 0 72 oracle@serverxx (J02L) Streams AQ: waiting for messages in the queue\n 665 47 0 0 72 oracle@serverxx (J02H) Streams AQ: waiting for messages in the queue\n\n SID MINUTES BIT2 REDO_BYTES UNDO_BYTES PROGRAM EVENT\n----- -------- ----- ---------- ---------- ----------------------- ------------------------------------------------\n 1120 47 0 0 72 oracle@serverxx (J03W) Streams AQ: waiting for messages in the queue\n 496 47 0 0 72 oracle@serverxx (J029) Streams AQ: waiting for messages in the queue\n 1176 47 0 0 72 oracle@serverxx (J01T) Streams AQ: waiting for messages in the queue\n 1523 47 0 0 72 oracle@serverxx (J020) Streams AQ: waiting for messages in the queue\n 1366 47 0 0 72 oracle@serverxx (J08V) Streams AQ: waiting for messages in the queue\n 355 47 0 0 72 oracle@serverxx (J04Y) Streams AQ: waiting for messages in the queue\n 1470 47 0 0 72 oracle@serverxx (J03Y) Streams AQ: waiting for messages in the queue\n 1202 47 0 0 72 oracle@serverxx (J00K) Streams AQ: waiting for messages in the queue\n 641 48 0 0 72 oracle@serverxx (J02K) Streams AQ: waiting for messages in the queue\n 573 48 0 0 72 oracle@serverxx (J02E) Streams AQ: waiting for messages in the queue\n 41 48 0 0 72 oracle@serverxx (J01F) Streams AQ: waiting for messages in the queue\n 487 48 0 0 72 oracle@serverxx (J03J) Streams AQ: waiting for messages in the queue\n 1407 108 0 0 72 oracle@serverxx (J046) pipe get\n 1448 108 0 0 72 oracle@serverxx (J012) pipe get\n 1291 108 0 0 72 oracle@serverxx (J06V) pipe get\n 864 108 0 0 72 oracle@serverxx (J08Z) pipe get\n 850 108 0 0 72 oracle@serverxx (J08P) pipe get\n\n SID MINUTES BIT2 REDO_BYTES UNDO_BYTES PROGRAM EVENT\n----- -------- ----- ---------- ---------- ----------------------- ------------------------------------------------\n 1368 468 0 0 72 oracle@serverxx (J03R) pipe get\n 1457 468 0 0 72 oracle@serverxx (J071) Streams AQ: waiting for messages in the queue\n 1201 468 0 0 72 oracle@serverxx (J06G) PL\/SQL lock timer\n 1136 468 0 0 72 oracle@serverxx (J036) Streams AQ: waiting for messages in the queue\n 1189 468 0 0 72 oracle@serverxx (J03B) pipe get\n 1174 468 0 0 72 oracle@serverxx (J03A) pipe get\n 1162 468 0 0 72 oracle@serverxx (J06D) pipe get\n 1145 468 0 0 72 oracle@serverxx (J038) pipe get\n 521 468 0 0<\/span> 72 oracle@serverxx (J000) pipe get\n\n171 rows selected.<\/code><\/pre>\n\n
ktcxbflg<\/h1>\n
BITAND (ktcxbflg, 2) != 0<\/code><\/pre>\ninsert into t values (1);\n\n SID MINUTES BIT2 REDO_BYTES UNDO_BYTES PROGRAM EVENT\n----- -------- ---------- ---------- ---------- ----------------------- ------------------------------------------------\n 257 0 1 572<\/span> 576 sqlplus@svdbp01i (TNS V PGA memory operation\n 1-V3)<\/code><\/pre>\nInter-process communication<\/h1>\n
AQ<\/h2>\n
ALTER session SET EVENTS 'wait_event[\"Streams AQ: waiting for messages in the queue\"] {occurence:end_after 100} errorstack()';<\/code><\/pre>\n----- PL\/SQL Call Stack -----\n object line object\n handle number name\nc1a5e6e0 750 package body SYS.DBMS_AQ.DEQUEUE<\/span>\nc31eb7a0 2859 package body K.MSG_EXTL#.GET_NEXT_IN_MSG\nc33f9130 489 package body K.MSG_IN#.GET_NEXT_MSG\nc6fdb388 1215 procedure K.BGP_MSG_IN\nc6fdb388 1404 procedure K.BGP_MSG_IN\nbfb9fa78 1 anonymous block<\/code><\/pre>\nDECLARE\n l_dequeue_options DBMS_AQ.dequeue_options_t;\n l_message_properties DBMS_AQ.message_properties_t;\n l_message_handle RAW(16);\n l_event_msg event_msg_type;\nBEGIN\n DBMS_AQ.dequeue(queue_name => 'event_queue',\n dequeue_options => l_dequeue_options,\n message_properties => l_message_properties,\n payload => l_event_msg,\n msgid => l_message_handle);\nEND;\n\/<\/code><\/pre>\n SID MINUTES BIT2 REDO_BYTES UNDO_BYTES PROGRAM EVENT\n----- -------- ---------- ---------- ---------- ----------------------- ------------------------------------------------\n 265 2 0 0 72 sqlplus@svdbp01i (TNS V Streams AQ: waiting for messages in the queue\n 1-V3)<\/code><\/pre>\nAlerts<\/h2>\n
ALTER session SET EVENTS 'wait_event[\"pipe get\"] {occurence:end_after 100} errorstack()'<\/code><\/pre>\nc2e8a078 169 package body SYS.DBMS_PIPE.RECEIVE_MESSAGE\nc42bdc00 165 package body SYS.DBMS_ALERT.PIPE_WAIT\nc42bdc00 363 package body SYS.DBMS_ALERT.WAITONE<\/span><\/code><\/pre>\ndeclare\n L_MSG VARCHAR2(240);\n l_status pls_integer ;\nbegin\n DBMS_ALERT.WAITONE('TEST2', L_MSG, L_STATUS, 1000);\n insert into t values(1);\nend;<\/code><\/pre>\nexec DBMS_ALERT.SIGNAL('TEST2', 'message_text2'); \ncommit;<\/code><\/pre>\n SID MINUTES BIT2 REDO_BYTES UNDO_BYTES PROGRAM EVENT\n----- -------- ---------- ---------- ---------- ----------------------- ------------------------------------------------\n 265 1 0 0 72 sqlplus@svdbp01i (TNS V pipe get\n 1-V3)<\/code><\/pre>\nIs it a bug or a feature?<\/h2>\n
Avaloq<\/h1>\n
MTTR advisor<\/h1>\n
ORA-00600: [krcput_overwrite]<\/h1>\n
...\nkrcput()+2249 call ksesin() 008C173D0 ? 000000004 ?\n 000000000 ? 00000003E ?\n 000000000 ? 00000003E ?\nkcrfw_redo_gen_ext( call krcput() 091ED0FD8 ? 7FFFBFFF18F8 ?\n)+22019 7FFFBFFF24C0 ? 000000000 ?\n 000000002 ? 00000003E ?\nkcbchg1_main()+7114 call kcrfw_redo_gen_ext( 000000002 ? 7FFFBFFF24C0 ?\n ) 7FFFBFFF2480 ? 000000000 ?\n 7FFFBFFF2188 ? 7FFFBD869CD0 ?\nkcbchg()+482 call kcbchg1_main() 000000008 ? 000000002 ?\n 000000037 ? 7FFFBFFF2DB0 ?\n 7FFFBFFF2E00 ? 000000000 ?\nktuapundo()+497 call kcbchg() 000000008 ? 000000002 ?\n...<\/code><\/pre>\nSummary<\/h1>\n
References<\/h1>\n
\n
Updates<\/h1>\n
October 10, 2020<\/h2>\n
October 23, 2020<\/h2>\n
\n Continue Reading