Huge delay (about 2 years) in ros messages timestamps when using PTP

Hardware
1

Hello, I’ve been an Ouster user for years but this never occured to me. Using a well known computer with PTP support, I am unable to sync my new Ouster OS1-128 with the v3.1 firmware. The timestamps on ROS are 2.3 years in the past.

I have originally posted an issue on github explaining what I’ve done in full detail: Huge delay (about 2 years) in ros messages timestamps when using PTP · Issue #366 · ouster-lidar/ouster-ros · GitHub

As per one of your colleagues’ suggestion, I’m reposting the content of that issue below (some things have been removed because I’m a new user):

Describe the bug
When the lidar is set in PTP mode, the timestamps produced have a fixed offset of 74986812 seconds (about 2 years) on a correctly configured machine with a PTP supported NIC.

The output of lspci -nnk | grep -A2 Ethernet is:

2d:00.0 Ethernet controller [0200]: Intel Corporation Device [8086:125b] (rev 04)
	Subsystem: ASRock Incorporation Device [1849:125b]
	Kernel driver in use: igc
--
2f:00.0 Ethernet controller [0200]: Intel Corporation Device [8086:125b] (rev 04)
	Subsystem: ASRock Incorporation Device [1849:125b]
	Kernel driver in use: igc

The output of ethtool -T enp45s0 is:

Time stamping parameters for enp45s0:
Capabilities:
	hardware-transmit     (SOF_TIMESTAMPING_TX_HARDWARE)
	software-transmit     (SOF_TIMESTAMPING_TX_SOFTWARE)
	hardware-receive      (SOF_TIMESTAMPING_RX_HARDWARE)
	software-receive      (SOF_TIMESTAMPING_RX_SOFTWARE)
	software-system-clock (SOF_TIMESTAMPING_SOFTWARE)
	hardware-raw-clock    (SOF_TIMESTAMPING_RAW_HARDWARE)
PTP Hardware Clock: 0
Hardware Transmit Timestamp Modes:
	off                   (HWTSTAMP_TX_OFF)
	on                    (HWTSTAMP_TX_ON)
Hardware Receive Filter Modes:
	none                  (HWTSTAMP_FILTER_NONE)
	all                   (HWTSTAMP_FILTER_ALL)

The Ouster diagnostic and ptp config files are attached here:
diagnostic_and_config.zip

To Reproduce

  1. connect the lidar to the ethernet port (in my case enp45s0) and set it to link local mode
  2. On one terminal, run the ptp4l utility (config file is attached):
sudo ptp4l -m -f /etc/linuxptp/ptp4l.conf

the output is as follows:

ptp4l[1817.658]: selected /dev/ptp0 as PTP clock
ptp4l[1817.658]: port 1: INITIALIZING to LISTENING on INIT_COMPLETE
ptp4l[1817.658]: port 0: INITIALIZING to LISTENING on INIT_COMPLETE
ptp4l[1825.211]: port 1: LISTENING to MASTER on ANNOUNCE_RECEIPT_TIMEOUT_EXPIRES
ptp4l[1825.211]: selected local clock 9c6b00.fffe.0118e9 as best master
ptp4l[1825.211]: assuming the grand master role
  1. On another terminal, run the phc2sys to sync the NIC to the CLOCK_REALTIME:
 sudo phc2sys -w -m -s CLOCK_REALTIME -c enp45s0 -O 0

Example output:

phc2sys[1900.970]: enp45s0 sys offset        -8 s2 freq  -24787 delay   4992
phc2sys[1901.970]: enp45s0 sys offset        -7 s2 freq  -24788 delay   5715
phc2sys[1902.971]: enp45s0 sys offset        25 s2 freq  -24758 delay   5721
phc2sys[1903.971]: enp45s0 sys offset        10 s2 freq  -24766 delay   5709
phc2sys[1904.972]: enp45s0 sys offset         8 s2 freq  -24765 delay   5728
phc2sys[1905.972]: enp45s0 sys offset       -12 s2 freq  -24782 delay   5728
phc2sys[1906.973]: enp45s0 sys offset        54 s2 freq  -24720 delay   5722
phc2sys[1907.973]: enp45s0 sys offset       -21 s2 freq  -24779 delay   5696
phc2sys[1908.974]: enp45s0 sys offset       -12 s2 freq  -24776 delay   5696
phc2sys[1909.974]: enp45s0 sys offset        71 s2 freq  -24697 delay   4115
  1. On a third terminal, run the compiled driver:
