请教个VKTM问题，在线等待.....

zergduan

yyp2009 发表于 2015-5-27 12:33
补丁啊  有补丁，或设event 规避

这不是补丁的问题~ 根本不是bug。

这是因为操作系统管理员，违反调整时间的规则造成的，没有任何补丁能解决这个问题，因为向前调整时间对于oracle应用是不允许的

yyp2009

zergduan 发表于 2015-5-27 13:28
这不是补丁的问题~ 根本不是bug。

这是因为操作系统管理员，违反调整时间的规则造成的，没有任何补丁能 ...

Applies to:
Oracle Database - Enterprise Edition - Version 11.2.0.2 and later
Information in this document applies to any platform.
Goal
Below message keeps repeating in Alert-log.
Time drift detected. Please check VKTM trace file for more details.
Warning: VKTM detected a time drift

This note explains the possible cause and if the issue needs to be addressed or not.
Solution
There are multiple bugs filed for this issue, Some of them follows:
Bug 12601857 - TIME DRIFT DETECTED. PLEASE CHECK VKTM TRACE FILE FOR MORE DETAILS.
Bug 12374867 - TIME DRIFT DETECTED. PLEASE CHECK VKTM TRACE FILE FOR MORE DETAILS.

Which were closed as duplicates of:
Bug 11837095 "TIME DRIFT DETECTED" APPEARS INTERMITTENTLY IN ALERT LOG, THO' EVENT 10795 SET.

To fix the issue, please download and apply patch 11837095 as available for your release/platform. This is available for 11.2.0.2 and above.
NOTE:
Patch 11837095 extends to functionality of event 10795 (set to level 2) for VKTM tracing and limits alert log entries.
After applying the patch, enable event 10795 at level 2:
alter system set event="10795 trace name context forever, level 2" scope=spfile;
Then bounce the instance (shutdown then startup) for the event to be applied.
The permanent fix is planned to be included in the 11.2.0.4 and 12.1 releases.
For version 11.2.0.1, Apply patch for Bug 9843304.  This Bug is already fixed in 11.2.0.2
Meaning and technical Impact of the error:
The time drifts usually occurring less than 1sec and 5 sec for forward and backward respectively are permissible and OK.
If the traces are emitting time drifts of amount beyond these ranges, then it needs to be analyzed.
Most of the times, during high loads, there would be issues with underlying OS due to virtual memory, network time protocol improper configuration etc.

In general VKTM process need to be scheduled in every 10ms, if due to above reasons this is not happening we see the time drifts and to certain level (mentioned above) are permissible.
Eventually, this probably would cause the resource manager to take improper decisions and can lead to a hang in worst case.

VKTM process trace file can be found under bdump, However in this case the trace file doesn't contain useful information, Which makes the message ambiguous.
There are bugs for the VKTM process malfunction
Unpublished Bug 18390507 : EXADATA: VKTM CONSUMING HUGE CPU AFTER PATCHING 11.2.3.3.0 AND 11.2.0.4.3
This Bug is closed as duplicate of Unpublished Bug 18499306
Unpublished Bug 18499306 : DBMX28 DATABASE VKTM PROCESSES CONSUME LARGE AMOUNT OF CPU, UNSTABLIZE MACHINE
This Bug is fixed in 12.2
So please download & apply patch 18499306, if its available on top of your database version for your platform

zergduan

yyp2009 发表于 2015-5-27 14:02
Applies to:
Oracle Database - Enterprise Edition - Version 11.2.0.2 and later
Information in thi ...

里面写着：

The time drifts usually occurring less than 1sec and 5 sec for forward and backward respectively are permissible and OK.
If the traces are emitting time drifts of amount beyond these ranges, then it needs to be analyzed.

楼主的trace文件里，都前滚17秒以上了~，不是正常的现象，不属于bug~

yyp2009

zergduan 发表于 2015-5-27 14:26
里面写着：

