Merge pull request #137 from elfenpiff/iox2-136-reduce-clock-gettime-…

…usage

[#136] Remove clock_gettime usage; add benchmark configurability

CHANGELOG.md

@@ -1,4 +1,5 @@
 # Changelog
 
  * [unreleased](doc/release-notes/iceoryx2-unreleased.md)
- * [v0.0.1]()
+ * [v0.2.2](doc/release-notes/iceoryx2-v0.2.2.md)
+ * [v0.2.1](doc/release-notes/iceoryx2-v0.2.1.md)

Cargo.toml

@@ -58,7 +58,7 @@ bindgen = { version = "0.65.1" }
 bitflags = { version = "1.3.2" }
 cc = { version = "1.0" }
 cdr = { version = "0.2.4" }
-clap = { version = "3.2.0", features = ["derive"] }
+clap = { version = "3.2.25", features = ["derive"] }
 enum-iterator = { version = "1.2.0" }
 generic-tests = { version = "0.1.2" }
 lazy_static = { version = "1.4.0" }

benchmarks/README.md

@@ -10,5 +10,11 @@ respond upon message reception. This process repeats `n` times, and the average
 latency is subsequently computed.
 
 ```sh
-cargo run --release benchmark_publish_subscribe
+cargo run --release benchmark-publish-subscribe -- --bench-all
+```
+
+For more benchmark configuration details, see
+
+```sh
+cargo run --release benchmark-publish-subscribe -- --help
 ```

benchmarks/publish-subscribe/Cargo.toml

@@ -15,3 +15,5 @@ iceoryx2-bb-log = { workspace = true }
 iceoryx2 = { workspace = true }
 iceoryx2-bb-posix = { workspace = true }
 iceoryx2-bb-container = { workspace = true }
+
+clap = { workspace = true }

benchmarks/publish-subscribe/src/main.rs

@@ -10,14 +10,15 @@
 //
 // SPDX-License-Identifier: Apache-2.0 OR MIT
 
+use clap::Parser;
 use iceoryx2::prelude::*;
 use iceoryx2_bb_log::set_log_level;
 use iceoryx2_bb_posix::barrier::BarrierHandle;
 use iceoryx2_bb_posix::{barrier::BarrierBuilder, clock::Time};
 
 const ITERATIONS: u64 = 10000000;
 
-fn perform_benchmark<T: Service>() {
+fn perform_benchmark<T: Service>(iterations: u64) {
     let service_name_a2b = ServiceName::new("a2b").unwrap();
     let service_name_b2a = ServiceName::new("b2a").unwrap();
 
@@ -27,7 +28,7 @@ fn perform_benchmark<T: Service>() {
         .max_subscribers(1)
         .history_size(0)
         .subscriber_max_buffer_size(1)
-        .enable_safe_overflow(false)
+        .enable_safe_overflow(true)
         .create::<u64>()
         .unwrap();
 
@@ -37,7 +38,7 @@ fn perform_benchmark<T: Service>() {
         .max_subscribers(1)
         .history_size(0)
         .subscriber_max_buffer_size(1)
-        .enable_safe_overflow(false)
+        .enable_safe_overflow(true)
         .create::<u64>()
         .unwrap();
 
@@ -51,7 +52,7 @@ fn perform_benchmark<T: Service>() {
 
             barrier.wait();
 
-            for i in 0..ITERATIONS {
+            for i in 0..iterations {
                 while sender_a2b.send_copy(i).expect("failed to send") == 0 {}
 
                 while receiver_b2a.receive().unwrap().is_none() {}
@@ -64,7 +65,7 @@ fn perform_benchmark<T: Service>() {
 
             barrier.wait();
 
-            for i in 0..ITERATIONS {
+            for i in 0..iterations {
                 while receiver_a2b.receive().unwrap().is_none() {}
 
                 while sender_b2a.send_copy(i).expect("failed to send") == 0 {}
@@ -79,16 +80,51 @@ fn perform_benchmark<T: Service>() {
         t2.join().expect("thread failure");
         let stop = start.elapsed().expect("failed to measure time");
         println!(
-            "{} ::: Time: {}, Latency: {} ns",
+            "{} ::: Iterations: {}, Time: {}, Latency: {} ns",
             std::any::type_name::<T>(),
+            iterations,
             stop.as_secs_f64(),
-            stop.as_nanos() / (ITERATIONS as u128 * 2)
+            stop.as_nanos() / (iterations as u128 * 2)
         );
     });
 }
 
+#[derive(Parser, Debug)]
+#[clap(version, about, long_about = None)]
+struct Args {
+    /// Number of iterations the A --> B --> A communication is repeated
+    #[clap(short, long, default_value_t = ITERATIONS)]
+    iterations: u64,
+    /// Run benchmark for every service setup
+    #[clap(short, long, default_value_t = false)]
+    bench_all: bool,
+    /// Run benchmark for the IPC zero copy setup
+    #[clap(short, long, default_value_t = false)]
+    bench_zero_copy: bool,
+    /// Run benchmark for the process local setup
+    #[clap(short, long, default_value_t = false)]
+    bench_process_local: bool,
+}
+
 fn main() {
+    let args = Args::parse();
+
     set_log_level(iceoryx2_bb_log::LogLevel::Error);
-    perform_benchmark::<zero_copy::Service>();
-    perform_benchmark::<process_local::Service>();
+    let mut at_least_one_benchmark_did_run = false;
+
+    if args.bench_zero_copy || args.bench_all {
+        perform_benchmark::<zero_copy::Service>(args.iterations);
+        at_least_one_benchmark_did_run = true;
+    }
+
+    if args.bench_process_local || args.bench_all {
+        perform_benchmark::<process_local::Service>(args.iterations);
+        at_least_one_benchmark_did_run = true;
+    }
+
+    if !at_least_one_benchmark_did_run {
+        println!(
+            "Please use either '--bench_all' or select a specific benchmark. See `--help` for details."
+        );
+    }
 }

doc/release-notes/iceoryx2-unreleased.md

@@ -13,6 +13,7 @@
  * New constructs from [#123](https://github.com/eclipse-iceoryx/iceoryx2/issues/123)
     * Introduce semantic string `iceoryx2-bb-system-types::base64url`
     * Introduce `iceoryx2-cal::hash::HashValue` that contains the result of a hash
+ * Performance improvements, especially for AMD CPUs [#136](https://github.com/eclipse-iceoryx/iceoryx2/issues/136)
 
 ### Bugfixes
 
@@ -51,6 +52,7 @@
  * Introduce traits for all ports (`Listen`, `Notify`, `Publish`, `DefaultLoan`, `UninitLoan`, `Subscribe`)
    and for samples (`PayloadMut`, `Payload`) [#69](https://github.com/eclipse-iceoryx/iceoryx2/issues/69)
  * Implement `Ord` and `PartialOrd` for `FixedSizeByteString` and `ServiceName` [#110](https://github.com/eclipse-iceoryx/iceoryx2/issues/110)
+ * Remove `publish_subscribe::Header::time_stamp()` due to ordering and performance problems [#136](https://github.com/eclipse-iceoryx/iceoryx2/issues/136)
 
 ### API Breaking Changes
 
@@ -125,3 +127,52 @@
     // new
     fn my_generic_service_function<ServiceType: iceoryx2::service::Service>();
     ```
+
+5. Do not use `Header::time_stamp()`, when required make it part of the payload
+    type. **Be aware, this can be expensive and can lead to a significantly increased latency!**
+
+    ```rust
+    // old
+    let subscriber = service.subscriber().create()?;
+    println!("sample timestamp: {:?}", sample.unwrap().header().time_stamp());
+
+    // new
+    use iceoryx2_bb_posix::clock::{Time, TimeBuilder};
+
+    #[derive(Debug)]
+    #[repr(C)]
+    pub struct TimeStamp {
+        seconds: u64,
+        nanoseconds: u32,
+    }
+
+    impl TimeStamp {
+        pub fn new() -> Self {
+            let now = Time::now().unwrap();
+            Self {
+                seconds: now.seconds(),
+                nanoseconds: now.nanoseconds(),
+            }
+        }
+    }
+
+    pub struct MyMessageType {
+        payload: u64,
+        time_stamp: TimeStamp
+    }
+
+    // sender side
+    let publisher = service.publisher().create()?;
+    let sample = publisher.loan_uninit()?;
+    let sample = sample.write_payload(MyMessageType {
+        payload: 1234,
+        time_stamp: TimeStamp::now();
+    });
+    sample.send()?;
+
+    // receiver side
+    let subscriber = service.subscriber().create()?;
+    println!("sample timestamp: {:?}", sample.unwrap().time_stamp);
+    ```
+
+

iceoryx2/src/sample.rs

@@ -23,8 +23,7 @@
 //!
 //! while let Some(sample) = subscriber.receive()? {
 //!     println!("received: {:?}", *sample);
-//!     println!("header timestamp {:?}, publisher id {:?}",
-//!         sample.header().time_stamp(), sample.header().publisher_id());
+//!     println!("header publisher id {:?}", sample.header().publisher_id());
 //! }
 //!
 //! # Ok(())

iceoryx2/src/sample_mut.rs

@@ -26,8 +26,7 @@
 //! let sample = publisher.loan_uninit()?;
 //! let sample = sample.write_payload(1234);
 //!
-//! println!("timestamp: {:?}, publisher port id: {:?}",
-//!     sample.header().time_stamp(), sample.header().publisher_id());
+//! println!("publisher port id: {:?}", sample.header().publisher_id());
 //! sample.send()?;
 //!
 //! # Ok(())

iceoryx2/src/service/header/publish_subscribe.rs

@@ -30,48 +30,23 @@
 //! # Ok(())
 //! # }
 //! ```
-use iceoryx2_bb_posix::clock::{Time, TimeBuilder};
-
 use crate::port::port_identifiers::UniquePublisherId;
 
-#[derive(Debug)]
-#[repr(C)]
-struct TimeStamp {
-    seconds: u64,
-    nanoseconds: u32,
-}
-
 /// Message header used by
 /// [`MessagingPattern::PublishSubscribe`](crate::service::messaging_pattern::MessagingPattern::PublishSubscribe)
 #[derive(Debug)]
 #[repr(C)]
 pub struct Header {
     publisher_port_id: UniquePublisherId,
-    time_stamp: TimeStamp,
 }
 
 impl Header {
     pub(crate) fn new(publisher_port_id: UniquePublisherId) -> Self {
-        let now = Time::now().unwrap();
-        Self {
-            publisher_port_id,
-            time_stamp: TimeStamp {
-                seconds: now.seconds(),
-                nanoseconds: now.nanoseconds(),
-            },
-        }
+        Self { publisher_port_id }
     }
 
     /// Returns the [`UniquePublisherId`] of the source [`crate::port::publisher::Publisher`].
     pub fn publisher_id(&self) -> UniquePublisherId {
         self.publisher_port_id
     }
-
-    /// Returns the [`Time`] when the [`crate::sample::Sample`] was delivered.
-    pub fn time_stamp(&self) -> Time {
-        TimeBuilder::new()
-            .nanoseconds(self.time_stamp.nanoseconds)
-            .seconds(self.time_stamp.seconds)
-            .create()
-    }
 }