Here’s what I learned while troubleshooting stale v$transaction.start_time<\/i> entries.<\/p>\nReading transaction information<\/h1>\n
This section describes the mechanism behind select start_time from v$transaction<\/i>.<\/p>\nv$transaction<\/i><\/h2>\n
start_time<\/i> and start_date<\/i> contain the same information stored in different data types – varchar2<\/i> and date<\/i>, respectively.<\/p>\n v$transaction<\/i> is underpinned by x$ktcxb<\/i>:<\/p>\n ktcxbstm<\/i> and to_date(ktcxbstm)<\/i> in x$ktcxb<\/i> are mapped to start_time<\/i> and start_date<\/i>, respectively, in v$transaction<\/i>: Every time we select from x$ktcxb<\/i> the Oracle C function ktcxbc<\/i> populates the information in UGA :<\/p>\n In other words, ktcxb<\/i> is the helper function [1]<\/a> for x$ktcxb<\/i>.<\/p>\n The function ktcxb<\/i> reads the information from the transaction table, and stores the address of the transaction table entry in x$ktcxb.ktcxbxba<\/i>.<\/p>\n start_time<\/i> in Epoch format is stored at the location ktcxbxba<\/span>+0x7c8<\/i> (on 19c) in the transaction table:<\/p>\n (1599556843 is Epoch time for September 8, 2020 11:20:43 AM GMT+02:00 DST.)<\/p>\n The helper function ktcxb<\/i> calls slcts<\/i> to convert the Epoch time to the human readable format:<\/p>\n slcts<\/i> first calls localtime_r<\/i> to convert the Epoch time to the local time. Then it calls sprintf<\/i> to format it to the human readable format.<\/p>\n The Epoch timestamp is passed through the first argument:<\/p>\n The returned address points to the formatted date:<\/p>\n This section describes how the server process populates the start_time<\/i> when a user session creates a transaction.<\/p>\n Interestingly, the server process doesn’t call the OS timestamp function. It reads instead the global SGA variable ksudbrmseccnt_<\/i> (“seconds counter”). This variable holds the current timestamp.<\/p>\n The Oracle function ktcAllocXcb<\/i> reads the variable and puts it into the transaction table entry:<\/p>\n ksudbrmseccnt_<\/i> increases every second:<\/p>\n The background process vktm<\/i> maintains the global SGA variable ksudbrmseccnt_<\/i> by calling the kstmrmtickcntkeeper<\/i> function:<\/p>\n Consequently, if you see an old v$transaction.start_time<\/i>, examine vktm<\/i> with pstack<\/i> and truss<\/i>. I, for example, have found couple of databases where vktm<\/i> was stuck in the nanosleep<\/i> system call:<\/p>\n As a result, start_time<\/i> was in the past.<\/p>\n It was an OS issue, but the knowledge about the database internals helped me pinpoint this problem.<\/p>\n It seems unusual that a server process of a user session doesn’t call the OS timestamp function for getting a transaction start time. It rather reads the location in the SGA (ksudbrmseccnt_<\/i> – “seconds counter”) which stores the current timestamp in seconds. The background process vktm<\/i> maintains that counter.<\/p>\n On the one hand, a single CPU instruction is much more efficient than a local timestamp function call. Besides that, vktm<\/i> updates the timestamp just once per second, so it stays on CPU only very briefly.<\/p>\n On the other hand, a stale counter remains unnoticed.<\/p>\n In conclusion, v$transaction.start_time<\/i> is a low-resolution value maintained on a best-effort basis at a very low cost. It primarily exists for monitoring and is probably not used internally by the database.<\/p>\n [1]<\/a> Tanel Poder, Oracle X$ tables \u2013 Part 1 \u2013 Where do they get their data from?.<\/i> January 10, 2014.<\/p>\n The root cause is the following new bug: 31716314 : poll\/nanosleep waits weeks when passed 0.01 second timer values passed<\/i>. Oracle issued the following support note for this case: A process issuing a poll\/nanosleep with 0.01 second timer value waits weeks (Doc ID 2732367.1)<\/i>.<\/p>\n","protected":false},"excerpt":{"rendered":" Troubleshooting wrong v$transaction.start_time entries. Undocumented internals on how Oracle populates x$ktcxb. Continue Reading desc v$transaction ;\n Name Null? Type\n ----------------------------------------- -------- ----------------------------\n...\n START_TIME VARCHAR2(20)\n...\n START_DATE DATE\n...\n\nSTART_TIME START_DATE\n-------------------- -------------------\n09\/08\/20 11:20:43 08.09.2020 11:20:43<\/code><\/pre>\nx$ktcxb<\/i><\/h2>\n
select addr,ktcxbxba,ktcxbstm \n from x$ktcxb WHERE BITAND (ksspaflg, 1) != 0 AND BITAND (ktcxbflg, 2) != 0 ;\n\nADDR KTCXBXBA<\/span> KTCXBSTM\n---------------- ---------------- --------------------\n00007FFFBD880AF8<\/span> 0000000096D95C70<\/span> 09\/08\/20 11:20:43<\/code><\/pre>\n
\nx$ktcxb<\/i> is stored in UGA:<\/p>\n@fcha 0x00007FFFBD880AF8<\/span>\n\nLOC KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR\n--- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ----------------\nUGA<\/span> 00007FFFBD880678 kxsFrame4kPage 4152 freeabl 0 00<\/code><\/pre>\nktcxbc<\/i><\/h2>\n
#0 0x00007ffc0c958120 in memcpy () from \/lib\/64\/libc.so.1\n#1 0x000000000a2f77b0 in ktcxbc ()\n#2 0x000000000676348f in qerfxFetch ()\n#3 0x00000000065c58a8 in opifch2 ()<\/code><\/pre>\n@fcha<\/a> 0000000096D95C70<\/span>\n\nLOC KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR\n--- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ----------------\nSGA<\/span> 0000000096D95A90 1 1 transaction<\/span> 21328 perm 0 0000000096CD0200<\/code><\/pre>\n(gdb) p\/d *(uint32_t)(0x0000000096D95C70<\/span>+0x7c8)\n$2 = 1599556843<\/code><\/pre>\nslcts<\/i><\/h1>\n
#0 0x000000001a710983 in slcts ()\n#1 0x000000000a2f7353 in ktcxbcProcessInPDB ()\n#2 0x000000000a2f7823 in ktcxbc ()\n#3 0x000000000676348f in qerfxFetch ()\n#4 0x00000000065c58a8 in opifch2 ()<\/code><\/pre>\nThread 2 hit Breakpoint 2, 0x000000001a710900 in slcts ()\n(gdb) p $rdi\n$3 = 1599556843<\/code><\/pre>\n(gdb)fin\nRun till exit from #0 0x000000001a710900 in slcts ()\n0x000000000a2f7353 in ktcxbcProcessInPDB ()\n(gdb) x\/s $rax\n0x7fffbd880f34: \"09\/08\/20 11:20:43\"<\/code><\/pre>\nPopulating transaction information<\/h1>\n
ksudbrmseccnt_<\/i><\/h2>\n
select ksmfsnam, ksmfsadr, ksmfssiz, ksmfstyp from x$ksmfsv where ksmfsadr like '0000000060008398' ;\n\nKSMFSNAM KSMFSADR KSMFSSIZ KSMFSTYP\n---------------------------------------------------------------- ---------------- ---------- ----------------------------------------------------------------\nksudbrmseccnt_ 0000000060008398 4 ub4<\/code><\/pre>\n#0 0x00000000063caf2d in ktcAllocXcb ()\n#1 0x000000000668e43b in ktaiam ()\n#2 0x000000000623c262 in ktagetg0 ()\n#3 0x000000000623b0d4 in ktagetp_internal ()\n#4 0x000000000668d9cd in ktagdw ()\n#5 0x0000000006544d7e in ktaadm ()\n#6 0x000000000653c2cb in kksfbc ()\n#7 0x000000000603c1d3 in opiexe ()\n#8 0x00000000066926da in kpoal8 ()\n#9 0x000000000602d6c9 in opiodr ()\n#10 0x0000000006037303 in ttcpip ()\n#11 0x0000000006032cfc in opitsk ()\n#12 0x0000000006031818 in opiino ()\n#13 0x000000000602d6c9 in opiodr ()\n#14 0x000000000602cc8f in opidrv ()\n#15 0x000000000602c8c7 in sou2o ()\n#16 0x000000000602c711 in opimai_real ()\n#17 0x000000000602c1eb in ssthrdmain ()\n#18 0x000000000602bf59 in main ()<\/code><\/pre>\n(gdb) p\/d *(uint32_t)0x60008398\n$3 = 1599573789\n(gdb)\n$4 = 1599573790\n(gdb)\n$6 = 1599573791\n(gdb)\n$7 = 1599573792\n(gdb)\n$8 = 1599573793<\/code><\/pre>\nvktm\/kstmrmtickcntkeeper<\/i><\/h2>\n
#0 0x00000000074a5478 in kstmrmtickcntkeeper ()\n#1 0x00000000074a4844 in kstmmainvktm ()\n#2 0x000000000720dd21 in ksbrdp ()\n#3 0x0000000006e14599 in opirip ()\n#4 0x000000000602cab0 in opidrv ()\n#5 0x000000000602c8c7 in sou2o ()\n#6 0x000000000602c694 in opimai_real ()\n#7 0x000000000602c1eb in ssthrdmain ()\n#8 0x000000000602bf59 in main ()<\/code><\/pre>\npstack 14583\n14583: ora_vktm_DB1\n 00007fff93c76eba nanosleep (7fffbfffc7d0, 7fffbfffc7e0)\n 00000000072f3e9a sltrusleep () + 6a\n 000000000758b994 kstmrmtickcntkeeper () + 5a4\n 000000000758b1f4 kstmmainvktm () + 194\n 00000000072f5869 ksbrdp () + 9a9\n 0000000006efc489 opirip () + 2b9\n 0000000006118950 opidrv () + 160\n 0000000006118767 sou2o () + 97\n 0000000006118534 opimai_real () + a4\n 000000000611808b ssthrdmain () + 26b\n 0000000006117df9 main () + a9\n 0000000007771e34 ???????? ()\n\ntruss -f -p 14583\n14583: nanosleep(0x7FFFBFFFC7D0, 0x7FFFBFFFC7E0) (sleeping...)<\/code><\/pre>\nConclusion<\/h1>\n
References<\/h1>\n
Updates<\/h1>\n
Solaris OS Bug – November 3, 2020<\/h2>\n
\nIt has been a remarkable service by Oracle Solaris Support. After reproducing the problem with a simple C program, it took only a couple of weeks to identify the problem, file a new bug, include in the latest SRU (SRU27).<\/p>\nOracle Support Note – March 15, 2021<\/h2>\n