Menu ▾ ▴

Offset above 1 second (10075080.684773270 s). Clock will step.

Help
Thomas F.
2019-09-06
2019-09-24

  • Thomas F.

    Thomas F. - 2019-09-06

    Hello,

    The time master was a Linux system with PTP4L started as:
    ptp4l -i eth0.1234 -S -E -2 -m -q

    The ptpd client was started as:
    ptpd2 -i vlan1234 -s -E -C -L --ptpengine:transport="ethernet" --ptpengine:use_libpcap="Y"

    The output I get from ptpd client is the following:

    2020-01-01 00:04:24.297000 ptpd2[852006].vlan1234 (notice)    (lstn_init) Now in state: PTP_LISTENING
2020-01-01 00:04:26.266000 ptpd2[852006].vlan1234 (info)      (lstn_init) New best master selected: b827ebfffe009301(unknown)/1
2020-01-01 00:04:26.266000 ptpd2[852006].vlan1234 (notice)    (slv) Now in state: PTP_SLAVE, Best master: b827ebfffe009301(unknown)/1
2020-01-01 00:04:26.320000 ptpd2[852006].vlan1234 (notice)    (slv) Received first Sync from Master
2020-01-01 00:04:27.320000 ptpd2[852006].vlan1234 (critical)  (slv) Offset above 1 second (10075082.684904074 s). Clock will step.

    Hint: The client system was set to 2020-01-01 00:00:00 before starting PTP.

    Now the clock syncs to the time master and jumps to the current time which was received via PTP:

    2019-09-06 09:26:21.577095 ptpd2[852006].vlan1234 (warning)   (slv) Stepped the system clock to: 09/06/19 09:26:21.577095926
2019-09-06 09:26:21.601095 ptpd2[852006].vlan1234 (notice)    (lstn_reset) Now in state: PTP_LISTENING

2019-09-06 09:26:22.520095 ptpd2[852006].vlan1234 (info)      (lstn_reset) New best master selected: b827ebfffe009301(unknown)/1
2019-09-06 09:26:22.521095 ptpd2[852006].vlan1234 (notice)    (slv) Now in state: PTP_SLAVE, Best master: b827ebfffe009301(unknown)/1
2019-09-06 09:26:22.577095 ptpd2[852006].vlan1234 (notice)    (slv) Received first Sync from Master

    Why is the offset still so huge here? The timestamp which is printed on the left matches the current time.
    And why is the 'state' alternating between "PTP_SLAVE" and "PTP_LISTENING" all the time?

    2019-09-06 09:26:23.577095 ptpd2[852006].vlan1234 (critical)  (slv) Offset above 1 second (10075080.684773270 s). Clock will step.
2019-09-06 09:26:23.577226 ptpd2[852006].vlan1234 (warning)   (slv) Stepped the system clock to: 09/06/19 09:26:23.577226730
2019-09-06 09:26:23.601226 ptpd2[852006].vlan1234 (notice)    (lstn_reset) Now in state: PTP_LISTENING

2019-09-06 09:26:24.520226 ptpd2[852006].vlan1234 (info)      (lstn_reset) New best master selected: b827ebfffe009301(unknown)/1
2019-09-06 09:26:24.521226 ptpd2[852006].vlan1234 (notice)    (slv) Now in state: PTP_SLAVE, Best master: b827ebfffe009301(unknown)/1
2019-09-06 09:26:24.577226 ptpd2[852006].vlan1234 (notice)    (slv) Received first Sync from Master

2019-09-06 09:26:25.577226 ptpd2[852006].vlan1234 (critical)  (slv) Offset above 1 second (10075078.684593299 s). Clock will step.
2019-09-06 09:26:25.577406 ptpd2[852006].vlan1234 (warning)   (slv) Stepped the system clock to: 09/06/19 09:26:25.577406701
2019-09-06 09:26:25.601406 ptpd2[852006].vlan1234 (notice)    (lstn_reset) Now in state: PTP_LISTENING

