Pub/sub: ~300 ms latency #434

nodakai · 2024-10-04T16:41:16Z

Required information

Operating system:

Debian trixie
Linux db 6.1.0-25-cloud-arm64 #1 SMP Debian 6.1.106-3 (2024-08-26) aarch64 GNU/Linux

Rust version:
rustc 1.81.0 (eeb90cda1 2024-09-04)

Cargo version:
cargo 1.81.0 (2dbb1af80 2024-08-20)

iceoryx2 version:

[dependencies]
iceoryx2 = "0.4.1"

Detailed log output:

Details

        0 [D] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 20, data: "config/iceoryx2.toml" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None, creation_mode: None }
              | Unable to open file since it does not exist.
        1 [D] Config { global: Global { root_path_unix: Path { value: FixedSizeByteString<255> { len: 14, data: "/tmp/iceoryx2/" } }, root_path_windows: Path { value: FixedSizeByteString<255> { len: 17, data: "c:\Temp\iceoryx2\" } }, prefix: FileName { value: FixedSizeByteString<255> { len: 5
              , data: "iox2_" } }, service: Service { directory: Path { value: FixedSizeByteString<255> { len: 8, data: "services" } }, publisher_data_segment_suffix: FileName { value: FixedSizeByteString<255> { len: 15, data: ".publisher_data" } }, static_config_storage_suffix: FileName { va
              lue: FixedSizeByteString<255> { len: 8, data: ".service" } }, dynamic_config_storage_suffix: FileName { value: FixedSizeByteString<255> { len: 8, data: ".dynamic" } }, creation_timeout: 500ms, connection_suffix: FileName { value: FixedSizeByteString<255> { len: 11, data: ".conne
              ction" } }, event_connection_suffix: FileName { value: FixedSizeByteString<255> { len: 6, data: ".event" } } }, node: Node { directory: Path { value: FixedSizeByteString<255> { len: 5, data: "nodes" } }, monitor_suffix: FileName { value: FixedSizeByteString<255> { len: 13, data:
               ".node_monitor" } }, static_config_suffix: FileName { value: FixedSizeByteString<255> { len: 8, data: ".details" } }, service_tag_suffix: FileName { value: FixedSizeByteString<255> { len: 12, data: ".service_tag" } }, cleanup_dead_nodes_on_creation: true, cleanup_dead_nodes_on_
              destruction: true } }, defaults: Defaults { publish_subscribe: PublishSubscribe { max_subscribers: 8, max_publishers: 2, max_nodes: 20, subscriber_max_buffer_size: 2, subscriber_max_borrowed_samples: 2, publisher_max_loaned_samples: 2, publisher_history_size: 1, enable_safe_over
              flow: true, unable_to_deliver_strategy: Block, subscriber_expired_connection_buffer: 128 }, event: Event { max_listeners: 2, max_notifiers: 16, max_nodes: 36, event_id_max_value: 32 } } }
              | Failed to create config since the config file could not be opened.
        2 [W] "Config::global_config()"
              | Default config file found but unable to read data, populate config with default values.
        3 [T] Directory { path: Path { value: FixedSizeByteString<255> { len: 48, data: "/tmp/iceoryx2/nodes/6479049688623293062137549711" } }, directory_stream: 0xaaaaf83ffb40, file_descriptor: FileDescriptor { value: 3, is_owned: false } }
              | created
        4 [T] Builder { storage_name: FileName { value: FixedSizeByteString<255> { len: 4, data: "node" } }, has_ownership: false, config: Configuration { path: Path { value: FixedSizeByteString<255> { len: 48, data: "/tmp/iceoryx2/nodes/6479049688623293062137549711" } }, suffix: FileName { v
              alue: FixedSizeByteString<255> { len: 8, data: ".details" } }, prefix: FileName { value: FixedSizeByteString<255> { len: 5, data: "iox2_" } } } }
              | Created service root directory "/tmp/iceoryx2/nodes/6479049688623293062137549711" since it did not exist before.
        5 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/6479049688623293062137549711/iox2_node.details" } }, access_mode: ReadWrite, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None
              , creation_mode: Some(CreateExclusive) }
              | created
        6 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 77, data: "/tmp/iceoryx2/nodes/iox2_6479049688623293062137549711.node_monitor_owner_lock" } }, access_mode: ReadWrite, permission: Permission(448), has_ownership: true, owner: None, group: None, truncate_
              size: None, creation_mode: Some(CreateExclusive) }
              | created
        7 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/iox2_6479049688623293062137549711.node_monitor" } }, access_mode: ReadWrite, permission: Permission(128), has_ownership: true, owner: None, group: None, truncate_size: None,
               creation_mode: Some(CreateExclusive) }
              | created
        8 [T] "ProcessGuard::new()"
              | create process state "/tmp/iceoryx2/nodes/iox2_6479049688623293062137549711.node_monitor" for monitoring
        9 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 106, data: "/tmp/iceoryx2/nodes/6479049688623293062137549711/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service_tag" } }, access_mode: ReadWrite, permission: Permission(448), has_ownership: false, owne
              r: None, group: None, truncate_size: None, creation_mode: Some(CreateExclusive) }
              | created
       10 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 76, data: "/tmp/iceoryx2/services/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service" } }, access_mode: ReadWrite, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_
              size: None, creation_mode: Some(CreateExclusive) }
              | created
       11 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 94, data: "iox2_305ad9523c6b202364d581359ec3d2c5743e42e7_4eacadf2695a3f4b2eb95485759246ce1a2aa906.dynamic" } }, size: 1411, base_address: 0xffff99b75000, has_ownership: false, file_descriptor: FileDescriptor 
              { value: 8, is_owned: true }, memory_lock: None }
              | create
       12 [T] "Service::open()"
              | open service: My/Funk/ServiceName (ServiceId(RestrictedFileName { value: FixedSizeByteString<64> { len: 40, data: "4eacadf2695a3f4b2eb95485759246ce1a2aa906" } }))
       13 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 116, data: "iox2_b9fc73e5c1f646968758453273c6c65cb372831b_80384572563851900296847201183_85727422363461066471884231567.connection" } }, size: 273, base_address: 0xffff99b74000, has_ownership: false, file_descr
              iptor: FileDescriptor { value: 6, is_owned: true }, memory_lock: None }
              | open
       14 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 97, data: "iox2_0354a209029e7d094a819e2d4030ea331e6caaf0_824223_80384572563851900296847201183.publisher_data" } }, size: 2242, base_address: 0xffff99b6f000, has_ownership: false, file_descriptor: FileDescript
              or { value: 9, is_owned: true }, memory_lock: None }
              | open