The time drifts usually occurring less than 1sec and 5 sec for forward and backward  ...

bug，绝对是bug，问题是修改的时间不对 触发的bug；kstmmainvktm: succeeded in setting elevated priority
kstmmainvktm:enabled, highres_enabled, sectick_enabled

*** 2010-08-10 11:06:48.624
VKTM running at (10)millisec precision with DBRM quantum (100)ms
[Start] HighResTick = 1281452808624677
kstmrmtickcnt = 0 : ksudbrmseccnt[0] = 1281452808
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time stalled at 1281452809277676
kstmchkdrift (kstmhighrestimecntkeeper:highres): Stall, backward drift ended at 1281452809353605
Cause

The issue has been investigated by development in the following bug:

Bug 9843304 - VKTM TRACE FILE IS FILLING UP WITH KSTMCHKDRIFT "BACKWARD DRIFT ENDED AT"

Solution

1-Apply patch for Bug 9843304.  The Bug fix is included in the 11.2.0.2 patchset.
If the patch is not available for your platform, please log a Service Request with Oracle Support and request one.

2-The patch adds the ability to disable this debugging information.  

To actually disable the debugging information after applying the patch, add the following event in the init.ora/pfile for the instance:
event="10795 trace name context forever, level 2"
虽然是03版本中已经有了。但问题是：
VKTM去存取时间作计时时，代替了os的gettimeofday()函数避免了很多bug的可能，和提升了相比的性能，可是不代表此进程与os没有交互，只是更高效率的交互，如果os的时间回放从前了，就会因此时间差异触发的问题哦。

kstmchkdrift (kstmhighrestimecntkeeper:highres): Time jumped forward by (86384713465)usec at (1326085560000441) whereas (1000000) is allowed
[End] HighResTick = 1326085758255964

zergduan

yyp2009 发表于 2015-5-27 14:46
我遇到的 和 lz的不一样的，我贴了一下，和我最近遇到很相似

最重要的是这个文章的提到：这两个bug，是与Bug 11837095 "TIME DRIFT DETECTED" APPEARS INTERMITTENTLY IN ALERT LOG, THO' EVENT 10795 SET.相同，而11837095，所说的是当你设置10795 event后，仍然无法停止VKTM的追踪，没发停止追踪是个bug。

但是没说VKTM追踪并报告异常这件事儿本身是bug~

这篇文章中下面说了
VKTM process trace file can be found under bdump, However in this case the trace file doesn't contain useful information, Which makes the message ambiguous.
There are bugs for the VKTM process malfunction
当VKTM产生的trace文件中，没有给出任何有意义的信息的时候，可能是因为bug触发VKTM报错，这时候应该尝试用EVENT 10795来关闭追踪，但是又因为前面说的3个bug，导致EVENT 10795无效，所以需要打patch~
（因为VKTM进程是消耗CPU的，大量无意义的VKTM追踪的产生会消耗大量的CPU，所以需要关闭追踪）

所谓的没有任何意义的信息是指下面类似的内容：
kstmmainvktm: succeeded in setting elevated priority
kstmmainvktm:enabled, highres_enabled, sectick_enabled

*** 2010-08-10 11:06:48.624
VKTM running at (10)millisec precision with DBRM quantum (100)ms
[Start] HighResTick = 1281452808624677
kstmrmtickcnt = 0 : ksudbrmseccnt[0] = 1281452808
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time stalled at 1281452809277676
kstmchkdrift (kstmhighrestimecntkeeper:highres): Stall, backward drift ended at 1281452809353605

但是请看lz的trace文件，内容很清楚，就是时间发生了超出许可范围的前滚，VKTM报告异常是非常正确的事情，是要求管理员尽快处理，防止更严重的问题发生~

zergduan

yyp2009 发表于 2015-5-27 14:46
bug，绝对是bug，问题是修改的时间不对 触发的bug；kstmmainvktm: succeeded in setting elevated priori ...

