none
タスクによるw32timeサービスの起動時に時刻同期が行われず、SpecialPollingTime後に同期される RRS feed

 > 

  • 質問

  • Question
    サインインして投票
    0
    サインインして投票
    OS：Windows2008R2 DataCenter Edition
    ワークグループ環境


    時刻同期について、インターネットタイムサーバに全環境で使用しているNTPサーバを指定しています。
    時刻同期の設定については、上記以外はデフォルトのままに設定しているので、
    タスクのTimeSyncronizationに登録された毎週日曜日の1:00にw32timeサービスが起動される仕組みになっています。

    上記設定だと、通常は毎週1回w32timeサービスが起動され、起動後にNTPサーバとの同期がとられ、
    その後時刻が同期されたらサービスが停止されるものと認識しています。

    しかし、実際の動作はこの起動時での時刻同期が必ず失敗（もしくは同期が行われていない）為、
    デフォルトのSpecialPollingTimeの設定値（604800=1週間後）に同期され、再度w32timeサービスが起動されるのはその次の週になります。
    ※2週目はw32timeサービスは起動中となるので、TimeSyncronizationタスクは失敗します。

    上記の動作が続く為、結果的に2週間に1度の同期が行われる動作が続いています。


    この時、何故w32timeサービスが起動した時に何故同期が行われないかがわかりません。
    w32timeサービス起動時以外は、正常に同期がとれているようなので、NTPサーバとの疎通に問題があるとは思えません。


    もし、解析方法等が分かれば、ご教授いただけると幸いです。

    以下はw32timeのデバッグログ（FileLogEntries→0-300に設定）です
    ※この時は、SpecialPollingTimeを300（5分間）に設定し、w32timeサービス起動後、5分置きにNTPサーバと同期をとる仕組みにしています。
    ※以下の結果から、13:07にw32timeサービス起動時には、同期出来ていなく、その5分後に同期が完了してサービスが終了しているところまでは読み取れています。

    2013/08/29 13:07:50.6311269 - ---------- Log File Opened -----------------
    2013/08/29 13:07:50.6311269 - Service started as a task. Service will be shut down when synchornization is complete.
    2013/08/29 13:07:50.6311269 - CurSpc:15600100ns  BaseSpc:15600100ns  SyncToCmos:Yes
    2013/08/29 13:07:50.6311269 - PerfFreq:2083437c/s
    2013/08/29 13:07:50.6311269 - ReadConfig: Found provider 'NtpClient':
    2013/08/29 13:07:50.6311269 - ReadConfig:   'Enabled'=0x00000001
    2013/08/29 13:07:50.6311269 - ReadConfig:   'DllName'='%systemroot%\system32\w32time.dll'
    2013/08/29 13:07:50.6311269 - ReadConfig:   'DllName'='C:\Windows\system32\w32time.dll'
    2013/08/29 13:07:50.6311269 - ReadConfig:   'DllName'='C:\Windows\system32\w32time.dll'
    2013/08/29 13:07:50.6311269 - ReadConfig:   'InputProvider'=0x00000001
    2013/08/29 13:07:50.6311269 - ReadConfig: Found provider 'NtpServer':
    2013/08/29 13:07:50.6311269 - ReadConfig:   'Enabled'=0x00000000
    2013/08/29 13:07:50.6311269 - ReadConfig:   'DllName'='%systemroot%\system32\w32time.dll'
    2013/08/29 13:07:50.6311269 - ReadConfig:   'DllName'='C:\Windows\system32\w32time.dll'
    2013/08/29 13:07:50.6311269 - ReadConfig:   'DllName'='C:\Windows\system32\w32time.dll'
    2013/08/29 13:07:50.6311269 - ReadConfig:   'InputProvider'=0x00000000
    2013/08/29 13:07:50.6311269 - ReadConfig: Found provider 'VMICTimeProvider':
    2013/08/29 13:07:50.6311269 - ReadConfig:   'Enabled'=0x00000001
    2013/08/29 13:07:50.6311269 - ReadConfig:   'DllName'='%SystemRoot%\System32\vmictimeprovider.dll'
    2013/08/29 13:07:50.6311269 - ReadConfig:   'DllName'='C:\Windows\System32\vmictimeprovider.dll'
    2013/08/29 13:07:50.6311269 - ReadConfig:   'DllName'='C:\Windows\System32\vmictimeprovider.dll'
    2013/08/29 13:07:50.6311269 - ReadConfig:   'InputProvider'=0x00000001
    2013/08/29 13:07:50.6311269 - ReadConfig: 'PhaseCorrectRate'=0x00000001 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'UpdateInterval'=0x00057E40 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'FrequencyCorrectRate'=0x00000004 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'PollAdjustFactor'=0x00000005 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'LargePhaseOffset'=0x02FAF080 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'SpikeWatchPeriod'=0x00000384 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'HoldPeriod'=0x00000005 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'MinPollInterval'=0x0000000A (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'MaxPollInterval'=0x0000000F (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'AnnounceFlags'=0x0000000A (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'LocalClockDispersion'=0x0000000A (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'MaxNegPhaseCorrection'=0x0000D2F0 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'MaxPosPhaseCorrection'=0x0000D2F0 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'EventLogFlags'=0x00000002 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'MaxAllowedPhaseOffset'=0x00000001 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'TimeJumpAuditOffset'=0x00007080 (2)
    2013/08/29 13:07:50.6311269 - lastClockRate=156001, clockPrecision=-6
    2013/08/29 13:07:50.6311269 - SetTimeSlipNotification succeeds with 0x00000000.
    2013/08/29 13:07:50.6311269 - W32TmServiceMain: RequestNetTopoChangeNotification Succeed
    2013/08/29 13:07:50.6311269 -   DomainHierarchy: LSA role change notification. Redetecting.
    2013/08/29 13:07:50.6311269 - ClockDisciplineThread: Starting: SetUnsync: LI:3 S:0 RDl:0 RDs:0 TSF:0x0  LastUTC:1124450464
    2013/08/29 13:07:50.6311269 - Starting Providers.
    2013/08/29 13:07:50.6311269 - Starting 'NtpClient', dll:'C:\Windows\system32\w32time.dll'
    2013/08/29 13:07:50.6311269 - LoadLibrary
    2013/08/29 13:07:50.6311269 - NtpTimeProvOpen("NtpClient") called.
    2013/08/29 13:07:50.6311269 - StartNtpProv
    2013/08/29 13:07:50.6311269 - sysPrecision=-6, systmeClockResolution=156250
    2013/08/29 13:07:50.6311269 - NtpProvider: Created 2 sockets (0 listen-only): [::]:123<0x0>, 0.0.0.0:123<0x0>
    2013/08/29 13:07:50.6311269 - StartListeningThread completed!
    2013/08/29 13:07:50.6311269 - PeerPollingThread: waiting forever
    2013/08/29 13:07:50.6311269 - StartPeerPollingThread completed!
    2013/08/29 13:07:50.6311269 - ReadConfig: 'AllowNonstandardModeCombinations'=0x00000001 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'CompatibilityFlags'=0x80000000 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'SpecialPollInterval'=0x0000012C (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'ResolvePeerBackoffMinutes'=0x0000000F (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'ResolvePeerBackoffMaxTimes'=0x00000007 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'EventLogFlags'=0x00000001 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'LargeSampleSkew'=0x00000003 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'Type'=NTP (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'NtpServer'=10.129.209.40,0x9 (2)
    2013/08/29 13:07:50.6311269 - ReadConfig: 'ManualPeerList'(parsed)='10.129.209.40,0x9'
    2013/08/29 13:07:50.6467269 - AddNewPendingPeer: manual
    2013/08/29 13:07:50.6467269 - StartListeningThread completed!
    2013/08/29 13:07:50.6467269 - PeerPollingThread: waiting 0.000s
    2013/08/29 13:07:50.6467269 - PeerPollingThread: WaitTimeout
    2013/08/29 13:07:50.6467269 - StartPeerPollingThread completed!
    2013/08/29 13:07:50.6467269 - Resolving manual peer: 10.129.209.40,0x9
    2013/08/29 13:07:50.6467269 - NtpClient started.
    2013/08/29 13:07:50.6467269 - Starting 'VMICTimeProvider', dll:'C:\Windows\System32\vmictimeprovider.dll'
    2013/08/29 13:07:50.6467269 - Create new peer associations: #1
    2013/08/29 13:07:50.6467269 - PeerPollingThread: PeerListUpdated
    2013/08/29 13:07:50.6467269 - Association: (Local) 0.0.0.0:123 => 10.129.209.40:123 (Remote)
    2013/08/29 13:07:50.6467269 - Created reachability group: (
    2013/08/29 13:07:50.6467269 - 10.129.209.40:123,
    2013/08/29 13:07:50.6467269 - )
    2013/08/29 13:07:50.6467269 - PollIntervalChange(): clear: host 0 = max 17 
    2013/08/29 13:07:50.6467269 - PeerPollingThread: waiting 0.000s
    2013/08/29 13:07:50.6467269 - PeerPollingThread: WaitTimeout
    2013/08/29 13:07:50.6467269 - PeerPollingThread: waiting forever
    2013/08/29 13:07:50.6467269 - Reachability: Attempting to contact peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123).
    2013/08/29 13:07:50.6467269 - Polling peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123)
    2013/08/29 13:07:50.6467269 - PeerPollingThread: PeerListUpdated
    2013/08/29 13:07:50.6467269 - Sending packet to 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123) in Win2K detect mode, stage 1.
    2013/08/29 13:07:50.6467269 - PeerPollingThread: waiting forever
    2013/08/29 13:07:50.6467269 - LoadLibrary
    2013/08/29 13:07:50.6467269 - PollIntervalChange(10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123)): reclamp: 17 -> 10 (min=4, max=17, sys=10)
    2013/08/29 13:07:50.6467269 - Peer poll: Max:300.0000000s (special) Cur:00.0000000s
    2013/08/29 13:07:50.6467269 - PeerPollingThread: waiting 300.000s
    2013/08/29 13:07:50.6467269 - Successfully started 2 providers.
    2013/08/29 13:07:50.6467269 - /--TimeProvider: All providers started
    2013/08/29 13:07:50.6467269 - ListeningThread -- DataAvailEvent set for socket 1 (0.0.0.0:123)
    2013/08/29 13:07:50.6467269 - | Name:NtpClient, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\system32\w32time.dll
    2013/08/29 13:07:50.6467269 - ListeningThread -- response heard from 10.129.209.40:123 <- 192.168.249.86:123
    2013/08/29 13:07:50.6467269 - | Name:VMICTimeProvider, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\System32\vmictimeprovider.dll
    2013/08/29 13:07:50.6467269 - >--
    2013/08/29 13:07:50.6467269 - | Total:2, Input: 2, Marked: 0
    2013/08/29 13:07:50.6467269 - \--
    2013/08/29 13:07:50.6467269 - W32TmServiceMain: waiting i16.000s (1024.000s)
    2013/08/29 13:07:50.6467269 - /-- NTP Packet:
    2013/08/29 13:07:50.6467269 - | LeapIndicator: 0 - no warning;  VersionNumber: 3;  Mode: 4 - Server;  LiVnMode: 0x1C
    2013/08/29 13:07:50.6467269 - | Stratum: 3 - secondary reference (syncd by (S)NTP)
    2013/08/29 13:07:50.6467269 - | Poll Interval: 17 - out of valid range;  Precision: -6 - 15.625ms per tick
    2013/08/29 13:07:50.6467269 - | RootDelay: 0x0000.1000s - 0.0625s;  RootDispersion: 0x0000.2295s - 0.135086s
    2013/08/29 13:07:50.6467269 - | ReferenceClockIdentifier: 0xAC100006 - source IP: 172.16.0.6
    2013/08/29 13:07:50.6467269 - | ReferenceTimestamp:   0xD5C944751250A60A - 13022222069071543100ns - 150720 03:54:29.0715431s
    2013/08/29 13:07:50.6467269 - | OriginateTimestamp:   0xD5C94796A58FE4E4 - 13022222870646726900ns - 150720 04:07:50.6467269s
    2013/08/29 13:07:50.6467269 - | ReceiveTimestamp:     0xD5C947985250A60A - 13022222872321543100ns - 150720 04:07:52.3215431s
    2013/08/29 13:07:50.6467269 - | TransmitTimestamp:    0xD5C947985250A60A - 13022222872321543100ns - 150720 04:07:52.3215431s
    2013/08/29 13:07:50.6467269 - >-- Non-packet info:
    2013/08/29 13:07:50.6467269 - | DestinationTimestamp: 2013/08/29 13:07:50.6467269 - 0xD5C94796A58FE4E42013/08/29 13:07:50.6467269 -  - 13022222870646726900ns2013/08/29 13:07:50.6467269 -  - 150720 04:07:50.6467269s
    2013/08/29 13:07:50.6467269 - | RoundtripDelay: 000ns (0s)
    2013/08/29 13:07:50.6467269 - | LocalClockOffset: 1674816200ns - 0:01.674816200s
    2013/08/29 13:07:50.6467269 - \--
    2013/08/29 13:07:50.6467269 - ListeningThread STC:1124450465
    2013/08/29 13:07:50.6467269 - Peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123) is not Win2K. Setting compat flags.
    2013/08/29 13:07:50.6467269 - PollIntervalChange(10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123)): peer receive: 0 -> 17
    2013/08/29 13:07:50.6467269 - Peer poll: Max:300.0000000s (special) Cur:300.0000000s
    2013/08/29 13:07:50.6467269 - Response from peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123), ofs: +01.6748162s
    2013/08/29 13:07:50.6467269 - W32TmServiceMain: Network Topology Change
    2013/08/29 13:07:50.6467269 - 5 Age:5 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:08.0000000s
    2013/08/29 13:07:50.6467269 - TimeProvCommand([NtpClient], TPC_NetTopoChange) called.
    2013/08/29 13:07:50.6467269 - 4 Age:4 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:12.0000000s
    2013/08/29 13:07:50.6467269 - 3 Age:3 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:14.0000000s
    2013/08/29 13:07:50.6467269 - 2 Age:2 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:15.0000000s
    2013/08/29 13:07:50.6467269 - 1 Age:1 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:15.5000000s
    2013/08/29 13:07:50.6467269 - 0 Age:0 Ofs:+01.6748162s Dly:+00.0312500s RDly:+00.0625000s Dsp:00.0312251s RDsp:00.1350861s Pnt:00.0000000s Dst:00.0468501s FDsp:07.7500000s
    2013/08/29 13:07:50.6467269 - Reachability:  peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123) is reachable.
    2013/08/29 13:07:50.6467269 - W32TmServiceMain: resync req, irreg already pending.
    2013/08/29 13:07:50.6467269 - Logging information: NtpClient is currently receiving valid time data from 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123).
    2013/08/29 13:07:50.6467269 - W32TmServiceMain: waiting i16.000s (1024.000s)
    2013/08/29 13:07:50.6467269 - NtpProvider: Network Topology Change
    2013/08/29 13:07:50.6467269 - Reachability:  removing peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123).  LAST PEER IN GROUP!
    2013/08/29 13:07:50.6467269 -   Peer (special) now pending: <Name:10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123) poll:300 diff:2133437385 last:130222228723215431 resync?:FALSE>
    2013/08/29 13:07:50.6467269 -   Peers reset: p-p:0 a-p:1 a-x:0
    2013/08/29 13:07:50.6467269 - NtpProvider: Created 2 sockets (0 listen-only): [::]:123<0x0>, 0.0.0.0:123<0x0>
    2013/08/29 13:07:50.6467269 - StartListeningThread completed!
    2013/08/29 13:07:50.6467269 - PeerPollingThread: waiting 300.000s
    2013/08/29 13:07:50.6467269 - StartPeerPollingThread completed!
    2013/08/29 13:07:50.6467269 - PeerPollingThread: PeerListUpdated
    2013/08/29 13:07:50.6467269 - PeerPollingThread: waiting 300.000s
    2013/08/29 13:07:50.6467269 - W32TmServiceMain: waiting i16.000s (1024.000s)
    2013/08/29 13:07:50.6467269 - W32TmServiceMain: RequestNetTopoChangeNotification Succeed
    2013/08/29 13:08:06.6523550 - W32TmServiceMain: timeout
    2013/08/29 13:08:06.6523550 - W32TmServiceMain: waiting 1024.000s
    2013/08/29 13:12:50.6508538 - PeerPollingThread: WaitTimeout
    2013/08/29 13:12:50.6508538 - Resolving manual peer: 10.129.209.40,0x9
    2013/08/29 13:12:50.6508538 - Create new peer associations: #1
    2013/08/29 13:12:50.6508538 - Association: (Local) 0.0.0.0:123 => 10.129.209.40:123 (Remote)
    2013/08/29 13:12:50.6508538 - Created reachability group: (
    2013/08/29 13:12:50.6508538 - 10.129.209.40:123,
    2013/08/29 13:12:50.6508538 - )
    2013/08/29 13:12:50.6508538 - PollIntervalChange(): clear: host 0 = max 17 
    2013/08/29 13:12:50.6508538 - PeerPollingThread: waiting 0.000s
    2013/08/29 13:12:50.6508538 - PeerPollingThread: PeerListUpdated
    2013/08/29 13:12:50.6508538 - PeerPollingThread: WaitTimeout
    2013/08/29 13:12:50.6508538 - Reachability: Attempting to contact peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123).
    2013/08/29 13:12:50.6508538 - Polling peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123)
    2013/08/29 13:12:50.6508538 - Sending packet to 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123) in Win2K detect mode, stage 1.
    2013/08/29 13:12:50.6508538 - PeerPollingThread: waiting forever
    2013/08/29 13:12:50.6508538 - PollIntervalChange(10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123)): reclamp: 17 -> 10 (min=4, max=17, sys=10)
    2013/08/29 13:12:50.6508538 - Peer poll: Max:300.0000000s (special) Cur:00.0000000s
    2013/08/29 13:12:50.6508538 - PeerPollingThread: waiting 300.000s
    2013/08/29 13:12:50.6508538 - ListeningThread -- DataAvailEvent set for socket 1 (0.0.0.0:123)
    2013/08/29 13:12:50.6508538 - ListeningThread -- response heard from 10.129.209.40:123 <- 192.168.249.86:123
    2013/08/29 13:12:50.6508538 - /-- NTP Packet:
    2013/08/29 13:12:50.6508538 - | LeapIndicator: 0 - no warning;  VersionNumber: 3;  Mode: 4 - Server;  LiVnMode: 0x1C
    2013/08/29 13:12:50.6508538 - | Stratum: 3 - secondary reference (syncd by (S)NTP)
    2013/08/29 13:12:50.6508538 - | Poll Interval: 17 - out of valid range;  Precision: -6 - 15.625ms per tick
    2013/08/29 13:12:50.6508538 - | RootDelay: 0x0000.1000s - 0.0625s;  RootDispersion: 0x0000.2368s - 0.138306s
    2013/08/29 13:12:50.6508538 - | ReferenceClockIdentifier: 0xAC100006 - source IP: 172.16.0.6
    2013/08/29 13:12:50.6508538 - | ReferenceTimestamp:   0xD5C94875161B35E6 - 13022223093086352700ns - 150720 04:11:33.0863527s
    2013/08/29 13:12:50.6508538 - | OriginateTimestamp:   0xD5C948C2A69E5AC9 - 13022223170650853800ns - 150720 04:12:50.6508538s
    2013/08/29 13:12:50.6508538 - | ReceiveTimestamp:     0xD5C948C4561B35E6 - 13022223172336352700ns - 150720 04:12:52.3363527s
    2013/08/29 13:12:50.6508538 - | TransmitTimestamp:    0xD5C948C4561B35E6 - 13022223172336352700ns - 150720 04:12:52.3363527s
    2013/08/29 13:12:50.6508538 - >-- Non-packet info:
    2013/08/29 13:12:50.6508538 - | DestinationTimestamp: 2013/08/29 13:12:50.6508538 - 0xD5C948C2A69E5AC92013/08/29 13:12:50.6508538 -  - 13022223170650853800ns2013/08/29 13:12:50.6508538 -  - 150720 04:12:50.6508538s
    2013/08/29 13:12:50.6508538 - | RoundtripDelay: 000ns (0s)
    2013/08/29 13:12:50.6508538 - | LocalClockOffset: 1685498900ns - 0:01.685498900s
    2013/08/29 13:12:50.6508538 - \--
    2013/08/29 13:12:50.6508538 - ListeningThread STC:1124469695
    2013/08/29 13:12:50.6508538 - Peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123) is not Win2K. Setting compat flags.
    2013/08/29 13:12:50.6508538 - PollIntervalChange(10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123)): peer receive: 0 -> 17
    2013/08/29 13:12:50.6508538 - Peer poll: Max:300.0000000s (special) Cur:300.0000000s
    2013/08/29 13:12:50.6508538 - Response from peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123), ofs: +01.6854989s
    2013/08/29 13:12:50.6508538 - 5 Age:5 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:08.0000000s
    2013/08/29 13:12:50.6508538 - 4 Age:4 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:12.0000000s
    2013/08/29 13:12:50.6508538 - 3 Age:3 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:14.0000000s
    2013/08/29 13:12:50.6508538 - 2 Age:2 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:15.0000000s
    2013/08/29 13:12:50.6508538 - 1 Age:1 Ofs:+00.0000000s Dly:+00.0000000s RDly:+00.0000000s Dsp:16.0000000s RDsp:00.0000000s Pnt:00.0000000s Dst:16.0000000s FDsp:15.5000000s
    2013/08/29 13:12:50.6508538 - 0 Age:0 Ofs:+01.6854989s Dly:+00.0312500s RDly:+00.0625000s Dsp:00.0312251s RDsp:00.1383057s Pnt:00.0000000s Dst:00.0468501s FDsp:07.7500000s
    2013/08/29 13:12:50.6508538 - Reachability:  peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123) is reachable.
    2013/08/29 13:12:50.6508538 - Logging information: NtpClient is currently receiving valid time data from 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123).
    2013/08/29 13:12:50.6508538 - W32TmServiceMain: resync req, irreg now pending.
    2013/08/29 13:12:50.6508538 - W32TmServiceMain: waiting i0.000s (740.001s)
    2013/08/29 13:12:50.6508538 - W32TmServiceMain: timeout
    2013/08/29 13:12:50.6508538 - Sample Prepared at 130222231706508538 for peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123)
    2013/08/29 13:12:50.6508538 - NtpClient returned 1 samples.
    2013/08/29 13:12:50.6508538 - Sample 0 offset:+01.6854989s delay:+00.0937500s dispersion:07.9195308s
    2013/08/29 13:12:50.6508538 - Intersection successful with 0 dropped samples.
    2013/08/29 13:12:50.6508538 -   0: Sample:0 SyncDist:559664058 SelectDisp:0
    2013/08/29 13:12:50.6508538 - Sample 0 chosen. Select Dispersion:00.0000000s STC:1124469695
    2013/08/29 13:12:50.6508538 - ClockDispln Update: LastUTC:1124469695 SO:16854989 KPhO:0 PhO:16854989 uT:19231 SD:39597654 LI:0 S:4 RDl:937500 RDs:79295308 TSF:0x0 Unset->Hold
    2013/08/29 13:12:50.6508538 - ClockDispln Discipline: *SKEW*TIME* - PhCRR:46 CR:156001 PhCR:46 UI:360000 phcT:19231 KPhO:16854989
    2013/08/29 13:12:50.6508538 - Service was started as a task.  Synchronization complete, shutting down now.
    2013/08/29 13:12:50.6508538 - Logging information: The time service is now synchronizing the system time with the time source 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123).
    2013/08/29 13:12:50.6508538 - W32TmServiceMain: waiting 1024.000s
    2013/08/29 13:12:50.6508538 - Service shutdown initiated with exit code: 0.
    2013/08/29 13:12:50.6508538 - ClockDisciplineThread: hShutDownEvent signaled. Exiting.
    2013/08/29 13:12:50.6500000 - RemoveProviderFromList: NtpClient
    2013/08/29 13:12:50.6500000 - Stopping 'NtpClient', dll:'C:\Windows\system32\w32time.dll'
    2013/08/29 13:12:50.6500000 - NtpTimeProvClose("0000000000000002") called.
    2013/08/29 13:12:50.6500000 - NtpTimeProvClose([NtpClient]) called.
    2013/08/29 13:12:50.6500000 - Reachability:  removing peer 10.129.209.40,0x9 (ntp.m|0x9|0.0.0.0:123->10.129.209.40:123).  LAST PEER IN GROUP!
    2013/08/29 13:12:50.6500000 - StartListeningThread completed!
    2013/08/29 13:12:50.6500000 - PeerPollingThread: waiting forever
    2013/08/29 13:12:50.6500000 - StartPeerPollingThread completed!
    2013/08/29 13:12:50.6500000 - PeerPollingThread: PeerListUpdated
    2013/08/29 13:12:50.6500000 - StopNtpProv
    2013/08/29 13:12:50.6500000 - PeerPollingThread: waiting forever
    2013/08/29 13:12:50.6500000 - ListeningThread: StopEvent
    2013/08/29 13:12:50.6500000 - FreeLibrary dll:C:\Windows\system32\w32time.dll
    2013/08/29 13:12:50.6500000 - /--TimeProvider: Provider list after the provider is actually removed
    2013/08/29 13:12:50.6500000 - | Name:VMICTimeProvider, Started:1, Input:1, Marked:0, RefCount:0, DllName:C:\Windows\System32\vmictimeprovider.dll
    2013/08/29 13:12:50.6500000 - >--
    2013/08/29 13:12:50.6500000 - | Total:1, Input: 1, Marked: 0
    2013/08/29 13:12:50.6500000 - \--
    2013/08/29 13:12:50.6500000 - RemoveProviderFromList: VMICTimeProvider
    2013/08/29 13:12:50.6500000 - Stopping 'VMICTimeProvider', dll:'C:\Windows\System32\vmictimeprovider.dll'
    2013/08/29 13:12:50.6500000 - FreeLibrary dll:C:\Windows\System32\vmictimeprovider.dll
    2013/08/29 13:12:50.6500000 - /--TimeProvider: Provider list after the provider is actually removed
    2013/08/29 13:12:50.6500000 - >--
    2013/08/29 13:12:50.6500000 - | Total:0, Input: 0, Marked: 0
    2013/08/29 13:12:50.6500000 - \--
    2013/08/29 13:12:50.6500000 - SetTimeSlipNotification succeeds with 0x00000000.
    2013/08/29 13:12:50.6500000 - Exiting ServiceShutdown
    2013/08/29 13:12:50.6500000 - ---------- Log File Closed -----------------

    以上、宜しくお願い致します。
    2013年9月2日 22:31
    |