2019-09-06 09:26:26.520406 ptpd2[852006].vlan1234 (info)      (lstn_reset) New best master selected: b827ebfffe009301(unknown)/1
2019-09-06 09:26:26.521406 ptpd2[852006].vlan1234 (notice)    (slv) Now in state: PTP_SLAVE, Best master: b827ebfffe009301(unknown)/1
2019-09-06 09:26:26.577406 ptpd2[852006].vlan1234 (notice)    (slv) Received first Sync from Master

2019-09-06 09:26:27.577406 ptpd2[852006].vlan1234 (critical)  (slv) Offset above 1 second (10075076.684307860 s). Clock will step.
2019-09-06 09:26:27.577692 ptpd2[852006].vlan1234 (warning)   (slv) Stepped the system clock to: 09/06/19 09:26:27.577692140
2019-09-06 09:26:27.600692 ptpd2[852006].vlan1234 (notice)    (lstn_reset) Now in state: PTP_LISTENING

    Thanks,

    Thomas

     

    Last edit: Thomas F. 2019-09-16

  • Thomas F.

    Thomas F. - 2019-09-18

    The same behavior occurs also when only using ptpd (as master and slave).

    MASTER:

    #~/00_TEMP/ptpd$ sudo src/ptpd2 -i vlan1234 -d 0 -M -E -C --ptpengine:transport=ethernet --ptpengine:dot1as=1 --ptpengine:disable_bmca=1
2019-09-18 15:04:51.369795 ptpd2[9318].startup (notice)    (___) PTPd version 2.3.2 starting
2019-09-18 15:04:51.369829 ptpd2[9318].startup (info)      (___) Starting ptpd2 daemon with parameters:      src/ptpd2 -i vlan1234 -d 0 -M -E -C
2019-09-18 15:04:51.369843 ptpd2[9318].startup (info)      (___) Checking configuration
2019-09-18 15:04:51.369996 ptpd2[9318].startup (info)      (___) Configuration OK
2019-09-18 15:04:51.370604 ptpd2[9318].startup (info)      (___) Successfully acquired lock on /var/run/ptpd2.lock
2019-09-18 15:04:51.370652 ptpd2[9318].startup (notice)    (___) PTPd started successfully on vlan1234 using "masteronly" preset (PID 9318)
2019-09-18 15:04:51.370665 ptpd2[9318].startup (info)      (___) TimingService.PTP0: PTP service init
2019-09-18 15:04:51.426757 ptpd2[9318].vlan1234 (notice)    (mst) Now in state: PTP_MASTER, Best master: 001b21fffedec69e(unknown)/1 (self)
2019-09-18 15:05:01.370697 ptpd2[9318].vlan1234 (notice)    (mst) TimingService.PTP0: elected best TimingService
2019-09-18 15:05:01.370724 ptpd2[9318].vlan1234 (info)      (mst) TimingService.PTP0: acquired clock control

    SLAVE:

    # /scratch/ptpd2 -i vlan1234 -d 0 -s -E -C -L --ptpengine:transport=ethernet --ptpengine:dot1as=1