请注意这个地方 Stall, backward drift ended at 1281452809353605

数据库是允许向后（backupward）调整时间的，是不允许先前（forward）调整时间的~

对于你引用的文章标题是“VKTM Trace Files Generated With KSTMCHKDRIFT "BACKWARD DRIFT ENDED AT" (Doc ID 1185093.1)”

对于向后调整时间，对于数据库的影响不大，但那时向前调整时间，是非常危险的操作（其实不仅仅是数据库，对于操作系统也是不安全的操作）
如果VKTM不停地报错，说你向后修改了时间，那么我们可以认为这是没有意义的报错。
但是如果不停地报错，说你先前调整了时间，难道查都不查就把trace关闭，无疑是增加了宕机的风险

yyp2009

zergduan 发表于 2015-5-27 15:23
请注意这个地方 Stall, backward drift ended at 1281452809353605

数据库是允许向后（backupward）调 ...

这个你说的没错哦，

yyp2009

No error detected to change OS time for oracle DB running on 11.2
[oracle@vmxdb05b ~]$ vi trigger_changes.sql
[oracle@vmxdb05b ~]$ sqlplus donghua/donghua

SQL*Plus: Release 11.2.0.3.0 Production on Sun Jan 8 12:42:07 2012

Copyright (c) 1982, 2011, Oracle. All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Data Mining
and Real Application Testing options

SQL> truncate table t;

Table truncated.

SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Data Mining
and Real Application Testing options
[oracle@vmxdb05b ~]$ vi trigger_changes.sql
[oracle@vmxdb05b ~]$ sqlplus donghua/donghua

SQL*Plus: Release 11.2.0.3.0 Production on Sun Jan 8 12:42:26 2012

Copyright (c) 1982, 2011, Oracle. All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Data Mining
and Real Application Testing options

SQL> @trigger_changes.sql
SQL> col CURR_TIME for a30
SQL> col next_time for a30
SQL> insert into t values (t_s1.nextval,systimestamp);

1 row created.

SQL> commit;

Commit complete.

SQL> alter system switch logfile;

System altered.

SQL> alter system switch logfile;

System altered.

SQL> select ora_rowscn,id,curr_time from t;

ORA_ROWSCN ID CURR_TIME
---------- ---------- ------------------------------
1228384 23 08-JAN-12 12.42.30.484001 PM

