为什么SQL Agent job的next run time会发生突变
A real case.
一开始的的现象是很多每10分钟和5分钟执行一次的job会突然next run time变成第二天的某个时间，因此跳过了中间20多个小时：
拿到这种问题，首先我们先检查job的历史记录，在msdb里面运行这个query：
select j.name,h.* from dbo.sysjobhistory h join sysjobs j on j.job_id =h.job_id order by h.run_date, h.run_time
在这里我们从job的历史记录看起来最后一次执行时正常的，并没有错误发现。SQL job的调度也确实是每10分钟一次。
而这些job在2011-05-30 6:00pm以后本应该在6:10分执行，不知道因为什么原因SQL agent计算的下一次执行时间变成了2011-05-31 3:10pm.
接下来我们检查SQL agent的log，这个log和error log在同一个目录下：
2011-05-30 18:03:19 - ? [103] NetLib being used by driver is DBNETLIB.DLL; Local host server is
2011-05-30 18:03:19 - ? [310] 2 processor(s) and 3840 MB RAM detected
2011-05-30 18:03:19 - ? [339] Local computer is RCHDAT108 running Windows NT 5.2 (3790) Service Pack 2
2011-05-31 15:00:47 - ? [432] There are 12 subsystems in the subsystems cache
2011-05-31 15:01:03 - ! [364] The Messenger service has not been started - NetSend notifications will not be sent
2011-05-31 15:01:03 - ? [129] SQLSERVERAGENT starting under Windows NT service control
2011-05-31 15:01:03 - + [260] Unable to start mail session (reason: No mail profile defined)
2011-05-31 15:01:03 - + [396] An idle CPU condition has not been defined - OnIdle job schedules will have no effect
2011-05-31 09:56:16 - ? [131] SQLSERVERAGENT service stopping due to a stop request from a user, process, or the OS...
2011-05-31 09:56:18 - ? [098] SQLServerAgent terminated (normally)
我们在这里发现日志的时间顺序好像有一些错乱？ 从2011-05-30 18:03:19到2011-05-31 15:01:03然后又回到了2011-05-31 09:56:16？在SQL agent 日志里面能看到这个现象是非常幸运的。因为这个日志并不是每分钟都在记录的，如果发生时间跳动的间隔非常短，在这个日志通常是看不到线索的。我们同样也检查了那个时间段的SQL Server错误日志，就没有看到同样的时间顺序错乱的现象。
问题到了这一步，就可以开始怀疑是不是操作系统那个时候的系统时间不对。客户指出，这个机器是在域环境中，从一个固定的time server同步时间的。同时，客户也提供了一个比较有用的线索，问题发生之前6:00pm，这台运行job的服务器被重启过。
接下来的步骤就全部是windows的问题诊断了。
首先，我们在windows的system event log里面搜索 event ID 52的记录，果然我们发现了在不同时段的4条记录：5/23/2011 13:02:42 , 5/22/2011 1:47:15 PM, 5/22/2011 14:55:27 和 5/30/2011 18:03:58.
Event Type: Warning
Event Source: W32Time
Event Category: None
Event ID: 52
Date: 2011-5-30
Time: 18:03:58
User: N/A
Computer: RCHDAT108
Description:
The time service has set the time with offset -75425 seconds.
这个 event ID指出，系统时间被做了大的修改而OS探测到了这个问题。在这里我们发现的时间差异是超过十几个小时的。如果是从time server同步过来的时间不对，通常这样的时间偏差不会这么大，而且时间偏差是逐渐被消除的，而不会像我们在这台机器中看到的在一分钟之后马上跳回到正确的时间。 因此这个问题应该是由于这台机器本地导致的。以下两个原因可能会导致本机的时间不对：
1. <![endif]>VMware的虚拟系统。通常 系统启动的时候是从BIOS来初始化系统时间，但是VMWare没有BIOS，所以启动时是用host machine读取时间。如果host machine的时间不对，那么VMWare虚拟的系统在启动的时候时间就会不对。在启动以后，VMWare还会定期去同步虚拟系统和host machine的时间，这个可以通过如下设置关掉：
启动时候的同步我不知道能不能关掉。
2. 第三方的time provider，可以通过检查注册表键值来发现：HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\W32Time\TimeProviders\
这里应该只有NtpClient和NtpServer
以下一些service可能影响到win32time服务：
Trend Micro Network Time Protocol
Network Time Protocol
Tardis time service
Sprint SmartView
Bytemobile Optimization Client
Vodafone phone connect software
Cisco WAAS mobile (software compressor)
在这个问题中，客户的系统确实是VMWare的，但是客户说已经将时间同步都关掉了。好在问题是可以不断的重现，我们打开下面的audit抓更多的log:
我们打开看w32time的debug log：
a.运行 Regedit, 打开注册表编辑器 Registry Editor;
找到这个键值: HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\W32Time\Config
在这个键值下面增加以下三个项目：
Value Name: FileLogSize
Data Type: DWORD
Value data: 100000000
(1 followed by 8 zeros)
Value name: FileLogName
Data Type: String
Value data: C:\Windows\Debug\w32time.log
Value name: FileLogEntries
Data Type: String
Value: 0-300
b.为目录 C:\Windows\Debug 添加 Everyone – Full Control access的权限
c.重启Windows Time 服务使以上修改生效:
net stop w32time
net start w32time
问题再次发生之后，我们在windows的security event log就抓到的导致问题的证据：
Event ID : 520
Category : None
Source : Security
Type : Audit Success
Generated : 2011/6/17 6:07:07
Machine : RCHDAT108
Message : The system time was changed.
Process ID: 2164
Process Name: C:\Program Files (x86)\VMware\VMware Tools\ VMwareService.exe
Primary User Name: RCHDAT108$
Primary Domain: MSDOMAIN
Primary Logon ID: (0x0,0x3E7)
Client User Name: RCHDAT108$
Client Domain: MSDOMAIN
Client Logon ID: (0x0,0x3E7)
Previous Time: 9:10:30 AM 6/16/2011
New Time: 6:07:07 AM 6/17/2011
这里VMWare又将时间从9:10:30 AM 6/16/2011修改到了6:07:07 AM 6/17/2011。客户检查过host machine的时间和domain的时间实际上只差一小时，不知道为什么VMWare每次重启会将系统时间向后改21个小时。
接下来就需要从VMWare方面做进一步的troubleshooting了.