首页 > 代码库 > 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。