received: Msg { data: 1234, i: 1728059776063045068 } delay: 289894.3 us
received: Msg { data: 1234, i: 1728059777063175660 } delay: 289886.3 us
received: Msg { data: 1234, i: 1728059778063315400 } delay: 289876.7 us
received: Msg { data: 1234, i: 1728059779063456511 } delay: 289879.3 us
received: Msg { data: 1234, i: 1728059780063573663 } delay: 289897.6 us
received: Msg { data: 1234, i: 1728059781063700998 } delay: 289894.1 us
       15 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 116, data: "iox2_b9fc73e5c1f646968758453273c6c65cb372831b_80384572563851900296847201183_85727422363461066471884231567.connection" } }, size: 273, base_address: 0xffff99b74000, has_ownership: true, file_descri
              ptor: FileDescriptor { value: 6, is_owned: true }, memory_lock: None }
              | close
       16 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 116, data: "iox2_b9fc73e5c1f646968758453273c6c65cb372831b_80384572563851900296847201183_85727422363461066471884231567.connection" } }, size: 273, base_address: 0xffff99b74000, has_ownership: true, file_descri
              ptor: FileDescriptor { value: 6, is_owned: true }, memory_lock: None }
              | delete
       17 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 97, data: "iox2_0354a209029e7d094a819e2d4030ea331e6caaf0_824223_80384572563851900296847201183.publisher_data" } }, size: 2242, base_address: 0xffff99b6f000, has_ownership: false, file_descriptor: FileDescript
              or { value: 9, is_owned: true }, memory_lock: None }
              | close

        0 [D] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 20, data: "config/iceoryx2.toml" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None, creation_mode: None }
              | Unable to open file since it does not exist.
        1 [D] Config { global: Global { root_path_unix: Path { value: FixedSizeByteString<255> { len: 14, data: "/tmp/iceoryx2/" } }, root_path_windows: Path { value: FixedSizeByteString<255> { len: 17, data: "c:\Temp\iceoryx2\" } }, prefix: FileName { value: FixedSizeByteString<255> { len: 5
              , data: "iox2_" } }, service: Service { directory: Path { value: FixedSizeByteString<255> { len: 8, data: "services" } }, publisher_data_segment_suffix: FileName { value: FixedSizeByteString<255> { len: 15, data: ".publisher_data" } }, static_config_storage_suffix: FileName { va
              lue: FixedSizeByteString<255> { len: 8, data: ".service" } }, dynamic_config_storage_suffix: FileName { value: FixedSizeByteString<255> { len: 8, data: ".dynamic" } }, creation_timeout: 500ms, connection_suffix: FileName { value: FixedSizeByteString<255> { len: 11, data: ".conne
              ction" } }, event_connection_suffix: FileName { value: FixedSizeByteString<255> { len: 6, data: ".event" } } }, node: Node { directory: Path { value: FixedSizeByteString<255> { len: 5, data: "nodes" } }, monitor_suffix: FileName { value: FixedSizeByteString<255> { len: 13, data:
               ".node_monitor" } }, static_config_suffix: FileName { value: FixedSizeByteString<255> { len: 8, data: ".details" } }, service_tag_suffix: FileName { value: FixedSizeByteString<255> { len: 12, data: ".service_tag" } }, cleanup_dead_nodes_on_creation: true, cleanup_dead_nodes_on_
              destruction: true } }, defaults: Defaults { publish_subscribe: PublishSubscribe { max_subscribers: 8, max_publishers: 2, max_nodes: 20, subscriber_max_buffer_size: 2, subscriber_max_borrowed_samples: 2, publisher_max_loaned_samples: 2, publisher_history_size: 1, enable_safe_over
              flow: true, unable_to_deliver_strategy: Block, subscriber_expired_connection_buffer: 128 }, event: Event { max_listeners: 2, max_notifiers: 16, max_nodes: 36, event_id_max_value: 32 } } }
              | Failed to create config since the config file could not be opened.
        2 [W] "Config::global_config()"
              | Default config file found but unable to read data, populate config with default values.
        3 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/6479049688623293062137549711/iox2_node.details" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None, cre
              ation_mode: None }
              | opened
        4 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/iox2_6479049688623293062137549711.node_monitor" } }, access_mode: Write, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None, cr
              eation_mode: None }
              | opened
        5 [T] Directory { path: Path { value: FixedSizeByteString<255> { len: 48, data: "/tmp/iceoryx2/nodes/1128777915323046143846028191" } }, directory_stream: 0xaaab06de3ca0, file_descriptor: FileDescriptor { value: 3, is_owned: false } }
              | created
        6 [T] Builder { storage_name: FileName { value: FixedSizeByteString<255> { len: 4, data: "node" } }, has_ownership: false, config: Configuration { path: Path { value: FixedSizeByteString<255> { len: 48, data: "/tmp/iceoryx2/nodes/1128777915323046143846028191" } }, suffix: FileName { v
              alue: FixedSizeByteString<255> { len: 8, data: ".details" } }, prefix: FileName { value: FixedSizeByteString<255> { len: 5, data: "iox2_" } } } }
              | Created service root directory "/tmp/iceoryx2/nodes/1128777915323046143846028191" since it did not exist before.
        7 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/1128777915323046143846028191/iox2_node.details" } }, access_mode: ReadWrite, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None
              , creation_mode: Some(CreateExclusive) }
              | created
        8 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 77, data: "/tmp/iceoryx2/nodes/iox2_1128777915323046143846028191.node_monitor_owner_lock" } }, access_mode: ReadWrite, permission: Permission(448), has_ownership: true, owner: None, group: None, truncate_
              size: None, creation_mode: Some(CreateExclusive) }
              | created
        9 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/iox2_1128777915323046143846028191.node_monitor" } }, access_mode: ReadWrite, permission: Permission(128), has_ownership: true, owner: None, group: None, truncate_size: None,
               creation_mode: Some(CreateExclusive) }
              | created
       10 [T] "ProcessGuard::new()"
              | create process state "/tmp/iceoryx2/nodes/iox2_1128777915323046143846028191.node_monitor" for monitoring
       11 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 76, data: "/tmp/iceoryx2/services/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size:
               None, creation_mode: None }
              | opened
       12 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 76, data: "/tmp/iceoryx2/services/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size:
               None, creation_mode: None }
              | opened
       13 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 76, data: "/tmp/iceoryx2/services/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size:
               None, creation_mode: None }
              | opened
       14 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 76, data: "/tmp/iceoryx2/services/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size:
               None, creation_mode: None }
              | opened
       15 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 106, data: "/tmp/iceoryx2/nodes/1128777915323046143846028191/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service_tag" } }, access_mode: ReadWrite, permission: Permission(448), has_ownership: false, owne
              r: None, group: None, truncate_size: None, creation_mode: Some(CreateExclusive) }
              | created
       16 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 94, data: "iox2_305ad9523c6b202364d581359ec3d2c5743e42e7_4eacadf2695a3f4b2eb95485759246ce1a2aa906.dynamic" } }, size: 1411, base_address: 0xffff9962f000, has_ownership: false, file_descriptor: FileDescriptor 
              { value: 9, is_owned: true }, memory_lock: None }
              | open
       17 [T] "Service::open()"
              | open service: My/Funk/ServiceName (ServiceId(RestrictedFileName { value: FixedSizeByteString<64> { len: 40, data: "4eacadf2695a3f4b2eb95485759246ce1a2aa906" } }))
       18 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 97, data: "iox2_0354a209029e7d094a819e2d4030ea331e6caaf0_824223_80384572563851900296847201183.publisher_data" } }, size: 2242, base_address: 0xffff9962e000, has_ownership: true, file_descriptor: FileDescripto
              r { value: 6, is_owned: true }, memory_lock: None }
              | create
       19 [D] SharedMemoryBuilder { name: FileName { value: FixedSizeByteString<255> { len: 116, data: "iox2_b9fc73e5c1f646968758453273c6c65cb372831b_80384572563851900296847201183_85727422363461066471884231567.connection" } }, size: 0, is_memory_locked: false, has_ownership: true, permission:
               Permission(448), creation_mode: None, zero_memory: true, access_mode: ReadWrite, enforce_base_address: None }
              | Unable to open shared memory since the shared memory does not exist.
       20 [D] Builder { storage_name: FileName { value: FixedSizeByteString<255> { len: 59, data: "80384572563851900296847201183_85727422363461066471884231567" } }, supplementary_size: 113, has_ownership: true, config: Configuration { suffix: FileName { value: FixedSizeByteString<255> { len: 
              11, data: ".connection" } }, prefix: FileName { value: FixedSizeByteString<255> { len: 5, data: "iox2_" } }, path: Path { value: FixedSizeByteString<255> { len: 14, data: "/tmp/iceoryx2/" } }, _data: PhantomData }, timeout: 500ms, initializer: , _phantom_data: PhantomData }
              | Failed to open  since a shared memory with that name does not exists.
       21 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 116, data: "iox2_b9fc73e5c1f646968758453273c6c65cb372831b_80384572563851900296847201183_85727422363461066471884231567.connection" } }, size: 273, base_address: 0xffff99629000, has_ownership: true, file_descri
              ptor: FileDescriptor { value: 8, is_owned: true }, memory_lock: None }
              | create
