Here’s what I learned while troubleshooting stale v$transaction.start_time entries.

Reading transaction information

This section describes the mechanism behind select start_time from v$transaction.

v$transaction

start_time and start_date contain the same information stored in different data types – varchar2 and date, respectively.

desc v$transaction ;
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
...
 START_TIME                                         VARCHAR2(20)
...
 START_DATE                                         DATE
...

START_TIME           START_DATE
-------------------- -------------------
09/08/20 11:20:43    08.09.2020 11:20:43

x$ktcxb

v$transaction is underpinned by x$ktcxb:

select addr,ktcxbxba,ktcxbstm 
  from x$ktcxb WHERE BITAND (ksspaflg, 1) != 0 AND BITAND (ktcxbflg, 2) != 0 ;

ADDR             KTCXBXBA         KTCXBSTM
---------------- ---------------- --------------------
00007FFFBD880AF8 0000000096D95C70 09/08/20 11:20:43

ktcxbstm and to_date(ktcxbstm) in x$ktcxb are mapped to start_time and start_date, respectively, in v$transaction:
x$ktcxb is stored in UGA:

@fcha 0x00007FFFBD880AF8

LOC KSMCHPTR           KSMCHIDX   KSMCHDUR KSMCHCOM           KSMCHSIZ KSMCHCLS   KSMCHTYP KSMCHPAR
--- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ----------------
UGA 00007FFFBD880678                       kxsFrame4kPage         4152 freeabl           0 00

ktcxbc

Every time we select from x$ktcxb the Oracle C function ktcxbc populates the information in UGA :

#0  0x00007ffc0c958120 in memcpy () from /lib/64/libc.so.1
#1  0x000000000a2f77b0 in ktcxbc ()
#2  0x000000000676348f in qerfxFetch ()
#3  0x00000000065c58a8 in opifch2 ()

In other words, ktcxb is the helper function [1] for x$ktcxb.

The function ktcxb reads the information from the transaction table, and stores the address of the transaction table entry in x$ktcxb.ktcxbxba.

@fcha 0000000096D95C70

LOC KSMCHPTR           KSMCHIDX   KSMCHDUR KSMCHCOM           KSMCHSIZ KSMCHCLS   KSMCHTYP KSMCHPAR
--- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ----------------
SGA 0000000096D95A90          1          1 transaction           21328 perm              0 0000000096CD0200

start_time in Epoch format is stored at the location ktcxbxba+0x7c8 (on 19c) in the transaction table:

(gdb) p/d *(uint32_t)(0x0000000096D95C70+0x7c8)
$2 = 1599556843

(1599556843 is Epoch time for September 8, 2020 11:20:43 AM GMT+02:00 DST.)

slcts

The helper function ktcxb calls slcts to convert the Epoch time to the human readable format:

#0  0x000000001a710983 in slcts ()
#1  0x000000000a2f7353 in ktcxbcProcessInPDB ()
#2  0x000000000a2f7823 in ktcxbc ()
#3  0x000000000676348f in qerfxFetch ()
#4  0x00000000065c58a8 in opifch2 ()

slcts first calls localtime_r to convert the Epoch time to the local time. Then it calls sprintf to format it to the human readable format.

The Epoch timestamp is passed through the first argument:

Thread 2 hit Breakpoint 2, 0x000000001a710900 in slcts ()
(gdb) p $rdi
$3 = 1599556843

The returned address points to the formatted date:

(gdb)fin
Run till exit from #0  0x000000001a710900 in slcts ()
0x000000000a2f7353 in ktcxbcProcessInPDB ()
(gdb) x/s $rax
0x7fffbd880f34: "09/08/20 11:20:43"

Populating transaction information

This section describes how the server process populates the start_time when a user session creates a transaction.

ksudbrmseccnt_

Interestingly, the server process doesn’t call the OS timestamp function. It reads instead the global SGA variable ksudbrmseccnt_ (“seconds counter”). This variable holds the current timestamp.

select ksmfsnam, ksmfsadr, ksmfssiz, ksmfstyp from x$ksmfsv where ksmfsadr like '0000000060008398' ;

