Menu
▾
▴
Re: [Ptpd-devel] adjtimex syscall always returns with a TIME_ERROR
|
From: Chris H. <ch...@im...> - 2013-06-14 14:31:41
|
Wojciech,
The issue I am running into is that the kernel will never sync the "HW" clock to the system clock if STA_UNSYNC is always set.
When CONFIG_RTC_SYSTOHC or CONFIG_GENERIC_CMOS_UPDATE are enabled, the kernel will write the "HW" clock every 11 minutes provided the adjtimex call is made and STA_UNSYNC is not set. This functionality exists in kernel/time/ntp.c in the function "sync_cmos_clock". It may be in a file called ntp.c but it is not really NTP specific anymore given the existence of PTP.
In my design, I have a network that comes and goes as well as power that comes and goes, so there are times that I boot and have no network and depend on the "HW" clock. If I cannot have this kernel functionality run, the "HW" clock will never be updated to match the system time.
What changes would be necessary in ptpd to address this issue? Can you think of any workarounds?
Regards,
Chris
________________________________
From: Wojciech Owczarek [woj...@ow...]
Sent: Friday, June 14, 2013 3:06 AM
To: Chris Healy
Cc: ptp...@li...
Subject: Re: [Ptpd-devel] adjtimex syscall always returns with a TIME_ERROR
Chris,
It is normal for adjtimex() to return TIME_ERROR when STA_UNSYNC is set. This shouldn't affect anything really. You can treat this value as a warning ftom the kernel NTP API that nothing seems to be controlling the OS clock (denoted by STA_PLL or STA_FLL that NTP sets), but nothing more. Most of us get this value at least on Linux. We were having some discussions about ptpd setting STA_FLL for example but that also requires constant updating of other fields, namely maxerror, which when left alone sets STA_UNSYNC again when it gets to its maximum value. I'm not aware of any monitoring tools inspecting those flags so I don't think this is a big issue. Adjtimex() / ntp_adjtime is quite NTP specific.
So to sum it up: can we fix it - maybe, is this anything to worry about - no.
Regards
Wojciech
On 14 June 2013 00:00, Chris Healy <ch...@im...<mailto:ch...@im...>> wrote:
When using ptpdv2, every call to adjtimex returns a "TIME_ERROR". This seems to be due to the status being "STA_UNSYNC". I've left the slave running for hours and every time adjtimex is called, I always get "TIME_ERROR".
What is leading to this adjtimex issue that I am experiencing? (strace and ptpd2 output below)
Regards,
Chris
adjtimex({modes=ADJ_FREQUENCY, offset=0, freq=-2846032, maxerror=16000000, esterror=16000000, status=STA_UNSYNC, constant=2, precision=1, tolerance=32768000, time={1371052027, 347779}, tick=10000, ppsfreq=0, jitter=0, shift=0, stabil=0, jitcnt=0, calcnt=0, errcnt=0, tbcnt=0}) = 5 (TIME_ERROR)
root ~# ptpd2 -E -g -C -U -Y 4,4 -BB
(ptpd notice) 15:48:26.382402 (___)
(ptpd notice) 15:48:26.383978 (___) === PTPDv2 version 2.3.0-svn starting
(ptpd info) 15:48:26.384140 (___)
(ptpd info) 15:48:26.384209 (___) Starting ptpd2 daemon with parameters: ptpd2 -E -g -C -U -Y 4,4 -BB
(ptpd debug1) 15:48:26.384360 (___) allocated 1680 bytes for protocol engine data
(ptpd debug1) 15:48:26.384439 (___) allocated 440 bytes for foreign master data
(ptpd info) 15:48:26.384551 (___) Info: Going to check lock /var/run/kernel_clock
(ptpd debug2) 15:48:26.461064 (___) Query_shell: _pgrep -x ptpd2 | grep -v ^25886$ | wc -l_ -> _0
_
(ptpd info) 15:48:26.462056 (___) Info: No ptpd2 daemons detected in parallel (as expected)
(ptpd debug2) 15:48:26.526228 (___) Query_shell: _pgrep -x ntpd | grep -v ^25886$ | wc -l_ -> _0
_
(ptpd info) 15:48:26.527030 (___) Info: No ntpd daemons detected in parallel (as expected)
(ptpd info) 15:48:26.527154 (___) Info: Going to check lock /var/run/kernel_clock
(ptpd info) 15:48:27.057281 (___) snmp[info]: NET-SNMP version 5.7.1 AgentX subagent connected
(ptpd info) 15:48:27.104209 (___) Info: Startup finished sucessfully
(ptpd debug1) 15:48:27.104387 (?) event POWERUP
(ptpd debug1) 15:48:27.104490 (?) state PTP_INITIALIZING
# Timestamp, State, Clock ID, One Way Delay, Offset From Master, Slave to Master, Master to Slave, Drift, Last packet Received
2013-06-12 15:48:27.104991, init,
(ptpd debug1) 15:48:27.105094 (init) Debug Initializing...
(ptpd debug1) 15:48:27.105160 (init) manufacturerIdentity: ptpd.sf.net<http://ptpd.sf.net>;2.3.0
(ptpd debug1) 15:48:27.105229 (init) manufacturerOUI: ff:ff:ff
(ptpd debug1) 15:48:27.105369 (init) netInit
(ptpd debug1) 15:48:27.105729 (init) Local IP address used : 172.16.1.11
(ptpd debug1) 15:48:27.106227 (init) Going to set IP_MULTICAST_LOOP with 1
(ptpd debug1) 15:48:27.106329 (init) netInitTimestamping: trying to use SO_TIMESTAMPNS
(ptpd debug1) 15:48:27.106410 (init) initData
(ptpd debug1) 15:48:27.106550 (init) initTimer
(ptpd debug1) 15:48:27.106877 (init) initClock
(ptpd debug2) 15:48:27.107010 (init) adj is 0; t freq is 0 (float: 0.000000 Integer32: 0)
(ptpd debug1) 15:48:27.107267 (init) state PTP_LISTENING
(ptpd debug2) 15:48:27.107350 (init) timerStop: Stopping timer 2. (New interval: 0; New left: 0)
(ptpd debug2) 15:48:27.107424 (init) timerStop: Stopping timer 4. (New interval: 0; New left: 0)
(ptpd debug2) 15:48:27.107490 (init) timerStop: Stopping timer 0. (New interval: 0; New left: 0)
(ptpd debug2) 15:48:27.107557 (init) timerStop: Stopping timer 1. (New interval: 0; New left: 0)
(ptpd debug1) 15:48:27.107689 (init) netRefreshIGMP
(ptpd info) 15:48:27.169841 (init) Refreshed IGMP multicast memberships
(ptpd debug2) 15:48:27.170102 (init) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd info) 15:48:27.170258 (lstn_init) === Now in state: PTP_LISTENING
2013-06-12 15:48:27.170326, lstn_init, 1
(ptpd debug1) 15:48:27.344952 (lstn_init) ==> Sync received
(ptpd debug1) 15:48:27.345238 (lstn_init) ==> Announce received
(ptpd debug2) 15:48:27.345411 (lstn_init) event STATE_DECISION_EVENT
(ptpd info) 15:48:27.346519 (lstn_init) === New best master selected: 00e04bfffe405bb4(unknown)/01
(ptpd debug2) 15:48:27.346617 (lstn_init) timerStop: Stopping timer 3. (New interval: 189; New left: 0)
(ptpd debug1) 15:48:27.346779 (lstn_init) state PTP_SLAVE
(ptpd debug1) 15:48:27.346844 (lstn_init) initClock
(ptpd debug2) 15:48:27.346911 (lstn_init) adj is 0; t freq is 0 (float: 0.000000 Integer32: 0)
(ptpd debug2) 15:48:27.347173 (lstn_init) timerStart: Set timer 5 to 300.000000. New interval: 4800; new left: 4800
(ptpd debug2) 15:48:27.347361 (lstn_init) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd info) 15:48:27.347471 (slv) === Now in state: PTP_SLAVE, Best master: 00e04bfffe405bb4(unknown)/01
2013-06-12 15:48:27.347630, slv, 00e04bfffe405bb4(unknown)/01, 0.000000000, 0.000000000, 0.000000000, 0.000000000, 0, I
(ptpd debug1) 15:48:27.347745 (slv) Error: message shorter than header length
(ptpd debug1) 15:48:27.347954 (slv) ==> FollowUp received
(ptpd debug2) 15:48:27.348035 (slv) Ignored followup, Slave was not waiting a follow up message
(ptpd debug1) 15:48:31.344920 (slv) ==> Sync received
(ptpd notice) 15:48:31.345091 (slv) Received first Sync from Master
(ptpd notice) 15:48:31.345162 (slv) going to arm DelayReq timer for the first time, with initial rate: 4
(ptpd debug2) 15:48:31.359488 (slv) timerStart: Set timer 1 to 16.000000. New interval: 256; new left: 256
(ptpd debug2) 15:48:31.359687 (slv) HandleSync: waiting for follow-up
(ptpd debug1) 15:48:31.359939 (slv) ==> Announce received
(ptpd debug2) 15:48:31.360034 (slv) ___ Announce: received Announce from current Master, so reset the Announce timer
(ptpd debug2) 15:48:31.360110 (slv) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug2) 15:48:31.360198 (slv) event STATE_DECISION_EVENT
(ptpd debug1) 15:48:31.360427 (slv) ==> FollowUp received
(ptpd debug1) 15:48:31.360522 (slv) Observed_drift with AI component: 386
(ptpd debug1) 15:48:31.360589 (slv) After PI: Adj: 39011 Drift: 386 OFM 386257
(ptpd debug2) 15:48:31.360714 (slv) Observed_drift with AI component: 0
(ptpd debug2) 15:48:31.360783 (slv) After PI: Adj: 39011 Drift: 0 OFM 386
(ptpd debug2) 15:48:31.360848 (slv) adjFreq2: call adjfreq to -39 us
(ptpd debug2) 15:48:31.360914 (slv) adj is -39011; t freq is -2556625 (float: -2556625.000000 Integer32: -2535715)
2013-06-12 15:48:31.362864, slv, 00e04bfffe405bb4(unknown)/01, 0.000000000, 0.000386257, 0.000000000, 0.000772514, 386, S
(ptpd debug1) 15:48:35.344876 (slv) ==> Sync received
(ptpd debug2) 15:48:35.345084 (slv) HandleSync: waiting for follow-up
(ptpd debug1) 15:48:35.345346 (slv) ==> Announce received
(ptpd debug2) 15:48:35.345438 (slv) ___ Announce: received Announce from current Master, so reset the Announce timer
(ptpd debug2) 15:48:35.345516 (slv) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug2) 15:48:35.345633 (slv) event STATE_DECISION_EVENT
(ptpd debug1) 15:48:35.345798 (slv) ==> FollowUp received
(ptpd debug1) 15:48:35.345880 (slv) Observed_drift with AI component: 1167
(ptpd debug1) 15:48:35.345947 (slv) After PI: Adj: 79269 Drift: 1167 OFM 781026
(ptpd debug2) 15:48:35.346013 (slv) Observed_drift with AI component: 1
(ptpd debug2) 15:48:35.346076 (slv) After PI: Adj: 79269 Drift: 1 OFM 781
(ptpd debug2) 15:48:35.346140 (slv) adjFreq2: call adjfreq to -79 us
(ptpd debug2) 15:48:35.346271 (slv) adj is -79269; t freq is -5194973 (float: -5194973.000000 Integer32: -5152485)
2013-06-12 15:48:35.346547, slv, 00e04bfffe405bb4(unknown)/01, 0.000000000, 0.000781026, 0.000000000, 0.000789539, 1167, S
(ptpd debug1) 15:48:39.344736 (slv) ==> Sync received
(ptpd debug2) 15:48:39.344901 (slv) HandleSync: waiting for follow-up
(ptpd debug1) 15:48:39.345147 (slv) ==> Announce received
(ptpd debug2) 15:48:39.345240 (slv) ___ Announce: received Announce from current Master, so reset the Announce timer
(ptpd debug2) 15:48:39.345317 (slv) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug2) 15:48:39.345432 (slv) event STATE_DECISION_EVENT
(ptpd debug1) 15:48:39.345596 (slv) ==> FollowUp received
(ptpd debug1) 15:48:39.345681 (slv) Observed_drift with AI component: 1884
(ptpd debug1) 15:48:39.345748 (slv) After PI: Adj: 73584 Drift: 1884 OFM 717004
(ptpd debug2) 15:48:39.345812 (slv) Observed_drift with AI component: 1
(ptpd debug2) 15:48:39.345874 (slv) After PI: Adj: 73584 Drift: 1 OFM 717
(ptpd debug2) 15:48:39.345937 (slv) adjFreq2: call adjfreq to -73 us
(ptpd debug2) 15:48:39.346067 (slv) adj is -73584; t freq is -4822401 (float: -4822401.000000 Integer32: -4782960)
2013-06-12 15:48:39.346253, slv, 00e04bfffe405bb4(unknown)/01, 0.000000000, 0.000717004, 0.000000000, 0.000644470, 1884, S
(ptpd debug1) 15:48:43.344611 (slv) ==> Sync received
(ptpd debug2) 15:48:43.344784 (slv) HandleSync: waiting for follow-up
(ptpd debug1) 15:48:43.345035 (slv) ==> Announce received
(ptpd debug2) 15:48:43.345129 (slv) ___ Announce: received Announce from current Master, so reset the Announce timer
(ptpd debug2) 15:48:43.345207 (slv) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug2) 15:48:43.345323 (slv) event STATE_DECISION_EVENT
(ptpd debug1) 15:48:43.345488 (slv) ==> FollowUp received
(ptpd debug1) 15:48:43.345574 (slv) Observed_drift with AI component: 2466
(ptpd debug1) 15:48:43.345640 (slv) After PI: Adj: 60699 Drift: 2466 OFM 582333
(ptpd debug2) 15:48:43.345705 (slv) Observed_drift with AI component: 2
(ptpd debug2) 15:48:43.345767 (slv) After PI: Adj: 60699 Drift: 2 OFM 582
(ptpd debug2) 15:48:43.345831 (slv) adjFreq2: call adjfreq to -60 us
(ptpd debug2) 15:48:43.346038 (slv) adj is -60699; t freq is -3977970 (float: -3977969.750000 Integer32: -3945435)
2013-06-12 15:48:43.346230, slv, 00e04bfffe405bb4(unknown)/01, 0.000000000, 0.000582333, 0.000000000, 0.000520197, 2466, S
(ptpd debug2) 15:48:47.294509 (slv) TimerUpdate: Timer 1 has now expired. (Re-armed again with interval 256, left 256)
(ptpd debug2) 15:48:47.294685 (slv) timerExpired: Timer 1 expired, taking actions. current interval: 256; current left: 256
(ptpd debug2) 15:48:47.294762 (slv) event DELAYREQ_INTERVAL_TIMEOUT_EXPIRES
(ptpd debug1) 15:48:47.294891 (slv) ==> Issue DelayReq (0)
(ptpd debug2) 15:48:47.295289 (slv) timerStart_random: requested 16.00, got 16.03
(ptpd debug2) 15:48:47.295502 (slv) timerStart: Set timer 1 to 16.026529. New interval: 256; new left: 256
(ptpd debug1) 15:48:47.295899 (slv) ==> DelayReq received
(ptpd debug1) 15:48:47.295988 (slv) ==> Handle DelayReq (0)
(ptpd debug1) 15:48:47.296151 (slv) ==> DelayResp received
(ptpd debug1) 15:48:47.296229 (slv) ==> Handle DelayResp (0)
(ptpd debug1) 15:48:47.296325 (slv) ==> UpdateDelay(): Req_RECV: 1371052127.294839188 Req_SENT: 1371052127.295159594 (diff: -0.000320406)
2013-06-12 15:48:47.296391, slv, 00e04bfffe405bb4(unknown)/01, 0.000049947, 0.000582333, -0.000320406, 0.000520197, 2466, D
(ptpd notice) 15:48:47.296482 (slv) received first DelayResp from Master
(ptpd debug1) 15:48:47.344502 (slv) ==> Sync received
(ptpd debug2) 15:48:47.344641 (slv) HandleSync: waiting for follow-up
(ptpd debug1) 15:48:47.344889 (slv) ==> Announce received
(ptpd debug2) 15:48:47.344976 (slv) ___ Announce: received Announce from current Master, so reset the Announce timer
(ptpd debug2) 15:48:47.345049 (slv) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug2) 15:48:47.345154 (slv) event STATE_DECISION_EVENT
(ptpd debug1) 15:48:47.345314 (slv) ==> FollowUp received
(ptpd debug1) 15:48:47.345397 (slv) Observed_drift with AI component: 2922
(ptpd debug1) 15:48:47.345465 (slv) After PI: Adj: 48616 Drift: 2922 OFM 456942
(ptpd debug2) 15:48:47.345530 (slv) Observed_drift with AI component: 2
(ptpd debug2) 15:48:47.345592 (slv) After PI: Adj: 48616 Drift: 2 OFM 456
(ptpd debug2) 15:48:47.345794 (slv) adjFreq2: call adjfreq to -48 us
(ptpd debug2) 15:48:47.345868 (slv) adj is -48616; t freq is -3186098 (float: -3186098.250000 Integer32: -3160040)
2013-06-12 15:48:47.346042, slv, 00e04bfffe405bb4(unknown)/01, 0.000049947, 0.000456942, -0.000320406, 0.000443635, 2922, S
(ptpd debug1) 15:48:51.344480 (slv) ==> Sync received
(ptpd debug2) 15:48:51.344720 (slv) HandleSync: waiting for follow-up
(ptpd debug1) 15:48:51.344916 (slv) ==> Announce received
(ptpd debug2) 15:48:51.345005 (slv) ___ Announce: received Announce from current Master, so reset the Announce timer
(ptpd debug2) 15:48:51.345081 (slv) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug2) 15:48:51.345195 (slv) event STATE_DECISION_EVENT
(ptpd debug1) 15:48:51.345357 (slv) ==> FollowUp received
(ptpd debug1) 15:48:51.345639 (slv) Observed_drift with AI component: 3301
(ptpd debug1) 15:48:51.345722 (slv) After PI: Adj: 41205 Drift: 3301 OFM 379045
(ptpd debug2) 15:48:51.345788 (slv) Observed_drift with AI component: 3
(ptpd debug2) 15:48:51.345850 (slv) After PI: Adj: 41205 Drift: 3 OFM 379
(ptpd debug2) 15:48:51.345915 (slv) adjFreq2: call adjfreq to -41 us
(ptpd debug2) 15:48:51.345982 (slv) adj is -41205; t freq is -2700411 (float: -2700411.000000 Integer32: -2678325)
2013-06-12 15:48:51.346154, slv, 00e04bfffe405bb4(unknown)/01, 0.000049947, 0.000379045, -0.000320406, 0.000414350, 3301, S
(ptpd debug1) 15:48:55.344591 (slv) ==> Sync received
(ptpd debug2) 15:48:55.344758 (slv) HandleSync: waiting for follow-up
(ptpd debug1) 15:48:55.344953 (slv) ==> Announce received
(ptpd debug2) 15:48:55.345041 (slv) ___ Announce: received Announce from current Master, so reset the Announce timer
(ptpd debug2) 15:48:55.345117 (slv) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug2) 15:48:55.345231 (slv) event STATE_DECISION_EVENT
(ptpd debug1) 15:48:55.345552 (slv) ==> FollowUp received
(ptpd debug1) 15:48:55.345647 (slv) Observed_drift with AI component: 3675
(ptpd debug1) 15:48:55.345715 (slv) After PI: Adj: 41161 Drift: 3675 OFM 374862
(ptpd debug2) 15:48:55.345780 (slv) Observed_drift with AI component: 3
(ptpd debug2) 15:48:55.345842 (slv) After PI: Adj: 41161 Drift: 3 OFM 374
(ptpd debug2) 15:48:55.345907 (slv) adjFreq2: call adjfreq to -41 us
(ptpd debug2) 15:48:55.345972 (slv) adj is -41161; t freq is -2697527 (float: -2697527.250000 Integer32: -2675465)
2013-06-12 15:48:55.346193, slv, 00e04bfffe405bb4(unknown)/01, 0.000049947, 0.000374862, -0.000320406, 0.000435270, 3675, S
^C (ptpd notice) 15:48:56.983945 (___) === Shutdown on close signal
________________________________
This email and any files transmitted with it are confidential & proprietary to Systems and Software Enterprises, LLC. This information is intended solely for the use of the individual or entity to which it is addressed. Access or transmittal of the information contained in this e-mail, in full or in part, to any other organization or persons is not authorized.
------------------------------------------------------------------------------
This SF.net email is sponsored by Windows:
Build for Windows Store.
http://p.sf.net/sfu/windows-dev2dev
_______________________________________________
Ptpd-devel mailing list
Ptp...@li...<mailto:Ptp...@li...>
https://lists.sourceforge.net/lists/listinfo/ptpd-devel
--
-
Wojciech Owczarek
________________________________
This email and any files transmitted with it are confidential & proprietary to Systems and Software Enterprises, LLC. This information is intended solely for the use of the individual or entity to which it is addressed. Access or transmittal of the information contained in this e-mail, in full or in part, to any other organization or persons is not authorized.
|