Re: seconds_in_wait
Date: Wed, 30 Sep 2015 15:31:52 +0200 (CEST)
Message-ID: <1034007513.237880.1443619912455.JavaMail.open-xchange_at_app01.ox.hosteurope.de>
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_at_T11DB:167> select ksmfsnam, ksmfsadr, ksmfssiz from x$ksmfsv where ksmfsnam like '%ksudbrmseccnt%'; KSMFSNAM KSMFSADR KSMFSSIZ
---------------------------------------------------------------- ---------------- ---------- ksudbrmseccnt_ 000000006000ABA0 4 T11DB [oracle_at_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
>x/w 0x6000ABA0
>continue
>end
(gdb) continue
SYS_at_T11DB:179> exec DBMS_LOCK.SLEEP(500);
SYS_at_T11DB:94> select w.kslwtstime
from x$ksuse s, x$ksled e, x$kslwt w
where bitand(s.ksspaflg,1)!=0 and bitand(s.ksuseflg,1)!=0 and s.indx=w.kslwtsid and w.kslwtevt=e.indx and s.indx = 179;
…
0x6000aba0: 1443619017 0x6000aba0: 1443619017 0x6000aba0: 1443619017 … 0x6000aba0: 1443619020 0x6000aba0: 1443619020 0x6000aba0: 1443619020 … 0x6000aba0: 1443619023 0x6000aba0: 1443619023 0x6000aba0: 1443619023
…
Best Regards
Stefan Koehler
Freelance Oracle performance consultant and researcher
Homepage: http://www.soocs.de
Twitter: _at_OracleSK
> Jay Hostetter <hostetter.jay_at_gmail.com> 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
-- http://www.freelists.org/webpage/oracle-lReceived on Wed Sep 30 2015 - 15:31:52 CEST