roslaunch ouster_ros driver.launch sensor_hostname:=os-122415000093.local
  1. Monitor the delay:
rostopic delay /ouster/imu

example output is:

subscribed to [/ouster/imu]
average delay: 74986812.741
	min: 74986812.494s max: 74986813.430s std dev: 0.30612s window: 181
average delay: 74986812.653
	min: 74986812.494s max: 74986813.430s std dev: 0.27229s window: 281
average delay: 74986812.611
	min: 74986812.494s max: 74986813.430s std dev: 0.24388s window: 381
average delay: 74986812.587
	min: 74986812.494s max: 74986813.430s std dev: 0.22207s window: 481
average delay: 74986812.571

which is consistent with the timestamps, which are in the order of 165xxxxxxx nanoseconds while the actual ones from all other sensors are 172xxxxxxx

The PTP syncing is correct as evidenced by the outputs above, but as double check the output of the CLOC_REALTIME and the NIC itself are also in sync:

phc_ctl CLOCK_REALTIME get
phc_ctl[3557.270]: clock time is 1726158140.991257534 or Thu Sep 12 18:22:20 2024

sudo phc_ctl enp45s0 get
phc_ctl[3557.275]: clock time is 1726158140.996777650 or Thu Sep 12 18:22:20 2024

Screenshots
Configuration on the dashboard (everything was left untouched except for the PTP timestamp mode on the Ouster):

For the screenshot, see the GitHub issue.

Platform (please complete the following information):

  • Ouster Sensor? OS-1-128
  • Ouster Firmware Version? v3.1.0 (ousteros-image-prod-bootes-v3.1.0+20240426041747)
  • ROS version/distro? noetic
  • Operating System? Ubuntu 20.04 with kernel 6.1.100-0601100-generic
  • Machine Architecture? x64
  • git commit hash: current origin/master as of 12 Sep 2024 (e59e9a4bd53a1a65a6f99f09d3bbbf35a0aea806).
    Note that at this hash, the submodule for the ouster-sdk points to: 2898060 which is from Oct 2023
2

linking the github issue to the post:

3

Hi @mcamurri, as I have previously asked, to be able to assist you we need to see the output of /api/v1/time/ptp, please also include the output of /api/v1/time/ and /api/v1/sensor/config. Thanks

4

Sorry I didn’t have access to the device until now. Here are the outputs of the commands. I have pretty printed them so they are easier to read:

Output of curl --request GET --url http://os-122415000093.local/api/v1/time/ptp is as follows:

{
  "current_data_set": {
    "steps_removed": 0,
    "offset_from_master": 0,
    "mean_path_delay": 0
  },
  "parent_data_set": {
    "parent_port_identity": "bc0fa7.fffe.00bbfb-0",
    "parent_stats": 0,
    "observed_parent_offset_scaled_log_variance": 65535,
    "observed_parent_clock_phase_change_rate": 2147483647,
    "grandmaster_priority1": 128,
    "gm_clock_class": 255,
    "gm_clock_accuracy": 254,
    "gm_offset_scaled_log_variance": 65535,
    "grandmaster_priority2": 128,
    "grandmaster_identity": "bc0fa7.fffe.00bbfb"
  },
  "time_properties_data_set": {
    "current_utc_offset": 37,
    "leap61": 0,
    "leap59": 0,
    "current_utc_offset_valid": 0,
    "ptp_timescale": 1,
    "time_traceable": 0,
    "frequency_traceable": 0,
    "time_source": 160
  },
  "time_status_np": {
    "master_offset": 0,
    "ingress_time": 0,
    "cumulative_scaled_rate_offset": 0,
    "scaled_last_gm_phase_change": 0,
    "gm_time_base_indicator": 0,
    "last_gm_phase_change": "0x0000'0000000000000000.0000",
    "gm_present": false,
    "gm_identity": "bc0fa7.fffe.00bbfb"
  },
  "port_data_set": {
    "port_identity": "bc0fa7.fffe.00bbfb-1",
    "port_state": "LISTENING",
    "log_min_delay_req_interval": 0,
    "peer_mean_path_delay": 0,
    "log_announce_interval": 1,
    "announce_receipt_timeout": 3,
    "log_sync_interval": 0,
    "delay_mechanism": 1,
    "log_min_pdelay_req_interval": 0,
    "version_number": 2
  },
  "profile": "default"
}

The output of curl --request GET --url http://os-122415000093.local/api/v1/time is as follows:

