首页 > 代码库 > Time drift detected

Time drift detected

solaris10上安装了oracle 11.2.0.3的数据库,手工建库以后,发现告警日志里面有个非常有规律的报警信息,每隔76分钟报一次,报警信息如下:

Tue Aug 0503:05:18 2014
Time drift
detected. Please check VKTM trace file for more details.
Tue Aug 05
03:08:48 2014
Starting
background process SMCO
Tue Aug 05
03:08:48 2014
SMCO
started with pid=24, OS id=2446
Tue Aug 05
03:14:35 2014
Stopping
background process CJQ0
Tue Aug 0504:12:34 2014
Time drift
detected. Please check VKTM trace file for more details.
Tue Aug 0505:28:47 2014
Time drift
detected. Please check VKTM trace file for more details.
Tue Aug 0506:44:59 2014
Time drift
detected. Please check VKTM trace file for more details.
Tue Aug 0508:01:26 2014
Time drift
detected. Please check VKTM trace file for more details.
Tue Aug 05
09:17:33 2014
Time drift
detected. Please check VKTM trace file for more details.

 

告警日志提示看trace文件,trace文件内容如下:

[oracle@solaris186:/u01/app/oracle/diag/rdbms/anny/anny/trace]$
cat anny_vktm_2378.trc
Trace file
/u01/app/oracle/diag/rdbms/anny/anny/trace/anny_vktm_2378.trc
Oracle
Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the
Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME
= /u01/app/oracle/product/11.2.0/dbhome_1
System
name:    SunOS
Node
name:      solaris186
Release:        5.10
Version:        Generic_142910-17
Machine:        i86pc
Instance
name: anny
Redo
thread mounted by this instance: 0 <none>
Oracle
process number: 4
Unix
process pid: 2378, image: oracle@solaris186 (VKTM)
 
 
***
2014-08-05 02:58:43.036
***
SESSION ID:(4.1) 2014-08-05 02:58:43.036
*** CLIENT
ID:() 2014-08-05 02:58:43.036
***
SERVICE NAME:() 2014-08-05 02:58:43.036
*** MODULE
NAME:() 2014-08-05 02:58:43.036
*** ACTION
NAME:() 2014-08-05 02:58:43.036
 
kstmmainvktm:
succeeded in setting elevated priority
highres_enabled
 
***
2014-08-05 02:58:43.036
VKTM
running at (10)millisec precision with DBRM quantum (100)ms
[Start]
HighResTick = 59404806322
kstmrmtickcnt
= 0 : ksudbrmseccnt[0] = 1407178723
 
***
2014-08-05 03:05:18.798
kstmchkdrift
(kstmhighrestimecntkeeper:highres): Time jumped forward by (1297157)usec at
(59800568177) whereas (1000000) is allowed
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407180887
 
***
2014-08-05 03:34:48.908
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407180888
drift: 1
 
***
2014-08-05 03:35:18.823
kstmchkdrift
(kstmhighrestimecntkeeper:highres): Time jumped forward by (1366639)usec at
(61602594030) whereas (1000000) is allowed
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407183154
 
***
2014-08-05 04:12:35.900
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407183155
drift: 1
 
***
2014-08-05 04:12:51.999
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407183171
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407183172
drift: 1
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407185440
 
***
2014-08-05 04:50:41.947
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407185441
drift: 1
 
***
2014-08-05 04:50:58.972
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407185458
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407185459
drift: 1
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407187727
 
***
2014-08-05 05:28:48.883
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407187728
drift: 1
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407187744
 
***
2014-08-05 05:29:05.931
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407187745
drift: 1
 
***
2014-08-05 05:43:59.944
kstmchkdrift
(kstmhighrestimecntkeeper:highres): Time jumped forward by (1252499)usec at
(69329714522) whereas (1000000) is allowed
kstmchkdrift
(kstmhighrestimecntkeeper:highres): Time jumped forward by (1419573)usec at
(70537192617) whereas (1000000) is allowed
 
***
2014-08-05 06:06:53.993
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407190013
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407190014
drift: 1
 
***
2014-08-05 06:07:11.988
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407190031
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407190032
drift: 1
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407192299
 
***
2014-08-05 06:45:00.927
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407192300
drift: 1
 
***
2014-08-05 06:45:17.960
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407192317
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407192318
drift: 1
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407194588
 
***
2014-08-05 07:23:09.922
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407194589
drift: 1
 
***
2014-08-05 07:23:26.979
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407194606
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407194607
drift: 1
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407196886
 
***
2014-08-05 08:01:27.919
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407196887
drift: 1
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407199171
 
***
2014-08-05 08:39:32.932
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407199172
drift: 1
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Time stalled at 1407201453
 
***
2014-08-05 09:17:34.920
kstmchkdrift
(kstmhighrestimecntkeeper:lowres): Stall, backward drift ended at 1407201454
drift: 1

 

trace文件没有得到有用的信息,但这个信息不影响数据库的使用,查看官方文档说这是一个bug,网上说是因为vktm这个进程每隔一段时间会与ntp server进行对时,但我机器的ntp 服务是没有打开的。

[root@solaris186:/]#
svcs -a ntp  
svcs: -a
ignored when used with arguments.
STATE          STIME    FMRI
disabled       10:30:01 svc:/network/ntp:default

在Oracle Database 11g中,VKTM是一个新增的后台进程。这个进程的含义是:

VKTM (virtual keeper
of time) is responsible for providing a wall-clock time (updated every second)
and reference-time counter (updated every 20 ms and available only when running
at elevated priority).

也就是说,这个进程用于提供一个数据库的时钟,每秒更新;或者作为参考时间计数器,这种方式每20毫秒更新一次,仅在高优先级时可用。

 

通过VKTM进程,数据库可以降低和操作系统的交互,Kamus的解释是:在11g之前所有的Oracle数据库后台或者前台进程如果需要获得当前时间信息,就需要调用操作系统的gettimeofday()函数或者说是相类似的函数。而VKTM进程就是专门用来获得时间信息然后将信息存放在SGA中供其它进程使用,这样其它进程当需要时间信息的时候,只要到SGA的某个内存位置去获得就好,而不用频繁调用gettimeofday()函数。毫无疑问,这样效率会更高。

 

在RAC测试中,Oracle 1.1.0.6版本LMSx进程获取时间信息时,可以从VKTM进程中获益大概70%的速度提升,而11.1.0.7将会更高。同时,因为gettimeofday()函数也引发了很多bug,所以无论是RAC还是NORAC库,都将从VKTM进程中获益。

 

最后结论:

猜测这个bug在所有平台上都有可能触发,由于我机器的ntp服务没有启动,所以vktm进程与ntp服务进行对时,触发了这个bug。如果你机器上有ntp 服务,那么时间差异大的话也会触发这个bug