回答

  • Question
    サインインして投票
    1
    サインインして投票

    チャブーンです。

    必要な個所にお答えします。

    私の検証環境はNTPサーバにもWindows2008R2を使用しています。この場合は、特に関係無いと認識しているのですが、間違っておりませんでしょうか。

    ならば、特に気にしなくて大丈夫です。

    なので、常時起動中のサーバはハードウェアクロックがずれているという影響では無く、単純にHWのインターバルタイマーの精度が悪いものと考えていました。

    Windows Timeサーバが起動して同期が行われているならその通りですが、Windows Timeがダウンしている状況では、システム時刻はRTCの値を参照します。もっとも60秒ずれていないと更新しないとあるので、タイマの影響かもしれませんが。したのページが参考になるのではないでしょうか。

    http://support.microsoft.com/kb/946033/ja
    http://support.microsoft.com/kb/232488/ja

    SpecialPollTimeRemainingに保持された値を参照する、というご説明がありましたが、具体的にこの値がどのように使用されるかを記述したドキュメント等があれば教えていただければと思います。

    期待されているような情報(具体的な数値の意味や範囲)についての情報はありません。ですが、何が記録されているのか、についてはしたに情報があります。サービスのリスタート後何秒後に同期するか、が記載されていますね。

    http://technet.microsoft.com/en-us/library/cc773263(v=ws.10).aspx

    • 回答としてマーク 佐伯玲 2013年10月28日 2:54
    2013年9月26日 3:45
    |
    モデレータ
  • Question
    サインインして投票
    0
    サインインして投票

    チャブーンです。

    ちょっと気になりましたので、検証で確認してみました。まず、素のWindows Server 2008 R2 SP1と Linux NTPサーバで確認した結果、おっしゃるような状況になりました。で、したのような条件で再検証した場合、想定通りに時刻同期が行われました(したの条件を満たさないと、必ず詩失敗しました)。

    • Windows Server 2008 R2に「KB2493006」修正プログラムを必ず適用する
    • NTPサーバのrestrictセクションの「nomodify」オプションをはずす

    おそらくw32timeの不具合とNTPサーバの設定の2つの問題が相互干渉して、分かりにくい状態を作っているのではないでしょうか。ちなみに、起動直後は同期せず(SpecialPollIntervalの値にかかわらず)15秒ほど時間がかかる(この間Windows Timeサービスは起動を続けます)点はご了解ください。

    あと、1日で4秒ほど時刻が勝手にずれてしまう件ですが、CPUの高負荷等思い当たる理由がなければ、CMOSの電池切れ等の理由でシステムボード側の時刻がずれていて、それにWindowsが同期してしまっているのかもしれません。Windows Timeサービスが常時稼働していない場合(ワークグループの環境ではそうです)、OSシステム時刻はシステムボード側時刻に1時間ごとに時刻を合わせる動作だったように思います。1日に4秒は一般から言ってずれすぎですので、ハードウェアの購入元にご相談いただく方法も、ご検討ください。

    • 回答としてマーク 佐伯玲 2013年10月28日 2:55
    2013年9月24日 13:43
    |
    モデレータ

