ITPub博客

首页 > Linux操作系统 > Linux操作系统 > 为什么SQL Agent job的next run time会发生突变(转载))

为什么SQL Agent job的next run time会发生突变(转载))

原创 Linux操作系统 作者:edwardking888 时间:2011-08-25 13:06:40 0 删除 编辑
转载之:http://space.itpub.net/25175503/viewspace-704938

这个案例也非常经典,或许很多朋友也遇到过,反正我是遇到过这样的情况,当时我们公司在线系统的一个备份JOB,莫名其妙的延后了半个小时,看机器时钟,并不比别的机器快或慢超过30秒,为什么备份会突然晚了半小时???一直没有找到原因,看了这篇文章,觉得分析的很有道理,思路也非常对,值得学习。
下面是这篇文章的正文:

一开始的的现象是很多每10分钟和5分钟执行一次的job会突然next run time变成第二天的某个时间,因此跳过了中间20多个小时:

 

 

拿到这种问题,首先我们先检查job的历史记录,在msdb里面运行这个query

selectj.name,h.* fromdbo.sysjobhistoryh joinsysjobsj onj.job_id=h.job_idorder byh.run_date,h.run_time

 

在这里我们从job的历史记录看起来最后一次执行时正常的,并没有错误发现。SQL job的调度也确实是每10分钟一次。而这些job2011-05-30 6:00pm以后本应该在6:10分执行,不知道因为什么原因SQL agent计算的下一次执行时间变成了2011-05-31 3:10pm.

 

接下来我们检查SQL agentlog,这个logerror log在同一个目录下:

2011-05-30 18:03:19 - ?[103]NetLibbeing 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]Thereare 12 subsystems in the subsystems cache

2011-05-31 15:01:03- ! [364] The Messenger service has not been started -NetSendnotifications 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]Unableto start mail session (reason: No mail profile defined)

2011-05-31 15:01:03- + [396]Anidle CPU condition has not been defined -OnIdlejob 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]SQLServerAgentterminated (normally)

 

我们在这里发现日志的时间顺序好像有一些错乱? 从2011-05-30 18:03:192011-05-31 15:01:03然后又回到了2011-05-31 09:56:16?在SQL agent日志里面能看到这个现象是非常幸运的。因为这个日志并不是每分钟都在记录的,如果发生时间跳动的间隔非常短,在这个日志通常是看不到线索的。我们也检查了那个时间段的SQL Server错误日志,就没有看到同样的时间顺序错乱的现象。

 

问题到了这一步,就可以开始怀疑是不是操作系统那个时候的系统时间不对。客户指出,这个机器是在域环境中,从一个固定的time server同步时间的。同时,客户也提供了一个比较有用的线索,问题发生之前6:00pm,这台运行job服务器被重启过。

 

接下来的步骤就全部是windows的问题诊断了。

 

首先,我们在windowssystem 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. VMware的虚拟系统。通常系统启动的时候是从BIOS来初始化系统时间,但是VMWare没有BIOS,所以启动时是用host machine读取时间。如果host machine的时间不对,那么VMWare虚拟的系统在启动的时候时间就会不对。在启动以后,VMWare还会定期去同步虚拟系统和host machine的时间,这个可以通过如下设置关掉: 


启动时候的同步我不知道能不能关掉。

 

2. 第三方的time provider,可以通过检查注册表键值来发现:HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\W32Time\TimeProviders\

这里应该只有NtpClientNtpServer

以下一些service可能影响到win32time服务:

        Trend Micro Network Time Protocol

        Network Time Protocol

       Tardistime service

        SprintSmartView

       BytemobileOptimization Client

        Vodafone phone connect software

        Cisco WAAS mobile (software compressor)

 

在这个问题中,客户的系统确实是VMWare的,但是客户说已经将时间同步都关掉了。好在问题是可以不断的重现,我们打开下面的audit抓更多的log:

 

我们打开看w32timedebug 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

 

问题再次发生之后,我们在windowssecurity 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。客户检查过hostmachine的时间和domain的时间实际上只差一小时,不知道为什么VMWare每次重启会将系统时间向后改21个小时。

接下来就需要从VMWare方面做进一步的troubleshooting.

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/8183550/viewspace-705764/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论

注册时间:2010-04-03

  • 博文量
    477
  • 访问量
    1436686