Hi Jay,
sorry for answering so late, but i was pretty busy the last few days. However
you are also right about MOS ID #1185093.1 - it just disables the log
entries, but it is also "normal" to have some (tiny) time drifts, especially in
virtualized environments.
In your situation it is important to find out what value is wrong (and what has
gone wrong), but this is pretty hard to troubleshoot without access to
your system and debugging / testing stuff. In addition i only have a 12.1.0.2
RDBMS on Solaris in my lab (for DTrace) and i am pretty sure that the
implementation has changed slightly.
You can also use GDB to dump the corresponding values when your query shows the
wrong results. Here is just a tiny example from my lab with 11g R2 on
Linux (PID 2502 is SID 94 - the query that shows the wrong results in your
case).
SYS@T11DB:167> select ksmfsnam, ksmfsadr, ksmfssiz from x$ksmfsv where ksmfsnam
like '%ksudbrmseccnt%';
KSMFSNAM KSMFSADR
KSMFSSIZ
----------------------------------------------------------------
---------------- ----------
ksudbrmseccnt_
000000006000ABA0 4
T11DB [oracle@OEL scripts]$ ps -fu oracle
UID PID PPID C STIME TTY TIME CMD
oracle 2502 1 0 15:10 ? 00:00:00 oracleT11DB (LOCAL=NO)
(gdb) attach 2502
(gdb) break __gettimeofday
(gdb) commands
silent(gdb) continue
x/w 0x6000ABA0
continue
end
Jay Hostetter <hostetter.jay@xxxxxxxxx> hat am 23. September 2015 um 17:39--
geschrieben:
Stefan,
I first saw the issue in this database around 5:41 pm on 9/17 (give or
take a few minutes based on the monitoring script). Here is a glimpse of
the trace file at that time:
*** 2015-09-13 21:20:56.785
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time jumped forward by
(2486888)usec at (1442193656785390) whereas (1000000) is allowed
*** 2015-09-13 21:20:59.796
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time jumped forward by
(2302344)usec at (1442193659796615) whereas (1000000) is allowed
*** 2015-09-13 21:21:02.152
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time jumped forward by
(1707628)usec at (1442193662152364) whereas (1000000) is allowed
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time stalled at
1442529387154649
*** 2015-09-17 17:36:10.826
kstmchkdrift (kstmhighrestimecntkeeper:highres): Stall, backward drift ended
at 1442529387194058 drift: 39409
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(3615)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(3609)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(3603)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(3597)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(3591)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(3585)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(3579)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(3573)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(3567)microsecs at 1442529386
The "Time moved backward" messages continue until 9/20. At which point I
see this:
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(7)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Time moved backward by
(1)microsecs at 1442529386
kstmchkdrift (kstmhighrestimecntkeeper:lowres): Stall, backward drift ended
at 1442529387 drift: 1
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time jumped forward by
(7254467)usec at (1442798339931054) whereas (1000000) is allowed
*** 2015-09-20 20:28:34.040
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time jumped forward by
(1116348)usec at (1442798930408237) whereas (1000000) is allowed
*** 2015-09-20 20:28:35.358
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time jumped forward by
(1153249)usec at (1442798931725990) whereas (1000000) is allowed
*** 2015-09-20 20:28:42.326
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time jumped forward by
(1365489)usec at (1442798938694604) whereas (1000000) is allowed
No other messages appear after 9/20.
I see note 1185093.1 talks about a bug for time drift, but the fix appears
to simply disable the message.
Thank you,
Jay