すべての返信

  • Question
    サインインして投票
    0
    サインインして投票

    チャブーンです。

    ちょっと w32time デバッグログを簡単に読んでみました。まず、Spike状況は発生してないので、KB263243は関係ないようですね。

    で、内容についてですが、デバッグログからは重大な問題は特に発生していません。となると、Windows Timeサービスの設定の問題があるのかもしれません。

    Windows TimeをSpecialPollIntervalで動作させる場合、サービス起動時に必ず同期する、ということはありません。Windows TimeがSpecialPollIntervalで同期する場合、同期後にサービスが終了した場合「次回起動後に必要時間が経過したら同期する」ために必要な情報を保持しています。これはSpecialPollTimeRemainingレジストリ値に記載されていて、サービス起動時に必ず同期させたい場合、サービスダウン時、事前にこのデータを""(空)に設定する必要があります。

    タスク起動のタイミングとSpecialPollTimeRemainingレジストリ値の情報に不整合があるせいかもしれないので、Windows Timeダウンの状況で、SpecialPollTimeRemainingレジストリ値を空に設定し、再度試していただくのはどうでしょうか？

    2013年9月3日 7:35
    |
    モデレータ
  • Question
    サインインして投票
    0
    サインインして投票
    チャブーンさん

    ご回答ありがとうございます。

    SpecialPollTimeRemainingについては、まったく認知していませんでした。
    まずこの値を空にして現象が改善（または別の動作になるかどうか）を確認しようと思います。
    2013年9月4日 4:24
    |
  • Question
    サインインして投票
    0
    サインインして投票
    こんにちは、toketachiguhi さん
    フォーラムオペレータの佐伯 玲 です。

    その後少しお時間が立ちましたがいかがでしょうか？
    ご確認いただき状況に進展があればこちらのスレッドへその後の状況等をご返信いただけましたらと思います。

    また、ご参考になったり解決に至った際には「回答としてマーク」をしていただけましたらと思います。


    宜しくお願い致します。

    TechNet Community Support 佐伯 玲

    2013年9月12日 5:42
    |
  • Question
    サインインして投票
    0
    サインインして投票

    toketachiguhi です

    SpecialPollTimeRemainingの値をクリアした後に、w32timeサービスを起動するようにタスクを設定しましたが、結果はやはりサービス起動時に初回の同期は実行されず、SpecialPollIntervalの設定値後に時刻同期が行われ、サービスが停止するという状況は変わりませんでした。

    しかし、SpecialPollTimeRemainingのクリアの有無に関わらず、w32timeサービス起動後にSpecialPollIntervalの設定値前に時刻同期が行われた場合もありました。
    ※以下のイベントログにて確認
    Microsoft-Windows-Kernel-General　1　システム時間は ‎XXXXXXXXXXXX から ‎XXXXXXXXXXXX に変更されました。
    ただし、この時は同期しきれなかったのか、サービスは停止ししていませんでした。


    また、このサーバはNTPでの時刻同期を行わないと、１日に４秒ほど時刻が遅れる特性があることがわかりました。

    もしw32timeサービスの起動時、初回の時刻同期について詳細な仕様が分かる方がいましたら教えてください。


    2013年9月20日 6:36
    |
  • Question
    サインインして投票
    0
    サインインして投票

    チャブーンです。

    ちょっと気になりましたので、検証で確認してみました。まず、素のWindows Server 2008 R2 SP1と Linux NTPサーバで確認した結果、おっしゃるような状況になりました。で、したのような条件で再検証した場合、想定通りに時刻同期が行われました(したの条件を満たさないと、必ず詩失敗しました)。

    • Windows Server 2008 R2に「KB2493006」修正プログラムを必ず適用する
    • NTPサーバのrestrictセクションの「nomodify」オプションをはずす

    おそらくw32timeの不具合とNTPサーバの設定の2つの問題が相互干渉して、分かりにくい状態を作っているのではないでしょうか。ちなみに、起動直後は同期せず(SpecialPollIntervalの値にかかわらず)15秒ほど時間がかかる(この間Windows Timeサービスは起動を続けます)点はご了解ください。

    あと、1日で4秒ほど時刻が勝手にずれてしまう件ですが、CPUの高負荷等思い当たる理由がなければ、CMOSの電池切れ等の理由でシステムボード側の時刻がずれていて、それにWindowsが同期してしまっているのかもしれません。Windows Timeサービスが常時稼働していない場合(ワークグループの環境ではそうです)、OSシステム時刻はシステムボード側時刻に1時間ごとに時刻を合わせる動作だったように思います。1日に4秒は一般から言ってずれすぎですので、ハードウェアの購入元にご相談いただく方法も、ご検討ください。

    • 回答としてマーク 佐伯玲 2013年10月28日 2:55
    2013年9月24日 13:43
    |
    モデレータ
  • Question
    サインインして投票
    0
    サインインして投票

    チャブーンさん

    検証と確認ありがとうございます。大変助かります。

    ・まず、「KB2493006」修正プログラムについてですが、該当サーバには適用されていなかったので、まずはこれを適用して、結果がどうなるかという確認をしてみたいと思います。

    ・restrictセクションの「nomodify」オプションについてですが、私の検証環境はNTPサーバにもWindows2008R2を使用しています。この場合は、特に関係無いと認識しているのですが、間違っておりませんでしょうか。

    ・ハードウェアとの関連性についてですが、NTPとの時刻同期を抜きにした場合、WindowsOSの時刻計算の方法は以下のようなものと認識しています。
    （１）サーバが起動する場合は、RTC(Real Time Clock - ハードウェアクロック)を参照してOSの時刻が設定される
    （２）マザーボード上のインターバル タイマーから供給されるパルス信号を元に、ソフトウェアカウンタがOS上の時刻（システムクロック）を更新する
    （３）OS起動中はNTPとの同期のタイミング等で、システムクロック→RTCを更新する

    なので、常時起動中のサーバはハードウェアクロックがずれているという影響では無く、単純にHWのインターバルタイマーの精度が悪いものと考えていました。
    ※この部分の精度については、残念ながらHWベンダー側には異常値とはみなせないという回答となってしまいました。


    さて、w32timeサービスについてSpecialPollTimeRemainingで同期をする場合、サービス起動直後に同期を行うのではなく、
    SpecialPollTimeRemainingに保持された値を参照する、というご説明がありましたが、
    具体的にこの値がどのように使用されるかを記述したドキュメント等があれば教えていただければと思います。
    ※検証サーバでは、[<参照するNTPサーバのIP>,7c3669f]という複数行文字列値が保存されているのですが、この値がどのように使用されるのかがまったくわかりません。


    2013年9月26日 2:36
    |
  • Question
    サインインして投票
    1
    サインインして投票

    チャブーンです。

    必要な個所にお答えします。

    私の検証環境はNTPサーバにもWindows2008R2を使用しています。この場合は、特に関係無いと認識しているのですが、間違っておりませんでしょうか。

    ならば、特に気にしなくて大丈夫です。

    なので、常時起動中のサーバはハードウェアクロックがずれているという影響では無く、単純にHWのインターバルタイマーの精度が悪いものと考えていました。

    Windows Timeサーバが起動して同期が行われているならその通りですが、Windows Timeがダウンしている状況では、システム時刻はRTCの値を参照します。もっとも60秒ずれていないと更新しないとあるので、タイマの影響かもしれませんが。したのページが参考になるのではないでしょうか。

    http://support.microsoft.com/kb/946033/ja
    http://support.microsoft.com/kb/232488/ja

    SpecialPollTimeRemainingに保持された値を参照する、というご説明がありましたが、具体的にこの値がどのように使用されるかを記述したドキュメント等があれば教えていただければと思います。

    期待されているような情報(具体的な数値の意味や範囲)についての情報はありません。ですが、何が記録されているのか、についてはしたに情報があります。サービスのリスタート後何秒後に同期するか、が記載されていますね。

    http://technet.microsoft.com/en-us/library/cc773263(v=ws.10).aspx

    • 回答としてマーク 佐伯玲 2013年10月28日 2:54
    2013年9月26日 3:45
    |
    モデレータ
  • Question
    サインインして投票
    0
    サインインして投票

    toketachiguhi さん

    少しお時間がたってしまいましたがチャブーンさんから寄せられている情報はご質問に対して参考になる情報と思い、
    勝手ながら私の方で「回答としてマーク」とさせていただきました。

    回答マークがつきますと情報をお探しの方がスレッドやスレッドの内の発言を見つけやすくなりますのでご理解くださいませ。

    また寄せられた情報をご確認いただけた際にはその後の状況もご返信いただけましたらと思います。

    宜しくお願い致します。

    • 編集済み 佐伯玲 2013年10月28日 4:25
    2013年10月28日 2:54
    |
  • Question
    サインインして投票
    0
    サインインして投票

    ご返信が遅くなり申し訳ありません。

    LinuxのNTPサーバの構築に手間取ってしまいました。

    私の方でも、今回現象が発生した環境とは別の環境にて（VMwareの仮想環境）再現を行ってみました。

    １．Linux（RHEL6.3）をNTPサーバとする
    ２．ntp.confのRestrictセクションについてはnomodifyをつけたままにする
    ３．ntpdにてNTPサーバとして機能させる
    ４．Windows2008R2をインストールした直後（KBを全く当てない）をNTPClientとして時刻同期させる

    上記検証を行ったところ、タスクによってw32timeを起動する毎に、一発で同期に成功し、その度にw32timeサービスは停止するような動作となりました。
    ※よって物理サーバ環境にて発生していたw32time起動時の同期では時刻同期が完了せず、SpeciallpollingTimeの設定値後に何度か時刻同期を行って、やっと同期→w32timeサービスが停止するという動作は再現しませんでした。

    考えられるのは
    （１）私のLinuxサーバのNTPサーバの設定が間違っている
    （２）さらに細かな環境（HW、仮想環境等）に依存する
    のかと思います。

    本件では、とりあえず頂いた回答によって回避策の正しい設定方法については見つかりましたので、その方向で考えていこうと思います。

    もしよろしければ、現象を再現させることが出来た際のntp.confの設定値を教えていただければと思います。

    2013年11月22日 15:35
    |
  • Question
    サインインして投票
    0
    サインインして投票

    チャブーンです。

    こちらの環境ですが、CentOS 5.9上のntpdが対象です。また(ntpdを)stratum 1で設定していること、restrict www.xxx.yyy.zzz mask 255.255.255.0 noquery nomodifyという項目を加えているといった設定です。

    2013年11月27日 2:00
    |
    モデレータ