search

eclipse-iceoryx / iceoryx2

Eclipse iceoryx2™ - true zero-copy inter-process-communication in pure Rust
https://iceoryx.io
Apache License 2.0
1.03k stars 40 forks source link

Pub/sub: ~300 ms latency #434

Open nodakai opened 1 month ago

nodakai commented 1 month ago

Required information

Operating system:

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:

elfenpiff commented 1 month ago

@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 commented 1 month ago

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 commented 1 month ago

@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 commented 1 month ago

@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 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

@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 commented 1 month ago

@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

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 commented 1 month ago

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 commented 1 month ago

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.