published: Msg { data: 1234, i: 1728059776063045068 }
published: Msg { data: 1234, i: 1728059777063175660 }
published: Msg { data: 1234, i: 1728059778063315400 }
published: Msg { data: 1234, i: 1728059779063456511 }
published: Msg { data: 1234, i: 1728059780063573663 }
published: Msg { data: 1234, i: 1728059781063700998 }
^C       22 [D] "nanosleep_with_clock"
              | Interrupted "nanosleep": { duration: 1s, clock_type: Realtime }, remaining sleeping time: 0ns
       23 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 97, data: "iox2_0354a209029e7d094a819e2d4030ea331e6caaf0_824223_80384572563851900296847201183.publisher_data" } }, size: 2242, base_address: 0xffff9962e000, has_ownership: true, file_descriptor: FileDescripto
              r { value: 6, is_owned: true }, memory_lock: None }
              | close
       24 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 97, data: "iox2_0354a209029e7d094a819e2d4030ea331e6caaf0_824223_80384572563851900296847201183.publisher_data" } }, size: 2242, base_address: 0xffff9962e000, has_ownership: true, file_descriptor: FileDescripto
              r { value: 6, is_owned: true }, memory_lock: None }
              | delete
       25 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 116, data: "iox2_b9fc73e5c1f646968758453273c6c65cb372831b_80384572563851900296847201183_85727422363461066471884231567.connection" } }, size: 273, base_address: 0xffff99629000, has_ownership: false, file_descr
              iptor: FileDescriptor { value: 8, is_owned: true }, memory_lock: None }
              | close
       26 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 106, data: "/tmp/iceoryx2/nodes/1128777915323046143846028191/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service_tag" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: No
              ne, group: None, truncate_size: None, creation_mode: None }
              | opened
       27 [T] "File::remove"
              | "/tmp/iceoryx2/nodes/1128777915323046143846028191/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service_tag"
       28 [T] "ServiceState::drop()"
              | close service: My/Funk/ServiceName (ServiceId(RestrictedFileName { value: FixedSizeByteString<64> { len: 40, data: "4eacadf2695a3f4b2eb95485759246ce1a2aa906" } }))
       29 [T] SharedMemory { name: FileName { value: FixedSizeByteString<255> { len: 94, data: "iox2_305ad9523c6b202364d581359ec3d2c5743e42e7_4eacadf2695a3f4b2eb95485759246ce1a2aa906.dynamic" } }, size: 1411, base_address: 0xffff9962f000, has_ownership: false, file_descriptor: FileDescriptor 
              { value: 9, is_owned: true }, memory_lock: None }
              | close
       30 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/6479049688623293062137549711/iox2_node.details" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None, cre
              ation_mode: None }
              | opened
       31 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/iox2_6479049688623293062137549711.node_monitor" } }, access_mode: Write, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None, cr
              eation_mode: None }
              | opened
       32 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/1128777915323046143846028191/iox2_node.details" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None, cre
              ation_mode: None }
              | opened
       33 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { len: 66, data: "/tmp/iceoryx2/nodes/1128777915323046143846028191/iox2_node.details" } }, access_mode: Read, permission: Permission(448), has_ownership: false, owner: None, group: None, truncate_size: None, cre
              ation_mode: None }
              | opened
       34 [T] "File::remove"
              | "/tmp/iceoryx2/nodes/1128777915323046143846028191/iox2_node.details"
       35 [T] "Directory::remove"
              | removed "/tmp/iceoryx2/nodes/1128777915323046143846028191"
       36 [T] "File::remove"
              | "/tmp/iceoryx2/nodes/iox2_1128777915323046143846028191.node_monitor"
       37 [T] "File::remove"
              | "/tmp/iceoryx2/nodes/iox2_1128777915323046143846028191.node_monitor_owner_lock"