{
  "system": {
    "tracking": {
      "reference_id": "00000000",
      "remote_host": "",
      "stratum": 0,
      "ref_time_utc": 0,
      "system_time_offset": 7e-9,
      "last_offset": 0,
      "rms_offset": 0,
      "frequency": -5.614,
      "residual_frequency": 0,
      "skew": 0,
      "root_delay": 1,
      "root_dispersion": 1,
      "update_interval": 0,
      "leap_status": "not synchronised"
    },
    "monotonic": 843.215974759,
    "realtime": 1651168586.6396537
  },
  "sensor": {
    "timestamp": {
      "time": 1651168586.6368127,
      "mode": "TIME_FROM_PTP_1588",
      "time_options": {
        "ptp_1588": 1651168586,
        "sync_pulse_in": 838,
        "internal_osc": 837
      }
    },
    "sync_pulse_in": {
      "locked": 0,
      "polarity": "ACTIVE_HIGH",
      "diagnostics": {
        "last_period_nsec": 0,
        "count": 1,
        "count_unfiltered": 0
      }
    },
    "multipurpose_io": {
      "mode": "OFF",
      "sync_pulse_out": {
        "polarity": "ACTIVE_HIGH",
        "frequency_hz": 1,
        "angle_deg": 360,
        "pulse_width_ms": 10
      },
      "nmea": {
        "locked": 1,
        "polarity": "ACTIVE_HIGH",
        "ignore_valid_char": 0,
        "baud_rate": "BAUD_9600",
        "leap_seconds": 0,
        "diagnostics": {
          "decoding": {
            "utc_decoded_count": 0,
            "date_decoded_count": 0,
            "not_valid_count": 0,
            "last_read_message": ""
          },
          "io_checks": {
            "start_char_count": 0,
            "char_count": 0,
            "bit_count": 1,
            "bit_count_unfiltered": 0
          }
        }
      }
    }
  },
  "ptp": {
    "current_data_set": {
      "steps_removed": 0,
      "offset_from_master": 0,
      "mean_path_delay": 0
    },
    "parent_data_set": {
      "parent_port_identity": "bc0fa7.fffe.00bbfb-0",
      "parent_stats": 0,
      "observed_parent_offset_scaled_log_variance": 65535,
      "observed_parent_clock_phase_change_rate": 2147483647,
      "grandmaster_priority1": 128,
      "gm_clock_class": 255,
      "gm_clock_accuracy": 254,
      "gm_offset_scaled_log_variance": 65535,
      "grandmaster_priority2": 128,
      "grandmaster_identity": "bc0fa7.fffe.00bbfb"
    },
    "time_properties_data_set": {
      "current_utc_offset": 37,
      "leap61": 0,
      "leap59": 0,
      "current_utc_offset_valid": 0,
      "ptp_timescale": 1,
      "time_traceable": 0,
      "frequency_traceable": 0,
      "time_source": 160
    },
    "time_status_np": {
      "master_offset": 0,
      "ingress_time": 0,
      "cumulative_scaled_rate_offset": 0,
      "scaled_last_gm_phase_change": 0,
      "gm_time_base_indicator": 0,
      "last_gm_phase_change": "0x0000'0000000000000000.0000",
      "gm_present": false,
      "gm_identity": "bc0fa7.fffe.00bbfb"
    },
    "port_data_set": {
      "port_identity": "bc0fa7.fffe.00bbfb-1",
      "port_state": "LISTENING",
      "log_min_delay_req_interval": 0,
      "peer_mean_path_delay": 0,
      "log_announce_interval": 1,
      "announce_receipt_timeout": 3,
      "log_sync_interval": 0,
      "delay_mechanism": 1,
      "log_min_pdelay_req_interval": 0,
      "version_number": 2
    },
    "profile": "default"
  }
}

Finally, the output of curl --request GET --url http://os-122415000093.local/api/v1/sensor/config is as follows:

