Is 80us one way latency for python based events normal?

[kiasar]

Hi, first thanks for this awesome project.

We've been having a good time testing your library to understand it better. On reddit you reported the latency of Events to be around 2.5us, but when we test the events using two python processes on linux, we get on average 80us of latency. We've tested this on multiple different CPUs to make sure it's not a CPU artifact.

Wanted to ask if you think it's normal to have 80us (one way) latency on python processes or there is something wrong?

Just for the record, I put the toy example codes here:

Publisher:

import os
import threading
import time
import iceoryx2 as iox2
from multiprocessing import shared_memory
import numpy as np

print("PID:", os.getpid())
print("Thread ident:", threading.get_ident())
print("Native thread ID:", threading.get_native_id())

shape = (640, 360)
dtype = np.float64
nbytes = np.prod(shape) * np.dtype(dtype).itemsize
shm = shared_memory.SharedMemory(name="test", create=True, size=nbytes)
numpy_array = np.ndarray(shape, dtype=dtype, buffer=shm.buf)

node = (
    iox2.NodeBuilder.new().create(iox2.ServiceType.Ipc)
)
event_service = (
    node.service_builder(iox2.ServiceName.new("test_event"))
    .event()
    .event_id_max_value(256)
    .open_or_create()
)
event_id = iox2.EventId.new(1)
notifier = (
    event_service.notifier_builder()
    .default_event_id(event_id)
    .create()
)

count = 0

while True:
    numpy_array[1, 1] = count
    numpy_array[0, 0] = time.time_ns()
    notifier.notify_with_custom_event_id(event_id)
    time.sleep(.001)
    count += 1

Receiver:

import os
import threading
import time
import iceoryx2 as iox2
from multiprocessing import shared_memory
import numpy as np

print("PID:", os.getpid())
print("Thread ident:", threading.get_ident())
print("Native thread ID:", threading.get_native_id())

shape = (640, 360)
dtype = np.float64
shm = shared_memory.SharedMemory(name="test")
numpy_array = np.ndarray(shape, dtype=dtype, buffer=shm.buf)

node = (
    iox2.NodeBuilder.new().create(iox2.ServiceType.Ipc)
)
event_service = (
    node.service_builder(iox2.ServiceName.new("test_event"))
    .event()
    .open_or_create()
)

listener = event_service.listener_builder().create()

accum_elapsed = 0
num_samples = 0

for i in range(5000):
    event_id = listener.blocking_wait_one()
    time_ns = time.time_ns()
    send_time = numpy_array[0, 0]
    counter = numpy_array[1, 1]
    elapsed_ms = (time_ns - send_time) / 1e6
    accum_elapsed += elapsed_ms
    num_samples += 1

print("Average Latency:", accum_elapsed / num_samples)

[elfenpiff]

@kiasar Multiple factors could be the cause of this. First of all, could you please run our Rust event benchmark so that we have a baseline for your machines? You just need to call

cargo run --bin benchmark-event --release -- --bench-all

Do you compile iceoryx2 yourself, or do you use pip?

But I think the main thing is the following line in your publisher: time.sleep(.001) The main thing you are actually measuring is not the iceoryx2 latency but the latency of your OS scheduler.

As soon as you call listener.blocking_wait_one() and wait on the other side the OS scheduler moves the process down in the scheduling queue and puts it into deep sleep. Rescheduling a process and waking it up causes considerable effort on the OS side. So this is where the 80us are coming from - sometimes it is even more.

I could imagine that the latency might be reduced as soon as you remove the line time.sleep(.001). It will further go down when you use listener.try_wait_one() in a busy loop, because then the OS will never put the process into sleep mode and keeps everything fresh.

[kiasar]

@elfenpiff Thanks for your answer and help.

Just ran the --bench-all test and here are the results, the numbers are much lower:

iceoryx2::service::ipc::Service ::: MaxEventId: 128, Iterations: 1000000, Time: 9.295869651 s, Latency: 4647 ns
iceoryx2::service::ipc_threadsafe::Service ::: MaxEventId: 128, Iterations: 1000000, Time: 9.471050202 s, Latency: 4735 ns
iceoryx2::service::local::Service ::: MaxEventId: 128, Iterations: 1000000, Time: 9.371797163 s, Latency: 4685 ns
iceoryx2::service::local_threadsafe::Service ::: MaxEventId: 128, Iterations: 1000000, Time: 9.497507494 s, Latency: 4748 ns

Regarding this:

Do you compile iceoryx2 yourself, or do you use pip?

We use pip, if there is advantages to compile it ourself we can do that.

---

Thank you for the insight, the time.sleep(.001) is on the publisher side, does this really slow the time the receiver process receives the event? because we never put the receiver process on sleep.

[elfenpiff]

It indirectly does, since this call event_id = listener.blocking_wait_one() puts the receiver side instantly to sleep if there is no data available. And the longer it sleeps, the deeper the sleep gets - from a scheduler point of view.

At first, the process is constantly rescheduled to check if there is new data, but this only goes for several hundred nanoseconds, maybe a few microseconds. Then the process is removed from the internal queue and put into deep sleep. When something later happens, the process is reloaded, put into the scheduler queue again, and can continue to work - and this is the time-intensive part.

[kiasar]

Thank you for the answer, I never had thought about this aspect.