2020-01-01 00:02:36.400000 ptpd2[843814].startup (notice)    (___) PTPd version 2.3.2 starting
2020-01-01 00:02:36.402000 ptpd2[843814].startup (info)      (___) Starting ptpd2 daemon with parameters:      /scratch/ptpd2 -i vlan1234 -d 0 -s -E -C -L
2020-01-01 00:02:36.404000 ptpd2[843814].startup (info)      (___) Checking configuration
2020-01-01 00:02:36.407000 ptpd2[843814].startup (info)      (___) Configuration OK
2020-01-01 00:02:36.412000 ptpd2[843814].startup (notice)    (___) PTPd started successfully on vlan1234 using "slaveonly" preset (PID 843814)
2020-01-01 00:02:36.414000 ptpd2[843814].startup (info)      (___) TimingService.PTP0: PTP service init
2020-01-01 00:02:36.433000 ptpd2[843814].vlan1234 (info)      (init) Observed_drift loaded from kernel: 0 ppb
2020-01-01 00:02:36.435000 ptpd2[843814].vlan1234 (notice)    (lstn_init) Now in state: PTP_LISTENING
2020-01-01 00:02:37.101000 ptpd2[843814].vlan1234 (info)      (lstn_init) New best master selected: 001b21fffedec69e(unknown)/1
2020-01-01 00:02:37.103000 ptpd2[843814].vlan1234 (notice)    (slv) Now in state: PTP_SLAVE, Best master: 001b21fffedec69e(unknown)/1
2020-01-01 00:02:37.144000 ptpd2[843814].vlan1234 (notice)    (slv) Received first Sync from Master
2020-01-01 00:02:37.145000 ptpd2[843814].vlan1234 (critical)  (slv) Offset above 1 second (9025386.784930000 s). Clock will step.
2019-09-18 12:59:29.615070 ptpd2[843814].vlan1234 (warning)   (slv) Stepped the system clock to: 09/18/19 12:59:29.615070000
2019-09-18 12:59:29.645070 ptpd2[843814].vlan1234 (notice)    (lstn_reset) Now in state: PTP_LISTENING
2019-09-18 12:59:31.569070 ptpd2[843814].vlan1234 (info)      (lstn_reset) New best master selected: 001b21fffedec69e(unknown)/1
2019-09-18 12:59:31.570070 ptpd2[843814].vlan1234 (notice)    (slv) Now in state: PTP_SLAVE, Best master: 001b21fffedec69e(unknown)/1
2019-09-18 12:59:31.612070 ptpd2[843814].vlan1234 (notice)    (slv) Received first Sync from Master
2019-09-18 12:59:31.613070 ptpd2[843814].vlan1234 (critical)  (slv) Offset above 1 second (9025384.784915000 s). Clock will step.
2019-09-18 12:59:31.615085 ptpd2[843814].vlan1234 (warning)   (slv) Stepped the system clock to: 09/18/19 12:59:31.615085000
2019-09-18 12:59:31.645085 ptpd2[843814].vlan1234 (notice)    (lstn_reset) Now in state: PTP_LISTENING
2019-09-18 12:59:33.569085 ptpd2[843814].vlan1234 (info)      (lstn_reset) New best master selected: 001b21fffedec69e(unknown)/1
2019-09-18 12:59:33.570085 ptpd2[843814].vlan1234 (notice)    (slv) Now in state: PTP_SLAVE, Best master: 001b21fffedec69e(unknown)/1
2019-09-18 12:59:33.612085 ptpd2[843814].vlan1234 (notice)    (slv) Received first Sync from Master
2019-09-18 12:59:33.613085 ptpd2[843814].vlan1234 (critical)  (slv) Offset above 1 second (9025382.784926999 s). Clock will step.
2019-09-18 12:59:33.615073 ptpd2[843814].vlan1234 (warning)   (slv) Stepped the system clock to: 09/18/19 12:59:33.615073000
2019-09-18 12:59:33.645073 ptpd2[843814].vlan1234 (notice)    (lstn_reset) Now in state: PTP_LISTENING

    The clock is correctly adjusted from 2020-01-01 00:02:37 to 2019-09-18 12:59:29 but there is still shown "Offset above 1 second (9025384.784915000 s)".

    Why is the offset still so huge? 9025384 seconds are around 104 days (however, the date 2019-09-18 is show correctly).

    Any ideas?

    Thanks,

    Thomas

     

  • Thomas F.

    Thomas F. - 2019-09-24

    It seems to be a problem with a wrong interrupt vector number in the function getTime().
    Does someone know, why the getTime() function is based on an interrupt for QNX Neutrino systems and interrupt-les for all other systems?

     

Log in to post a comment.