On 3/31/2022 9:32 AM, Cole Walker wrote:
> Hello,
>
> I'm looking for some assistance getting to the root of an issue where
> ts2phc will be stable for a period of time and then experience a spike
> in the master offset value. The debug logs show a few interesting things
> and I'm looking for input on what steps to take next.
>
> My setup:
>
> linuxptp version 3.1.1
>
> I have two NICs using the Intel ICE driver. NIC0 has an integrated GNSS
> module and I am using ts2phc to sync them.
>
Hi,
> ethtool -i enp81s0f0
> driver: ice
> version: 1.7.16
> firmware-version: 3.10 0x80009be5 1.3086.0
> expansion-rom-version:
> bus-info: 0000:51:00.0
> supports-statistics: yes
> supports-test: yes
> supports-eeprom-access: yes
> supports-register-dump: yes
> supports-priv-flags: yes
>
>
This is with the ice driver and E810 device. Ok.
It looks like you're using a slightly older out-of-tree driver release.
What kernel are you running on?
There was a fair bit of work done on PTP around these releases, and I am
curious if you could try this with the 1.8.3 driver, or with a recent
kernel (5.16) in-tree driver.
sphc config - the pulsewidth and extts_polarity values are taken from
> the user guide for the NICs.
>
> [global]
> leapfile /usr/share/zoneinfo/leap-seconds.list
> logging_level 7
> ts2phc.nmea_serialport /dev/ttyGNSS_5100_0
> ts2phc.pulsewidth 100000000
>
> [enp81s0f0]
> ts2phc.extts_polarity rising
>
> [enp138s0f0]
> ts2phc.extts_polarity rising
>
>
>
> Log sample:
>
> 2022-03-15T04:50:26.000 controller-0 ts2phc: debug [1036434.421] nmea
> delay: 379832699 ns
> 2022-03-15T04:50:26.000 controller-0 ts2phc: debug [1036434.422]
> enp81s0f0 extts index 0 at 1647319864.000000000 corr 0 src
> 1647319864.620189416 diff 0
> 2022-03-15T04:50:26.000 controller-0 ts2phc: debug [1036434.422]
> enp81s0f0 master offset 0 s2 freq +0
> 2022-03-15T04:50:26.000 controller-0 ts2phc: debug [1036434.422] nmea
> delay: 379832699 ns
> 2022-03-15T04:50:26.000 controller-0 ts2phc: debug [1036434.422]
> enp138s0f0 extts index 0 at 1647319863.999999999 corr 0 src
> 1647319864.620839770 diff -1
> 2022-03-15T04:50:26.000 controller-0 ts2phc: debug [1036434.422]
> enp138s0f0 master offset -1 s2 freq +1
> 2022-03-15T04:50:27.000 controller-0 ts2phc: debug [1036435.421] nmea
> delay: 319026253 ns
> 2022-03-15T04:50:27.000 controller-0 ts2phc: debug [1036435.422]
> enp81s0f0 extts index 0 at 1647319865.000000000 corr 0 src
> 1647319865.680996587 diff 0
> 2022-03-15T04:50:27.000 controller-0 ts2phc: debug [1036435.422]
> enp81s0f0 master offset 0 s2 freq +0
> 2022-03-15T04:50:27.000 controller-0 ts2phc: debug [1036435.422] nmea
> delay: 319026253 ns
> 2022-03-15T04:50:27.000 controller-0 ts2phc: debug [1036435.422]
> enp138s0f0 extts index 0 at 1647319865.000000000 corr 0 src
> 1647319865.681640151 diff 0
> 2022-03-15T04:50:27.000 controller-0 ts2phc: debug [1036435.422]
> enp138s0f0 master offset 0 s2 freq +1
> 2022-03-15T04:50:28.000 controller-0 ts2phc: debug [1036436.421] nmea
> delay: 314155539 ns
> 2022-03-15T04:50:28.000 controller-0 ts2phc: debug [1036436.422]
> enp81s0f0 extts index 0 at 1647319866.000000000 corr 0 src
> 1647319866.685874828 diff 0
> 2022-03-15T04:50:28.000 controller-0 ts2phc: debug [1036436.422]
> enp81s0f0 master offset 0 s2 freq +0
> 2022-03-15T04:50:28.000 controller-0 ts2phc: debug [1036436.422] nmea
> delay: 314155539 ns
> 2022-03-15T04:50:28.000 controller-0 ts2phc: debug [1036436.422]
> enp138s0f0 extts index 0 at 1647319866.000000001 corr 0 src
> 1647319866.686513484 diff 1
> 2022-03-15T04:50:28.000 controller-0 ts2phc: debug [1036436.422]
> enp138s0f0 master offset 1 s2 freq +2
> 2022-03-15T04:50:29.000 controller-0 ts2phc: debug [1036437.422] nmea
> delay: 790744992 ns
>
It looks like nmea delay increased by about half a second here.
> # Things go weird here
> # The src value appears to be behind the previous one?
> 2022-03-15T04:50:29.000 controller-0 ts2phc: debug [1036437.422]
> enp138s0f0 extts index 0 at 1647319866.999999999 corr 0 src
> 1647319866.209929593 diff 999999999
> 2022-03-15T04:50:29.000 controller-0 ts2phc: debug [1036437.422]
> enp138s0f0 master offset 999999999 s2 freq +900000000
> 2022-03-15T04:50:30.000 controller-0 ts2phc: debug [1036437.434] nmea
> delay: 790744992 ns
> 2022-03-15T04:50:30.000 controller-0 ts2phc: debug [1036437.434]
> enp81s0f0 extts index 0 at 1647319867.000000000 corr 0 src
> 1647319866.221685020 diff 1000000000
> 2022-03-15T04:50:30.000 controller-0 ts2phc: debug [1036437.434]
> enp81s0f0 master offset 1000000000 s2 freq +900000000
> 2022-03-15T04:50:30.000 controller-0 ts2phc: debug [1036438.351] nmea
> delay: 234127497 ns
> 2022-03-15T04:50:30.000 controller-0 ts2phc: debug [1036438.351]
> enp81s0f0 extts index 0 at 1647319867.111604645 corr 0 src
> 1647319868.695211166 diff -888395355
> 2022-03-15T04:50:30.000 controller-0 ts2phc: debug [1036438.351]
> enp81s0f0 master offset -888395355 s2 freq -888395355
> 2022-03-15T04:50:30.000 controller-0 ts2phc: debug [1036438.351] nmea
> delay: 234127497 ns
> 2022-03-15T04:50:30.000 controller-0 ts2phc: debug [1036438.351]
> enp138s0f0 extts index 0 at 1647319867.100432414 corr 0 src
> 1647319868.695795473 diff -899567586
> 2022-03-15T04:50:30.000 controller-0 ts2phc: debug [1036438.351]
> enp138s0f0 master offset -899567586 s2 freq -899567584
>
>
>
> The offset eventually stabilizes and carries on for a while before this
> symptom occurs again.
> I have made sure that ntpd is disabled and I am not running any other
> ptp services.
>
>
>
> Looking at the ts2phc code, it appears to me that the behaviour occurs
> in ts2phc_slave.c ts2phc_slave_offset() when this check isn't true.
>
> if (source_ts.tv_nsec > 500000000) {
> source_ts.tv_sec++;
> }
I'd have to did into ptp4l code to understand what this check is even doing.
>
> So something is resulting in source_ts.tv_nsec being a bad value.
>
>
> I would appreciate your thoughts on this issue. Should I be looking into
> the driver code, or is there more I can investigate in tsphc?
>
I'd be suspicious that something is wrong in the driver here.
We did a bunch of work on the driver around the 1.7.x release and into
the 1.8.x release. I would recommend trying out 1.8.3 and seeing if this
behavior persists.
> Let me know if additional log output would be useful.
>
I'm not sure what else logging could be useful. I had thought at first
that the issue came from a reported timestamp being incorrectly
extended, but looking at the ice driver the external timestamp events
actually do capture the full 64 bit timestamp value so that extension
function is not used.
>
> Thanks for your help,
>
> Cole
>
_______________________________________________
Linuxptp-users mailing list
Linuxptp-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/linuxptp-users