Observed result or behaviour:

received: Msg { data: 1234, i: 1728059776063045068 } delay: 289894.3 us

use std::time::Duration;
use std::env;

use libc;
use anyhow::Result;
use iceoryx2::prelude::*;
use iceoryx2_bb_log::{self, LogLevel};

const CYCLE_TIME: Duration = Duration::from_secs(1);

const SVC_NAME: &str = "My/Funk/ServiceName";

#[derive(Debug, Clone)]
struct Msg {
  data: usize,
  i: i64
}

pub fn current_time() -> i64 {
  let mut ts = libc::timespec { tv_sec: 0, tv_nsec: 0 };
  let rc = unsafe { libc::clock_gettime(libc::CLOCK_REALTIME, &mut ts) };
  if rc < 0 {
    panic!("clock_gettime failed: {rc}");
  }
  ts.tv_sec * 1_000_000_000_i64 + ts.tv_nsec
}

fn pub_main() -> Result<()> {
  let node = NodeBuilder::new().create::<ipc::Service>()?;

  let service =
    node.service_builder(&SVC_NAME.try_into()?)
    .publish_subscribe::<Msg>()
    .open_or_create()?;

  let publisher = service.publisher_builder().create()?;

  while let NodeEvent::Tick = node.wait(CYCLE_TIME) {
    let sample = publisher.loan_uninit()?;
    let data = Msg{data: 1234, i: current_time()};
    let sample = sample.write_payload(data.clone());
    sample.send()?;
    println!("published: {:?}", data);
  }

  Ok(())
}

