Time skipping briefly

[Stevehewitt]

Hi Guys,

I have a 2008 server which is a member of a domain (2008R2 levels and DC's). Recently the time on the server skips forward by around half an hour (although it can be an hour) for a few minutes then back to the correct time again.

What I've done:

- Reset the W32tm config to use domain structure for time
- Triple checked the PDC emulator is getting it's time from our firewall cluster (acts as NTP server for the network)
- Uninstalled and reinstalled the W32tm service
- Ensured the machine is not using the VM host for time. (VMWare, option is unticked)
- Enabled debug logs

In the event logs I see a skew (as kernel-general) at 13:31:45 saying:

The system time has changed to 09/01/2012 13:31:45 from 09/01/2012 14:27:23.

Then the next event entry is another kernel-general at 13:31:45 (same time):

The system time has changed to 09/01/2012 13:31:45 from 09/01/2012 13:31:45.

Next kernel-general entry is at 14:34:05:

The system time has changed to 09/01/2012 14:34:05 from 09/01/2012 13:38:26.

A final entry is at 13:48:50 as below:

The system time has changed to 09/01/2012 13:48:50 from 09/01/2012 14:44:28.

I've found the relevant time slots in the debug log which are below:

150122 13:32:01.1450000s - W32TmServiceMain: timeout
150122 13:32:01.1450000s - Sample Prepared at 129705895211450000 for peer Controller01.kettlefoods.local (ntp.d|0.0.0.0:123->172.16.9.10:123)
150122 13:32:01.1450000s - NtpClient returned 1 samples.
150122 13:32:01.1450000s - Sample 0 offset:+00.0083943s delay:+00.0625000s dispersion:09.3171446s
150122 13:32:01.1450000s - Intersection successful with 0 dropped samples.
150122 13:32:01.1450000s -   0: Sample:0 SyncDist:413483946 SelectDisp:0
150122 13:32:01.1450000s - Sample 0 chosen. Select Dispersion:00.0000000s STC:27837929
150122 13:32:01.1450000s - ClockDispln Update: LastUTC:27837929 SO:83943 KPhO:0 PhO:83943 uT:66 SD:66783715 LI:0 S:3 RDl:625000 RDs:93271446 TSF:0x2 Unset->Hold
150122 13:32:01.1450000s - ClockDispln Discipline: *SKEW*TIME* - PhCRR:2 CR:156256 PhCR:2 UI:30000 phcT:1024 KPhO:83943
150122 13:32:01.1450000s - W32TmServiceMain: waiting 1024.000s
150122 13:37:01.1603600s - ClockDispln Discipline: *SKEW*TIME* - PhCRR:1 CR:156256 PhCR:1 UI:30000 phcT:19200 KPhO:45543
150122 14:44:28.8315552s - PeerPollingThread: WaitTimeout
150122 14:44:28.8315552s - Polling peer Controller01.kettlefoods.local (ntp.d|0.0.0.0:123->172.16.9.10:123)
150122 14:44:28.8315552s - PollIntervalChange(Controller01.kettlefoods.local (ntp.d|0.0.0.0:123->172.16.9.10:123)): adjust: (++) -> 11
150122 14:44:28.8315552s - PollIntervalChange(Controller01.kettlefoods.local (ntp.d|0.0.0.0:123->172.16.9.10:123)): reclamp: 11 -> 10 (min=4, max=17, sys=10)
150122 14:44:28.8315552s - Peer poll: Max:1024.0000000s Cur:00.0000000s
150122 14:44:28.8315552s - PeerPollingThread: waiting 1024.000s
150122 14:44:28.8315552s - ListeningThread -- DataAvailEvent set for socket 1 (0.0.0.0:123)
150122 14:44:28.8315552s - ListeningThread -- response heard from 172.16.9.10:123 <- 172.16.8.200:123
150122 14:44:28.8315552s - /-- NTP Packet:
150122 14:44:28.8315552s - | LeapIndicator: 0 - no warning;  VersionNumber: 3;  Mode: 4 - Server;  LiVnMode: 0x1C
150122 14:44:28.8315552s - | Stratum: 2 - secondary reference (syncd by (S)NTP)
150122 14:44:28.8315552s - | Poll Interval: 10 - 1024s;  Precision: -6 - 15.625ms per tick
150122 14:44:28.8315552s - | RootDelay: 0x0000.0800s - 0.03125s;  RootDispersion: 0x0001.4D28s - 1.30139s
150122 14:44:28.8315552s - | ReferenceClockIdentifier: 0xAC1007FE - source IP: 172.16.7.254
150122 14:44:28.8315552s - | ReferenceTimestamp:   0xD2B56B154FF7545F - 12970589589312367700ns - 150122 13:33:09.3123677s
150122 14:44:28.8315552s - | OriginateTimestamp:   0xD2B57BCCD4E0CD34 - 12970593868831555200ns - 150122 14:44:28.8315552s
150122 14:44:28.8315552s - | ReceiveTimestamp:     0xD2B56EC2B34B4C2E - 12970590530700367700ns - 150122 13:48:50.7003677s
150122 14:44:28.8315552s - | TransmitTimestamp:    0xD2B56EC2B34B4C2E - 12970590530700367700ns - 150122 13:48:50.7003677s
150122 14:44:28.8315552s - >-- Non-packet info:
150122 14:44:28.8315552s - | DestinationTimestamp: 150122 14:44:28.8315552s - 0xD2B57BCCD4E0CD34150122 14:44:28.8315552s -  - 12970593868831555200ns150122 14:44:28.8315552s -  - 150122 14:44:28.8315552s
150122 14:44:28.8315552s - | RoundtripDelay: 000ns (0s)
150122 14:44:28.8315552s - | LocalClockOffset: -3338131187500ns - 55:38.131187500s
150122 14:44:28.8315552s - \--
150122 14:44:28.8315552s - ListeningThread STC:27903465
150122 14:44:28.8315552s - Response received from domain controller Controller01.kettlefoods.local authenticated successfully.
150122 14:44:28.8315552s - Peer poll: Max:1024.0000000s Cur:1024.0000000s
150122 14:44:28.8315552s - Response from peer Controller01.kettlefoods.local (ntp.d|0.0.0.0:123->172.16.9.10:123), ofs: -3338.1311875s
150122 14:44:28.8315552s - 5 Age:5 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0312500s Dsp:16.0000000s RDsp:01.0624390s Pnt:04.7533696s Dst:20.7533696s FDsp:08.0000000s
150122 14:44:28.8315552s - 4 Age:4 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0312500s Dsp:16.0000000s RDsp:01.0776978s Pnt:03.9948512s Dst:19.9948512s FDsp:12.0000000s
150122 14:44:28.8315552s - 3 Age:3 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0312500s Dsp:16.0000000s RDsp:01.1091309s Pnt:03.2362892s Dst:19.2362892s FDsp:14.0000000s
150122 14:44:28.8315552s - 2 Age:2 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0312500s Dsp:16.0000000s RDsp:01.1738586s Pnt:02.4777292s Dst:18.4777292s FDsp:15.0000000s
150122 14:44:28.8315552s - 1 Age:1 Ofs:+00.0083943s Dly:+00.0312500s RDly:+00.0312500s Dsp:00.0817442s RDsp:01.5357208s Pnt:00.2019744s Dst:00.2993436s FDsp:15.5000000s
150122 14:44:28.8315552s - 0 Age:0 Ofs:-3338.1311875s Dly:+00.0312500s RDly:+00.0312500s Dsp:00.0312506s RDsp:01.3013916s Pnt:00.0000000s Dst:00.0468756s FDsp:07.7500000s
150122 14:44:28.8315552s - W32TmServiceMain: resync req, reg too soon.
150122 14:44:28.8315552s - W32TmServiceMain: waiting 0.000s
150122 14:44:28.8315552s - W32TmServiceMain: timeout
150122 14:44:28.8315552s - Sample Prepared at 129705938688315552 for peer Controller01.kettlefoods.local (ntp.d|0.0.0.0:123->172.16.9.10:123)
150122 14:44:28.8315552s - NtpClient returned 1 samples.
150122 14:44:28.8315552s - Sample 0 offset:-3338.1311875s delay:+00.0625000s dispersion:09.0826422s
150122 14:44:28.8315552s - Intersection successful with 0 dropped samples.
150122 14:44:28.8315552s -   0: Sample:0 SyncDist:411138922 SelectDisp:0
150122 14:44:28.8315552s - Sample 0 chosen. Select Dispersion:00.0000000s STC:27903465
150122 14:44:28.8315552s - ClockDispln Update: LastUTC:27903465 SO:-33381311875 KPhO:26343 *PhO:-33381338218 uT:65536 FllPPE:-3.33813e+010 PllPPE:-3.33813e+010 FllPPrE:1.66907e+010 PllPPrE:1.66907e+010 sysPollTicks:65533 FllDown:65536 PllUp:65533 PllDown:524264 FllRA:-127339 PllRA:-7959 [ RA:-396 CR:155860 nT:0 RAPhO:0 SD:80459216 LI:0 S:3 RDl:625000 RDs:90926422 TSF:0x2 Hold(0)
150122 13:48:50.7003677s - ClockDispln Discipline: *SET*TIME* - PhCR:1112710 KPho:-33381311875
150122 13:48:50.7003677s - ClockDispln Discipline: *SKEW*TIME* - PhCRR:0 CR:155860 PhCR:1112710 UI:30000 phcT:6978 KPhO:0
150122 13:48:50.7003677s - TimeProvCommand([NtpClient], TPC_TimeJumped) called.
150122 13:48:50.7003677s - Peer poll: Max:1024.0000000s Cur:1024.0000000s150122 13:48:50.7003677s -  New:01.0017216s
150122 13:48:50.7003677s - W32TmServiceMain: waiting 1024.000s
150122 13:48:50.7003677s - W32TmServiceMain: ********** Time Slip Notification **********
150122 13:48:50.7003677s - ClockDispln TimeSlip:TimeSlip LastUTC:27903465 SetUnsync: LI:3 S:0 RDl:625000 RDs:90926422 TSF:0x2 ReleaseClock2CMOS

You can clearly see the time jump in the logs, however I'm not knowledgeable enought about W32tm debug logs to interpret. Can anyone translate or advice?

The server is the only one out of 40 odd that have this problem so I've ruled out the NTP server, DC and hypervisor layers. I've also checked DST setting which are all correct. The server is fully patched.

Any help appreciated!

Thanks,


Steve.

"They have the internet on computers now!" - Homer Simpson

 

[Stevehewitt]

Looking at the log in more detail, I'm coming to the conclusion that this is nothing to do with w32tm as there is nothing in the logs at the time that the time was changed - therefore can I assume that the change isn't from w32tm but rather something else?

Any ideas on debugging this one?

Thanks again,


Steve.

"They have the internet on computers now!" - Homer Simpson

 

[itsp1965]

If it's getting the time from your firewall cluster, check the firewall's NTP logs to see if there is a skew issue.

 

[Stevehewitt]

The PDC emulator gets it from the firewall so all servers would have the skew. Plus the firewall is accurate.

Thanks,

Steve.

"They have the internet on computers now!" - Homer Simpson

 

[kmcferrin]

You sure you've ruled out the hypervisor layer? That was my first thought. Is it Hyper-V or VMware? If VMware then launch VMware tools and disable the time synchronization. If Hyper-V then edit the VM's properties, then looks under Management, then Integrations Services, and verify that the checkbox for time synch is cleared.

Of course if you are using time synch from your virtualization host then that means that your host is also out of synch as well.

________________________________________
CompTIA A+, Network+, Server+, Security+
MCTS:Windows 7
MCSE:Security 2003
MCITP:Server Administrator
MCITP:Enterprise Administrator
MCITP:Virtualization Administrator 2008 R2
Certified Quest vWorkspace Administrator