SQL> select * from (
2 select sequence#,to_char(next_time,'dd-mon-yy hh24.mi.ss') next_time,rownum rn from v$archived_log order by sequence#)
3 where rn<11;

SEQUENCE# NEXT_TIME RN
---------- ------------------------------ ----------
3 25-nov-11 08.09.55 1
4 27-nov-11 17.25.37 2
5 27-nov-11 21.00.08 3
6 07-dec-11 22.05.11 4
7 11-dec-11 10.41.06 5
8 11-dec-11 11.11.00 6
9 08-jan-12 09.46.15 7
10 08-jan-12 09.57.38 8
11 08-jan-12 11.08.41 9
12 08-jan-12 11.09.56 10

10 rows selected.

SQL>

[grid@vmxdb05b ~]$ crsctl stop has

[root@vmxdb05b ~]# date
Sun Jan 8 12:45:02 SGT 2012
You have new mail in /var/spool/mail/root
[root@vmxdb05b ~]# date 01081446
Sun Jan 8 14:46:00 SGT 2012
[root@vmxdb05b ~]# date
Sun Jan 8 14:46:01 SGT 2012
[root@vmxdb05b ~]#


[grid@vmxdb05b ~]$ crsctl start has

SQL> @trigger_changes.sql
SQL> col CURR_TIME for a30
SQL> col next_time for a30
SQL> insert into t values (t_s1.nextval,systimestamp);

1 row created.

SQL> commit;

Commit complete.

SQL> alter system switch logfile;

System altered.

SQL> alter system switch logfile;

System altered.

SQL> select ora_rowscn,id,curr_time from t;

ORA_ROWSCN ID CURR_TIME
---------- ---------- ------------------------------
1228384 23 08-JAN-12 12.42.30.484001 PM
1248897 24 08-JAN-12 02.48.55.368836 PM


SQL> select * from (
2 select sequence#,to_char(next_time,'dd-mon-yy hh24.mi.ss') next_time from v$archived_log order by sequence# desc )
3 where rownum<11
4 /

SEQUENCE# NEXT_TIME
---------- ------------------------------
19 08-jan-12 14.48.55
18 08-jan-12 14.48.55
17 08-jan-12 14.47.34
16 08-jan-12 12.42.30
15 08-jan-12 12.42.30
14 08-jan-12 12.17.48
13 08-jan-12 10.18.42
12 08-jan-12 11.09.56
11 08-jan-12 11.08.41
10 08-jan-12 09.57.38

10 rows selected.

[grid@vmxdb05b ~]$ crsctl stop has


[root@vmxdb05b ~]# date
Sun Jan 8 14:59:13 SGT 2012
[root@vmxdb05b ~]# date 01081259
Sun Jan 8 12:59:00 SGT 2012
[root@vmxdb05b ~]# date
Sun Jan 8 12:59:02 SGT 2012
[root@vmxdb05b ~]#

[grid@vmxdb05b ~]$ crsctl start has

SQL> @trigger_changes.sql
SQL> col CURR_TIME for a30
SQL> col next_time for a30
SQL> insert into t values (t_s1.nextval,systimestamp);

1 row created.

SQL> commit;

Commit complete.

SQL> alter system switch logfile;

System altered.

SQL> alter system switch logfile;

System altered.

SQL> select ora_rowscn,id,curr_time from t;

ORA_ROWSCN ID CURR_TIME
---------- ---------- ------------------------------
1228384 23 08-JAN-12 12.42.30.484001 PM
1269374 25 08-JAN-12 01.04.57.367069 PM
1248897 24 08-JAN-12 02.48.55.368836 PM

SQL> select * from (
2 select sequence#,to_char(next_time,'dd-mon-yy hh24.mi.ss') next_time from v$archived_log order by sequence# desc)
3 where rownum<11;

SEQUENCE# NEXT_TIME
---------- ------------------------------
20 08-jan-12 13.01.12
19 08-jan-12 14.48.55
18 08-jan-12 14.48.55
17 08-jan-12 14.47.34
16 08-jan-12 12.42.30
15 08-jan-12 12.42.30
14 08-jan-12 12.17.48
13 08-jan-12 10.18.42
12 08-jan-12 11.09.56
11 08-jan-12 11.08.41

10 rows selected.

[root@vmxdb05b ~]# date
Sun Jan 8 13:06:06 SGT 2012
[root@vmxdb05b ~]# date 01091306
Mon Jan 9 13:06:00 SGT 2012
[root@vmxdb05b ~]# date
Mon Jan 9 13:06:01 SGT 2012


SQL>
SQL> @trigger_changes.sql
SQL> set echo on
SQL> col CURR_TIME for a30
SQL> col next_time for a30
SQL> insert into t values (t_s1.nextval,systimestamp);

1 row created.

SQL> commit;

Commit complete.

SQL> alter system switch logfile;

System altered.

SQL> alter system switch logfile;

System altered.

SQL> select ora_rowscn,id,curr_time from t;

ORA_ROWSCN ID CURR_TIME
---------- ---------- ------------------------------
1228384 23 08-JAN-12 12.42.30.484001 PM
1269605 25 08-JAN-12 01.04.57.367069 PM
1269605 26 09-JAN-12 01.06.31.790207 PM
1248897 24 08-JAN-12 02.48.55.368836 PM

SQL> select * from (
2 select sequence#,to_char(next_time,'dd-mon-yy hh24.mi.ss') next_time from v$archived_log order by sequence# desc)
3 where rownum<11;

SEQUENCE# NEXT_TIME
---------- ------------------------------
22 08-jan-12 13.04.57
21 08-jan-12 13.04.57
20 08-jan-12 13.01.12
19 08-jan-12 14.48.55
18 08-jan-12 14.48.55
17 08-jan-12 14.47.34
16 08-jan-12 12.42.30
15 08-jan-12 12.42.30
14 08-jan-12 12.17.48
13 08-jan-12 10.18.42

10 rows selected.

SQL>
SQL> @trigger_changes.sql
SQL> set echo on
SQL> col CURR_TIME for a30
SQL> col next_time for a30
SQL> insert into t values (t_s1.nextval,systimestamp);

1 row created.

SQL> commit;

Commit complete.

SQL> alter system switch logfile;

System altered.

SQL> alter system switch logfile;

System altered.

SQL> select ora_rowscn,id,curr_time from t;

ORA_ROWSCN ID CURR_TIME
---------- ---------- ------------------------------
1228384 23 08-JAN-12 12.42.30.484001 PM
1269683 25 08-JAN-12 01.04.57.367069 PM
1269683 26 09-JAN-12 01.06.31.790207 PM
1269683 27 09-JAN-12 01.06.59.125860 PM
1248897 24 08-JAN-12 02.48.55.368836 PM

SQL> select * from (
2 select sequence#,to_char(next_time,'dd-mon-yy hh24.mi.ss') next_time from v$archived_log order by sequence# desc)
3 where rownum<11;

SEQUENCE# NEXT_TIME
---------- ------------------------------
25 09-jan-12 13.07.01
24 09-jan-12 13.06.34
23 09-jan-12 13.06.34
22 08-jan-12 13.04.57
21 08-jan-12 13.04.57
20 08-jan-12 13.01.12
19 08-jan-12 14.48.55
18 08-jan-12 14.48.55
17 08-jan-12 14.47.34
16 08-jan-12 12.42.30

10 rows selected.

SQL>

[root@vmxdb05b ~]# date
Mon Jan 9 13:09:48 SGT 2012
[root@vmxdb05b ~]# date 01081310
Sun Jan 8 13:10:00 SGT 2012
[root@vmxdb05b ~]# date
Sun Jan 8 13:10:00 SGT 2012


SQL> @@trigger_changes.sql
SQL> col CURR_TIME for a30
SQL> col next_time for a30
SQL> insert into t values (t_s1.nextval,systimestamp);

1 row created.

SQL> commit;

Commit complete.

SQL> alter system switch logfile;

System altered.

SQL> alter system switch logfile;

System altered.

SQL> select ora_rowscn,id,curr_time from t;

ORA_ROWSCN ID CURR_TIME
---------- ---------- ------------------------------
1228384 23 08-JAN-12 12.42.30.484001 PM
1269683 25 08-JAN-12 01.04.57.367069 PM
1269683 26 09-JAN-12 01.06.31.790207 PM
1269683 27 09-JAN-12 01.06.59.125860 PM
1248897 24 08-JAN-12 02.48.55.368836 PM
1270330 28 08-JAN-12 01.10.21.538665 PM

6 rows selected.

SQL> select * from (
2 select sequence#,to_char(next_time,'dd-mon-yy hh24.mi.ss') next_time from v$archived_log order by sequence# desc)
3 where rownum<11;

SEQUENCE# NEXT_TIME
---------- ------------------------------
26 09-jan-12 13.07.04
25 09-jan-12 13.07.01
24 09-jan-12 13.06.34
23 09-jan-12 13.06.34
22 08-jan-12 13.04.57
21 08-jan-12 13.04.57
20 08-jan-12 13.01.12
19 08-jan-12 14.48.55
18 08-jan-12 14.48.55
17 08-jan-12 14.47.34

10 rows selected.

SQL>
SQL>
SQL> @trigger_changes.sql
SQL> set echo on
SQL> col CURR_TIME for a30
SQL> col next_time for a30
SQL> insert into t values (t_s1.nextval,systimestamp);

1 row created.

SQL> commit;

Commit complete.

SQL> alter system switch logfile;

System altered.

SQL> alter system switch logfile;

System altered.

SQL> select ora_rowscn,id,curr_time from t;

ORA_ROWSCN ID CURR_TIME
---------- ---------- ------------------------------
1228384 23 08-JAN-12 12.42.30.484001 PM
1269683 25 08-JAN-12 01.04.57.367069 PM
1269683 26 09-JAN-12 01.06.31.790207 PM
1269683 27 09-JAN-12 01.06.59.125860 PM
1248897 24 08-JAN-12 02.48.55.368836 PM
1270344 28 08-JAN-12 01.10.21.538665 PM
1270344 29 08-JAN-12 01.10.24.453826 PM

7 rows selected.

SQL> select * from (
2 select sequence#,to_char(next_time,'dd-mon-yy hh24.mi.ss') next_time from v$archived_log order by sequence# desc)
3 where rownum<11;

SEQUENCE# NEXT_TIME
---------- ------------------------------
28 08-jan-12 13.10.21
27 08-jan-12 13.10.21
26 09-jan-12 13.07.04
25 09-jan-12 13.07.01
24 09-jan-12 13.06.34
23 09-jan-12 13.06.34
22 08-jan-12 13.04.57
21 08-jan-12 13.04.57
20 08-jan-12 13.01.12
19 08-jan-12 14.48.55

10 rows selected.

SQL>
SQL>

[oracle@vmxdb05b trace]$ cat orcl05b_vktm_9981.trc
Trace file /u01/app/oracle/diag/rdbms/orcl05b/orcl05b/trace/orcl05b_vktm_9981.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: Linux
Node name: vmxdb05b.lab.dbaglobe.com
Release: 2.6.32-71.29.1.el6.x86_64
Version: #1 SMP Mon Jun 27 19:49:27 BST 2011
Machine: x86_64
VM name: VMWare Version: 6
Instance name: orcl05b
Redo thread mounted by this instance: 0
Oracle process number: 4
Unix process pid: 9981, image: oracle@vmxdb05b.lab.dbaglobe.com (VKTM)


*** 2012-01-08 13:01:04.109
*** SESSION ID4.1) 2012-01-08 13:01:04.109
*** CLIENT ID) 2012-01-08 13:01:04.109
*** SERVICE NAME) 2012-01-08 13:01:04.109
*** MODULE NAME) 2012-01-08 13:01:04.109
*** ACTION NAME) 2012-01-08 13:01:04.109

kstmmainvktm: succeeded in setting elevated priority
highres_enabled

*** 2012-01-08 13:01:04.109
VKTM running at (1)millisec precision with DBRM quantum (100)ms
[Start] HighResTick = 1325998864109366
kstmrmtickcnt = 0 : ksudbrmseccnt[0] = 1325998864

*** 2012-01-09 13:06:00.000
kstmchkdrift (kstmhighrestimecntkeeper:highres): Time jumped forward by (86384713465)usec at (1326085560000441) whereas (1000000) is allowed
[End] HighResTick = 1326085758255964

*** 2012-01-09 13:09:18.257
kstmrmtickcnt = 5066 : ksudbrmseccnt[510] = 1326085758

yyp2009

from http://www.dbaglobe.com/2012/01/ ... ge-os-time-for.html

yyp2009

zergduan 发表于 2015-5-27 15:00
最重要的是这个文章的提到：这两个bug，是与Bug 11837095 "TIME DRIFT DETECTED" APPEARS INTERMITTENTLY ...

vktm异常写trc大量消耗cpu资源，一体机里好像很多bug：