fn sub_main() -> Result<()> {
  let node = NodeBuilder::new().create::<ipc::Service>()?;

  let service =
    node.service_builder(&SVC_NAME.try_into()?)
    .publish_subscribe::<Msg>()
    .open_or_create()?;

  let subscriber = service.subscriber_builder().create()?;

  while let NodeEvent::Tick = node.wait(CYCLE_TIME) {
    while let Some(sample) = subscriber.receive()? {
      let tr = current_time();
      let dt = tr - sample.i;

      println!("received: {:?} delay: {:.1} us", *sample, dt as f64 * 1e-3);
    }
  }

  Ok(())
}

fn main() -> Result<()> {
  set_log_level(LogLevel::Trace);
  if env::args().skip(1).any(|e| e == "--pub") {
    pub_main()
  } else {
    sub_main()
  }
}

Expected result or behaviour:

single digit us latency

Conditions where it occurred / Performed steps:

The text was updated successfully, but these errors were encountered:

elfenpiff · 2024-10-04T16:45:56Z

@nodakai I think if you change the code in the subscriber to:

  // while let NodeEvent::Tick = node.wait(CYCLE_TIME) {
  //  while let Some(sample) = subscriber.receive()? {
  while let NodeEvent::Tick = node.wait(Duration::ZERO) {
    if let Some(sample) = subscriber.receive()? {
      let tr = current_time();
      let dt = tr - sample.i;

      println!("received: {:?} delay: {:.1} us", *sample, dt as f64 * 1e-3);
    }
  }