KSMFSNAM                                                         KSMFSADR           KSMFSSIZ KSMFSTYP
---------------------------------------------------------------- ---------------- ---------- ----------------------------------------------------------------
ksudbrmseccnt_                                                   0000000060008398          4 ub4

The Oracle function ktcAllocXcb reads the variable and puts it into the transaction table entry:

#0  0x00000000063caf2d in ktcAllocXcb ()
#1  0x000000000668e43b in ktaiam ()
#2  0x000000000623c262 in ktagetg0 ()
#3  0x000000000623b0d4 in ktagetp_internal ()
#4  0x000000000668d9cd in ktagdw ()
#5  0x0000000006544d7e in ktaadm ()
#6  0x000000000653c2cb in kksfbc ()
#7  0x000000000603c1d3 in opiexe ()
#8  0x00000000066926da in kpoal8 ()
#9  0x000000000602d6c9 in opiodr ()
#10 0x0000000006037303 in ttcpip ()
#11 0x0000000006032cfc in opitsk ()
#12 0x0000000006031818 in opiino ()
#13 0x000000000602d6c9 in opiodr ()
#14 0x000000000602cc8f in opidrv ()
#15 0x000000000602c8c7 in sou2o ()
#16 0x000000000602c711 in opimai_real ()
#17 0x000000000602c1eb in ssthrdmain ()
#18 0x000000000602bf59 in main ()

ksudbrmseccnt_ increases every second:

(gdb) p/d  *(uint32_t)0x60008398
$3 = 1599573789
(gdb)
$4 = 1599573790
(gdb)
$6 = 1599573791
(gdb)
$7 = 1599573792
(gdb)
$8 = 1599573793

vktm/kstmrmtickcntkeeper

The background process vktm maintains the global SGA variable ksudbrmseccnt_ by calling the kstmrmtickcntkeeper function:

#0  0x00000000074a5478 in kstmrmtickcntkeeper ()
#1  0x00000000074a4844 in kstmmainvktm ()
#2  0x000000000720dd21 in ksbrdp ()
#3  0x0000000006e14599 in opirip ()
#4  0x000000000602cab0 in opidrv ()
#5  0x000000000602c8c7 in sou2o ()
#6  0x000000000602c694 in opimai_real ()
#7  0x000000000602c1eb in ssthrdmain ()
#8  0x000000000602bf59 in main ()

Consequently, if you see an old v$transaction.start_time, examine vktm with pstack and truss. I, for example, have found couple of databases where vktm was stuck in the nanosleep system call:

pstack 14583
14583:  ora_vktm_DB1
 00007fff93c76eba nanosleep (7fffbfffc7d0, 7fffbfffc7e0)
 00000000072f3e9a sltrusleep () + 6a
 000000000758b994 kstmrmtickcntkeeper () + 5a4
 000000000758b1f4 kstmmainvktm () + 194
 00000000072f5869 ksbrdp () + 9a9
 0000000006efc489 opirip () + 2b9
 0000000006118950 opidrv () + 160
 0000000006118767 sou2o () + 97
 0000000006118534 opimai_real () + a4
 000000000611808b ssthrdmain () + 26b
 0000000006117df9 main () + a9
 0000000007771e34 ???????? ()

truss -f -p 14583
14583:  nanosleep(0x7FFFBFFFC7D0, 0x7FFFBFFFC7E0) (sleeping...)

As a result, start_time was in the past.

It was an OS issue, but the knowledge about the database internals helped me pinpoint this problem.

Conclusion

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_ – “seconds counter”) which stores the current timestamp in seconds. The background process vktm maintains that counter.

On the one hand, a single CPU instruction is much more efficient than a local timestamp function call. Besides that, vktm updates the timestamp just once per second, so it stays on CPU only very briefly.

On the other hand, a stale counter remains unnoticed.

In conclusion, v$transaction.start_time 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.

References

[1] Tanel Poder, Oracle X$ tables – Part 1 – Where do they get their data from?. January 10, 2014.

Updates

Solaris OS Bug – November 3, 2020

The root cause is the following new bug: 31716314 : poll/nanosleep waits weeks when passed 0.01 second timer values passed.
It 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).

Oracle Support Note – March 15, 2021

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).