{
  "udp_dest": "169.254.75.79",
  "udp_port_lidar": 33898,
  "udp_port_imu": 39911,
  "udp_profile_lidar": "RNG19_RFL8_SIG16_NIR16",
  "udp_profile_imu": "LEGACY",
  "columns_per_packet": 16,
  "return_order": "STRONGEST_TO_WEAKEST",
  "timestamp_mode": "TIME_FROM_PTP_1588",
  "sync_pulse_in_polarity": "ACTIVE_HIGH",
  "nmea_in_polarity": "ACTIVE_HIGH",
  "nmea_ignore_valid_char": 0,
  "nmea_baud_rate": "BAUD_9600",
  "nmea_leap_seconds": 0,
  "multipurpose_io_mode": "OFF",
  "sync_pulse_out_polarity": "ACTIVE_HIGH",
  "sync_pulse_out_frequency": 1,
  "sync_pulse_out_angle": 360,
  "sync_pulse_out_pulse_width": 10,
  "operating_mode": "NORMAL",
  "lidar_mode": "1024x10",
  "azimuth_window": [
    0,
    360000
  ],
  "signal_multiplier": 1,
  "phase_lock_enable": false,
  "phase_lock_offset": 0,
  "min_range_threshold_cm": 50,
  "gyro_fsr": "NORMAL",
  "accel_fsr": "NORMAL"
}

For completness, I report the outputs of phc2sys and ptp4l as they are running right now:

sudo phc2sys -w -m -s CLOCK_REALTIME -c enp45s0 -O 0

phc2sys[1007.508]: enp45s0 sys offset       -37 s2 freq   -6833 delay   5082
phc2sys[1008.509]: enp45s0 sys offset        48 s2 freq   -6759 delay   5075
phc2sys[1009.509]: enp45s0 sys offset         5 s2 freq   -6787 delay   5139
phc2sys[1010.510]: enp45s0 sys offset       -15 s2 freq   -6806 delay   5107
phc2sys[1011.510]: enp45s0 sys offset        32 s2 freq   -6763 delay   5127
phc2sys[1012.510]: enp45s0 sys offset        -4 s2 freq   -6790 delay   5107
phc2sys[1013.511]: enp45s0 sys offset        57 s2 freq   -6730 delay   5094
phc2sys[1014.511]: enp45s0 sys offset        -9 s2 freq   -6779 delay   5152

sudo ptp4l -m -f /etc/linuxptp/ptp4l.conf

ptp4l[463.173]: selected /dev/ptp0 as PTP clock
ptp4l[463.174]: port 1: INITIALIZING to LISTENING on INIT_COMPLETE
ptp4l[463.174]: port 0: INITIALIZING to LISTENING on INIT_COMPLETE
ptp4l[470.189]: port 1: LISTENING to MASTER on ANNOUNCE_RECEIPT_TIMEOUT_EXPIRES
ptp4l[470.189]: selected local clock 9c6b00.fffe.0118e9 as best master
ptp4l[470.189]: assuming the grand master role
5

From my limited understanding of the json outputs it looks like the device is not able to pick up the grandmaster clock, the port state is LISTENING and the gm identity is not matching the output of the ptp4l output.

Could it be a hardware issue? I’m using a CAT6 cable so it should be fine.
Or perhaps a ethernet driver or kernel module poblem? It seems to be fine for other applications though…

6

Sorry to disturb @Samahu , are there any insight on the issue? Should I open a support ticket instead?

7

Hi @mcamurri, sorry for the late response but I was on vacation.
Reviewing the response you shared from the api/v1/time/ptp it is clear as you noted that the sensor is not properly configured to track time from the master clock. As noted in the Sensor PTP Verification Guide the port_data_set.port_state for the sensor should be SLAVE and time_status_np.gm_present value should be true.

You can reach our technical support team and check if they can offer some assistance with your PTP setup.

8

also I highly recommend that you read through the post Possible reasons that might cause PTP time synchronisation failure from one of technical staff. Specifically this paragraph which suggests that the issue might be due to mismatch between your PTP master configuration and the PTP sync requirements of Ouster sensors.

9

@mcamurri did you ever manage to find a solution to this? I am having the same issue and have tried the steps you have described, as well as the steps proposed in the link in the latest message in this thread (albeit the debugging advice in the final paragraph of that thread was quite vague)

Despite trying all that, still getting back "port_state": "LISTENING" and "gm_present": false from the lidar. Unsure if you’ve solved this issue and can pass on your findings.

Thanks!

10

I just wanted to follow up by saying that I found a solution to my problem - I assigned a static IP to my lidar rather than using the default link local setup.

I am not sure if PTP sync works with the lidar in link local mode, but the documentation does not appear to specify that a static IP is required for PTP sync to work. As soon as I made this change, my port_state changed to SLAVE and gm_present changed to true, which indicates that PTP synchronization is active on the lidar.

Hope this helps any future folks that come across this post. I would encourage the Ouster team to update documentation to explicitly state that a static IP is required, if that is indeed the case.

1 Like