It would fix the issue.

If you do not want to perform a busy wait, you can combine the publish-subscribe service with an event service and fire an event after the publisher has sent the message. On the subscriber side you wait on a listener until you have received the event and then receive your sample on the subscriber. For the event you can find an example here: https://github.com/eclipse-iceoryx/iceoryx2/tree/main/examples/rust/event

nodakai · 2024-10-04T17:08:36Z

Hmm, applying the suggested change (Duration::ZERO only) reduced latency to 20--50 us, without consuming 100 % CPU core. So it appears that IO2's implementation does not rely on classical busy looping on an atomic variable in shared memory? Is there any docs on what synchronization primitives are used for each operation mode?

It's still much slower than these numbers so I'll have to continue investigation
https://github.com/eclipse-iceoryx/iceoryx2/blob/main/internal/plots/benchmark_mechanism.svg

elfenpiff · 2024-10-04T18:03:26Z

@nodakai another problem can be this call libc::clock_gettime(libc::CLOCK_REALTIME, &mut ts) depending on what underlying clock source it uses - either HPET or TSC. With one of them you have a huge performance impact @elBoberido knows more here.
We encountered the same problem in our benchmarks and the solution was, instead of sending one sample and measure the time from A to B, we use a setup where process A sends a sample to process B and as soon as process B has received it, we send a sample back to A. We repeat this a million times and then measure the total time divided by the repetition times 2 (since we send the sample back and forth).

This is a common method called ping-pong benchmark.

elfenpiff · 2024-10-04T18:07:02Z

@nodakai Oh, could you adjust your code to:

  // while let NodeEvent::Tick = node.wait(CYCLE_TIME) {
  //  while let Some(sample) = subscriber.receive()? {
  loop {
    if let Some(sample) = subscriber.receive()? {
      let tr = current_time();
      let dt = tr - sample.i;

      println!("received: {:?} delay: {:.1} us", *sample, dt as f64 * 1e-3);
    }
  }

elfenpiff · 2024-10-04T18:11:10Z

Since you are working on an aarch64 target, you should be able to expect a latency in a single-digit microsecond, see: https://raw.githubusercontent.com/eclipse-iceoryx/iceoryx2/refs/heads/main/internal/plots/benchmark_architecture.svg

For the raspberry pi 4b we achieved a latency of ~800ns

nodakai · 2024-10-04T19:51:21Z

Removing node.wait(...) reduced latency further to 3--5 us at the cost of consuming 100 % CPU core (it does look like a busy looping now).

It still lags noticeably behind your Rasp Pi result. I know I shouldn't expect an ultimate performance from a shared, HT-enabled cloud machine but 0.8 us vs 5 us seems weird.

Was your Rasp Pi result obtained with busy looping (100 % CPU core consumption)?

