Menu
▾
▴
Re: [Linuxptp-users] sanity_freq_limit
|
From: Daniel Le <dan...@ex...> - 2015-06-19 18:13:01
|
Thanks Miroslav and Jake. I'm running linuxptp-1.4 and Linux kernel 2.6.35.7 with customization. My older linuxptp version has pi_f_offset_const instead of first_step_threshold, which I didn't alter. I added debugging code to confirm that the step takes place, however unclear how things are afterward. (1) On one slave clock device, where its system time is off by 1 hour and 35 minutes behind. Jun 19 14:31:24 (none) user.warn ptp4l: [16.960] port 1: get_ts_info not supported Jun 19 14:31:24 (none) user.notice ptp4l: [16.961] port 1: INITIALIZING to LISTENING on INITIALIZE Jun 19 14:31:24 (none) user.notice ptp4l: [16.961] port 0: INITIALIZING to LISTENING on INITIALIZE Jun 19 14:31:26 (none) user.notice ptp4l: [18.886] port 1: new foreign master 00b0ae.fffe.02d104-1 Jun 19 14:31:30 (none) user.notice ptp4l: [22.886] selected best master clock 00b0ae.fffe.02d104 Jun 19 14:31:30 (none) user.notice ptp4l: [22.886] port 1: LISTENING to UNCALIBRATED on RS_SLAVE Jun 19 14:31:30 (none) user.notice ptp4l: [23.118] port 1: minimum delay request interval 2^-7 Jun 19 14:31:33 (none) user.info ptp4l: [25.823] master offset -5479246314194 s0 freq +0 path delay 3492 Jun 19 14:31:34 (none) user.info ptp4l: [26.823] master offset -5479246315624 s0 freq +0 path delay 3550 Jun 19 14:31:35 (none) user.info ptp4l: [27.823] master offset -5479246316774 s0 freq +0 path delay 3512 Jun 19 14:31:36 (none) user.info ptp4l: [28.822] master offset -5479246318180 s0 freq +0 path delay 3542 Jun 19 14:31:37 (none) user.info ptp4l: [29.822] master offset -5479246319340 s0 freq +0 path delay 3486 Jun 19 14:31:38 (none) user.info ptp4l: [30.822] master offset -5479247196552 s0 freq +0 path delay 295486 Jun 19 14:31:39 (none) user.info ptp4l: [31.822] master offset -5479246905902 s0 freq +0 path delay 3520 Jun 19 14:31:40 (none) user.info ptp4l: [32.822] master offset -5479246907136 s0 freq +0 path delay 3506 Jun 19 14:31:41 (none) user.info ptp4l: [33.822] master offset -5479246908448 s0 freq +0 path delay 3538 Jun 19 14:31:42 (none) user.info ptp4l: [34.822] master offset -5479246909704 s0 freq +0 path delay 3514 Jun 19 14:31:43 (none) user.info ptp4l: [35.822] master offset -5479247782844 s0 freq +0 path delay 294126 Jun 19 14:31:44 (none) user.info ptp4l: [36.822] master offset -5479247493484 s0 freq +0 path delay 3518 Jun 19 14:31:45 (none) user.info ptp4l: [37.821] master offset -5479247494752 s0 freq +0 path delay 3538 Jun 19 14:31:46 (none) user.info ptp4l: [38.821] master offset -5479247496104 s0 freq +0 path delay 3546 Jun 19 14:31:47 (none) user.info ptp4l: [39.821] master offset -5479247497316 s0 freq +0 path delay 3514 Jun 19 14:31:48 (none) user.info ptp4l: [40.821] master offset -5479247498658 s0 freq +0 path delay 3540 Jun 19 14:31:49 (none) user.info ptp4l: [41.821] master offset -5479248375064 s1 freq -128819 path delay 295242 Jun 19 14:31:49 (none) user.info ptp4l: [41.821] Step system clock... Jun 19 14:31:49 (none) user.info ptp4l: [41.821] clockadj_set_freq: clkid=0 freq= +28819 Jun 19 14:31:49 (none) user.info ptp4l: [41.821] clockadj_step: clkid=0 step=5479248375064 Jun 19 14:31:50 (none) user.info ptp4l: [42.821] master offset -5479248376376 s2 freq -100000000 path delay 295242 Jun 19 14:31:50 (none) user.info ptp4l: [42.821] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:31:50 (none) user.notice ptp4l: [42.821] port 1: UNCALIBRATED to SLAVE on MASTER_CLOCK_SELECTED Jun 19 14:31:51 (none) user.info ptp4l: [43.921] master offset -5479248085876 s2 freq -100000000 path delay 3494 Jun 19 14:31:51 (none) user.info ptp4l: [43.921] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:31:52 (none) user.info ptp4l: [45.021] master offset -5479248087212 s2 freq -100000000 path delay 3518 Jun 19 14:31:52 (none) user.info ptp4l: [45.021] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:31:53 (none) user.info ptp4l: [46.121] master offset -5479248088444 s2 freq -100000000 path delay 3502 Jun 19 14:31:53 (none) user.info ptp4l: [46.121] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:31:55 (none) user.info ptp4l: [47.221] master offset -5479200033936 s2 freq -100000000 path delay -14414590 Jun 19 14:31:55 (none) user.info ptp4l: [47.221] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:31:56 (none) user.info ptp4l: [48.320] master offset -5478966697088 s2 freq -100000000 path delay -81086222 Jun 19 14:31:56 (none) user.info ptp4l: [48.321] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:31:57 (none) user.info ptp4l: [49.420] master offset -5478802913984 s2 freq -100000000 path delay -78204170 Jun 19 14:31:57 (none) user.info ptp4l: [49.420] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:31:58 (none) user.info ptp4l: [50.520] master offset -5478862522102 s2 freq -100000000 path delay -6196760 Jun 19 14:31:58 (none) user.info ptp4l: [50.520] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:31:59 (none) user.info ptp4l: [51.620] master offset -5478868723712 s2 freq -100000000 path delay 3538 Jun 19 14:31:59 (none) user.info ptp4l: [51.620] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:32:00 (none) user.info ptp4l: [52.720] master offset -5478868724940 s2 freq -100000000 path delay 3518 Jun 19 14:32:00 (none) user.info ptp4l: [52.720] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:32:01 (none) user.info ptp4l: [53.820] master offset -5478710523928 s2 freq -100000000 path delay -50266518 Jun 19 14:32:01 (none) user.info ptp4l: [53.820] clockadj_set_freq: clkid=0 freq= +0 Jun 19 14:32:02 (none) user.info ptp4l: [54.920] master offset -5478513781464 s2 freq -100000000 path delay -80343798 Jun 19 14:32:02 (none) user.info ptp4l: [54.920] clockadj_set_freq: clkid=0 freq= +0 (2) On another slave clock device, where its system time is almost same as the correct time. sbin #ptp4l -m -q -i eth3 -s -S ptp4l[841529.107]: clockadj_set_freq: clkid=0 freq= -25768 ptp4l[841529.107]: port 1: get_ts_info not supported ptp4l[841529.108]: port 1: INITIALIZING to LISTENING on INITIALIZE ptp4l[841529.108]: port 0: INITIALIZING to LISTENING on INITIALIZE ptp4l[841529.628]: port 1: new foreign master 00b0ae.fffe.02d103-1 ptp4l[841533.629]: selected best master clock 00b0ae.fffe.02d103 ptp4l[841533.629]: port 1: LISTENING to UNCALIBRATED on RS_SLAVE ptp4l[841533.709]: port 1: minimum delay request interval 2^-7 ptp4l[841535.566]: master offset 496921588 s0 freq -74232 path delay 1186 ptp4l[841536.566]: master offset 496919220 s0 freq -74232 path delay 1214 ptp4l[841537.566]: master offset 497436366 s0 freq -74232 path delay -171964 ptp4l[841538.567]: master offset 497260880 s0 freq -74232 path delay 1186 ptp4l[841539.567]: master offset 497258554 s0 freq -74232 path delay 1212 ptp4l[841540.567]: master offset 497256258 s0 freq -74232 path delay 1204 ptp4l[841541.567]: master offset 497253920 s0 freq -74232 path delay 1202 ptp4l[841542.567]: master offset 497251618 s0 freq -74232 path delay 1200 ptp4l[841543.567]: master offset 497768934 s0 freq -74232 path delay -172016 ptp4l[841544.567]: master offset 497593414 s0 freq -74232 path delay 1196 ptp4l[841545.567]: master offset 497591074 s0 freq -74232 path delay 1204 ptp4l[841546.567]: master offset 497588774 s0 freq -74232 path delay 1200 ptp4l[841547.567]: master offset 497586420 s0 freq -74232 path delay 1218 ptp4l[841548.567]: master offset 498103830 s0 freq -74232 path delay -172036 ptp4l[841549.567]: master offset 497928290 s0 freq -74232 path delay 1204 ptp4l[841550.567]: master offset 497925954 s0 freq -74232 path delay 1204 ptp4l[841551.567]: master offset 497923672 s1 freq -11601 path delay 1182 ptp4l[841551.567]: Step system clock... ptp4l[841551.567]: clockadj_set_freq: clkid=0 freq= +11601 ptp4l[841551.567]: clockadj_step: clkid=0 step= 497923672 ptp4l[841552.567]: master offset 497921336 s2 freq +50278454 path delay 1182 ptp4l[841552.567]: clockadj_set_freq: clkid=0 freq= +21546 ptp4l[841552.567]: port 1: UNCALIBRATED to SLAVE on MASTER_CLOCK_SELECTED ptp4l[841553.517]: master offset 497918992 s2 freq +50776139 path delay 1222 ptp4l[841553.517]: clockadj_set_freq: clkid=0 freq= +23861 ptp4l[841554.466]: master offset 418089084 s2 freq +43211237 path delay 24354298 ptp4l[841554.466]: clockadj_set_freq: clkid=0 freq= -11237 ptp4l[841555.423]: master offset 403879084 s2 freq +42194116 path delay 12854794 ptp4l[841555.423]: clockadj_set_freq: clkid=0 freq= +5884 ptp4l[841556.381]: master offset 416730386 s2 freq +43895976 path delay 1188 ptp4l[841556.381]: clockadj_set_freq: clkid=0 freq= +4024 ptp4l[841557.337]: master offset 416728028 s2 freq +44312469 path delay 1206 ptp4l[841557.337]: clockadj_set_freq: clkid=0 freq= -12469 ptp4l[841558.293]: master offset 416725754 s2 freq +44728967 path delay 1180 ptp4l[841558.293]: clockadj_set_freq: clkid=0 freq= -28967 ptp4l[841559.248]: master offset 416723444 s2 freq +45145459 path delay 1186 ptp4l[841559.248]: clockadj_set_freq: clkid=0 freq= -45459 ptp4l[841560.203]: master offset 416721094 s2 freq +45561946 path delay 1200 ptp4l[841560.203]: clockadj_set_freq: clkid=0 freq= +38054 ptp4l[841561.157]: master offset 389860090 s2 freq +43265705 path delay 7781368 ptp4l[841561.157]: clockadj_set_freq: clkid=0 freq= +34295 ptp4l[841562.114]: master offset 186064456 s2 freq +23072206 path delay 68717870 ptp4l[841562.114]: clockadj_set_freq: clkid=0 freq= +27794 ptp4l[841563.091]: master offset 43535162 s2 freq +8862812 path delay 68388060 ptp4l[841563.091]: clockadj_set_freq: clkid=0 freq= +37188 I also added code to verify if the servo reset occurs when the calculated offset is higher than default sanity_freq_limit. Jun 18 20:08:59 (none) user.warn ptp4l: [521.858] clockcheck: clock jumped backward or running slower than expected! Jun 18 20:08:59 (none) user.info ptp4l: [521.858] MAX-foffset=-206031909 flimit=200000000 Jun 18 20:08:59 (none) user.info ptp4l: [521.858] pi_reset ..................... Jun 18 20:08:59 (none) user.warn ptp4l: [521.966] clockcheck: clock jumped forward or running faster than expected! Jun 18 20:08:59 (none) user.info ptp4l: [521.966] MIN-foffset=+267792097 flimit=200000000 Jun 18 20:08:59 (none) user.info ptp4l: [521.966] pi_reset ..................... Jun 18 20:08:59 (none) user.info ptp4l: [522.070] master offset 1015988 s0 freq +108331 path delay 3518 Jun 18 20:09:00 (none) user.info ptp4l: [523.070] master offset 1014652 s0 freq +108331 path delay 3542 Jun 18 20:09:01 (none) user.info ptp4l: [524.070] master offset 1013376 s0 freq +108331 path delay 3538 Jun 18 20:09:02 (none) user.info ptp4l: [525.070] master offset 924804 s0 freq +108331 path delay 32622 Jun 18 20:09:03 (none) user.info ptp4l: [526.070] master offset 952644 s0 freq +108331 path delay 3506 Jun 18 20:09:04 (none) user.info ptp4l: [527.070] master offset 951354 s0 freq +108331 path delay 3512 -----Original Message----- From: Miroslav Lichvar [mailto:mli...@re...] Sent: Friday, June 19, 2015 4:04 AM To: Daniel Le Cc: Lin...@li... Subject: Re: [Linuxptp-users] sanity_freq_limit On Fri, Jun 19, 2015 at 04:15:20AM +0000, Daniel Le wrote: > And the log messages at start in "good case". I didn't save the log where my system time was initially off a few minutes, though I remember the master offsets were above 200000000. I'll need to reproduce such condition in order to capture the exact log messages. Your config looks good to me. The default value of first_step_threshold is 20 microseconds, so in your test with ~1.5 millisecond initial offset it should have stepped. > ptp4l[792717.068]: master offset -1567668 s0 freq -13556 path delay 1194 > ptp4l[792718.068]: master offset -1569978 s0 freq -13556 path delay 1200 > ptp4l[792719.068]: master offset -1554292 s1 freq -13510 path delay -4826 > ptp4l[792720.068]: master offset -1556592 s2 freq -170726 path delay -4826 But as we can see, it didn't step for some reason. Here is a test I did using the same config file and it does step for me. ptp4l[8898442.271]: master offset -1093869 s0 freq -1946 path delay 54642 ptp4l[8898443.271]: master offset -1094931 s0 freq -1946 path delay 54642 ptp4l[8898444.271]: master offset -1102224 s1 freq -6078 path delay 55329 ptp4l[8898445.271]: master offset 9378 s2 freq -5131 path delay 55329 What linuxptp and kernel versions are you using? -- Miroslav Lichvar |