I already verified the following test yields ~50 ns on the target Linux machine so I'm not worried about the accuracy/overhead of clock_gettime(CLOCK_REALTIME). It should be accelerated by vDSO https://man7.org/linux/man-pages/man7/vdso.7.html#ARCHITECTURE-SPECIFIC_NOTES

    loop {
      let t0 = current_time();
      let t1 = current_time();
      println!("t1 - t0 = {}", t1 - t0);
      std::thread::sleep(CYCLE_TIME);
    }

elBoberido · 2024-10-04T21:41:23Z

@nodakai I hesitate to ask, but are you building in release mode? On my system, debug builds are ~6.5 times slower than release builds.

elfenpiff · 2024-10-05T06:14:25Z

@nodakai

Was your Rasp Pi result obtained with busy looping (100 % CPU core consumption)?

Yes, our benchmarks are part of the repo and you can run them yourself: https://github.com/eclipse-iceoryx/iceoryx2/tree/main/benchmarks

cargo run --bin benchmark-publish-subscribe --release -- --bench-all runs a ping-pong style pub-sub benchmark with two busy spin loops
cargo run --bin benchmark-event --release -- --bench-all runs a ping-pong style event benchmark with two loop waiting for a notification. Here the threads perform under the hood a sys call to wait for the notification to arrive and then fire a response.

It still lags noticeably behind your Rasp Pi result. I know I shouldn't expect an ultimate performance from a shared, HT-enabled cloud machine but 0.8 us vs 5 us seems weird.

We never experimented with such a machine and our benchmark suite, but it would be good to add them. One idea is that the hardware is emulated, and you pay with latency? But this is just a wild guess.

nodakai · 2024-10-13T18:24:05Z

but are you building in release mode?

Surely using --release

Yes, our benchmarks are part of the repo and you can run them yourself: https://github.com/eclipse-iceoryx/iceoryx2/tree/main/benchmarks

Thanks, I'll give it a try. However, it seems that there’s quite a bit of parameter tuning involved. If the examples in the README aren’t reflective of typical usage, there might be room for improvement in the API design.

elfenpiff · 2024-10-14T09:35:18Z

Thanks, I'll give it a try. However, it seems that there’s quite a bit of parameter tuning involved. If the examples in the README aren’t reflective of typical usage, there might be room for improvement in the API design.

You could divide the parameter tuning into to fields: deployment and iceoryx2.

For the deployment we used the posix thread feature to pin a thread to a specific CPU core and add a high priority which reduces jittering from your OS.
For iceoryx2 it is essentially, the less the better (at least for most parameter). If you have a setup with 1 publisher and 1000 subscribers, the latency will go up - this goes also for other parameters like history size. In the future, we need to provide a benchmark for such a setups as well, but the first benchmark focuses on a minimal use case with one publisher and one subscriber. I expect only a few nanoseconds when you increase these numbers significantly - but this needs to be proven by a benchmark.

nodakai added the bug Something isn't working label Oct 4, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Pub/sub: ~300 ms latency #434

Pub/sub: ~300 ms latency #434

nodakai commented Oct 4, 2024

elfenpiff commented Oct 4, 2024 •

edited

Loading

nodakai commented Oct 4, 2024

elfenpiff commented Oct 4, 2024

elfenpiff commented Oct 4, 2024

elfenpiff commented Oct 4, 2024 •

edited

Loading

nodakai commented Oct 4, 2024

elBoberido commented Oct 4, 2024

elfenpiff commented Oct 5, 2024 •

edited

Loading

nodakai commented Oct 13, 2024

elfenpiff commented Oct 14, 2024 •

edited

Loading

Pub/sub: ~300 ms latency #434

Pub/sub: ~300 ms latency #434

Comments

nodakai commented Oct 4, 2024

Required information

elfenpiff commented Oct 4, 2024 • edited Loading

nodakai commented Oct 4, 2024

elfenpiff commented Oct 4, 2024

elfenpiff commented Oct 4, 2024

elfenpiff commented Oct 4, 2024 • edited Loading

nodakai commented Oct 4, 2024

elBoberido commented Oct 4, 2024

elfenpiff commented Oct 5, 2024 • edited Loading

nodakai commented Oct 13, 2024

elfenpiff commented Oct 14, 2024 • edited Loading

elfenpiff commented Oct 4, 2024 •

edited

Loading

elfenpiff commented Oct 4, 2024 •

edited

Loading

elfenpiff commented Oct 5, 2024 •

edited

Loading

elfenpiff commented Oct 14, 2024 •

edited

Loading