Higher round trip time when using vsomeip3 compared to vsomeip

[kamelfakihh]

Hello,

I'm evaluating the round trip time (RTT) of a SOME/IP request response application. I measured RTT as the time between the moment I call app->send() and the moment I receive a response. To do so, I modified the official hello world example by adding measurement probes to the client. Then ran each of the client and service in a container.

I observed that when I build the application using version 2.10.11, RTT is around 500-1000 us, while when I build the application using version 3.5.1, RTT goes up to more the 10,000 us. Is this an expected behavior ? or am I missing something here ?

You can find the source code and docker files at github.com/kamelfakihh/vsomeip-docker-benchmark.

Note: I used version 2.10.11 specifically as I came across this evaluation on which the authors ran a similar benchmark and got a similar round trip to mine. In fact, I also run their benchmark with both version and still the older version was faster (you can also take a look at their benchmark in the repo I linked above or at github.com/netgroup-polito/secure-vsomeip

Edit : Added some logs below

1. vsomeip2

• client :

2024-10-17 09:02:35.112977 [info] Parsed vsomeip configuration in 0ms
2024-10-17 09:02:35.113065 [info] Using configuration file: "/vsomeip/_benchmark/hello_world/conf/client.json".
2024-10-17 09:02:35.113073 [info] Default configuration module loaded.
2024-10-17 09:02:35.113077 [info] Initializing vsomeip application "hello_world_client".
2024-10-17 09:02:35.113145 [info] SOME/IP client identifier configured. Using 1002 (was: 1002)
2024-10-17 09:02:35.113160 [info] Instantiating routing manager [Host].
2024-10-17 09:02:35.113193 [info] init_routing_endpoint Routing endpoint at /tmp/vsomeip-0
2024-10-17 09:02:35.131958 [info] Client [1002] is connecting to [0] at /tmp/vsomeip-0
2024-10-17 09:02:35.132002 [info] Service Discovery enabled. Trying to load module.
2024-10-17 09:02:35.132220 [info] Service Discovery module loaded.
2024-10-17 09:02:35.132267 [info] Application(hello_world_client, 1002) is initialized (11, 100).
2024-10-17 09:02:35.132288 [info] Starting vsomeip application "hello_world_client" using 2 threads
2024-10-17 09:02:35.132404 [info] shutdown thread id from application: 1002 (hello_world_client) is: 7f1bf4fd7700
2024-10-17 09:02:35.132427 [info] main dispatch thread id from application: 1002 (hello_world_client) is: 7f1bf57d8700
2024-10-17 09:02:35.152856 [info] Watchdog is disabled!
2024-10-17 09:02:35.152935 [info] REQUEST(1002): [1111.2222:255.4294967295]
2024-10-17 09:02:35.152966 [info] io thread id from application: 1002 (hello_world_client) is: 7f1bf7d3e780
2024-10-17 09:02:35.153005 [info] vSomeIP 2.10.11
2024-10-17 09:02:35.153075 [info] Network interface "eth0" state changed: up
2024-10-17 09:02:35.153109 [info] Route "default route (0.0.0.0/0) if: eth0 gw: 172.17.0.1" state changed: up
2024-10-17 09:02:35.153128 [info] io thread id from application: 1002 (hello_world_client) is: 7f1bef7fe700
2024-10-17 09:02:35.173669 [info] SOME/IP routing ready.
2024-10-17 09:02:35.173716 [warning] Route "224.224.224.245/32 if: eth0 gw: n/a" state changed: up
Sending: World
Received: Hello World
RTT [usec] 00000804
2024-10-17 09:02:35.241973 [info] RELEASE(1002): [1111.2222]
2024-10-17 09:02:35.242057 [info] Stopping vsomeip application "hello_world_client".
2024-10-17 09:02:35.242671 [info] utility::auto_configuration_exit: munmap succeeded.

2. vsomeip3

• client :

2024-10-17 09:04:46.781197  [info] Using configuration file: "/vsomeip/_benchmark/hello_world/conf/client.json".
2024-10-17 09:04:46.782049  [info] Parsed vsomeip configuration in 0ms
2024-10-17 09:04:46.782130  [info] Configuration module loaded.
2024-10-17 09:04:46.782200  [info] Security disabled!
2024-10-17 09:04:46.782228  [info] Initializing vsomeip (3.5.1) application "hello_world_client".
2024-10-17 09:04:46.785063  [info] Instantiating routing manager [Host].
2024-10-17 09:04:46.786333  [info] create_routing_root: Routing root @ /tmp/vsomeip-0
2024-10-17 09:04:46.906606  [info] Service Discovery enabled. Trying to load module.
2024-10-17 09:04:46.909205  [info] Service Discovery module loaded.
2024-10-17 09:04:46.909641  [info] Application(hello_world_client, 1002) is initialized (11, 100).
2024-10-17 09:04:46.909821  [info] Starting vsomeip application "hello_world_client" (1002) using 2 threads I/O nice 0
2024-10-17 09:04:46.910452  [debug] Thread created. Number of active threads for hello_world_client : 1
2024-10-17 09:04:46.910858  [info] Client [1002] routes unicast:172.17.0.3, netmask:255.255.255.0
2024-10-17 09:04:46.911203  [info] shutdown thread id from application: 1002 (hello_world_client) is: 7f7f0e4dc640 TID: 26
2024-10-17 09:04:46.911576  [info] main dispatch thread id from application: 1002 (hello_world_client) is: 7f7f0ecdd640 TID: 25
2024-10-17 09:04:46.122021  [info] Watchdog is disabled!
2024-10-17 09:04:46.123089  [info] REQUEST(1002): [1111.2222:255.4294967295]
2024-10-17 09:04:46.123830  [info] io thread id from application: 1002 (hello_world_client) is: 7f7f0f5d6f80 TID: 1
2024-10-17 09:04:46.123354  [info] io thread id from application: 1002 (hello_world_client) is: 7f7f0d4da640 TID: 28
2024-10-17 09:04:46.124509  [info] vSomeIP 3.5.1 | (default)
2024-10-17 09:04:46.125780  [info] Network interface "eth0" state changed: up
2024-10-17 09:04:46.126627  [info] Route "default route (0.0.0.0/0) if: eth0 gw: 172.17.0.1" state changed: up
2024-10-17 09:04:46.319806  [info] udp_server_endpoint_impl: SO_RCVBUFFORCE successful.
2024-10-17 09:04:46.320269  [debug] Joining to multicast group 224.224.224.245 from 172.17.0.3
2024-10-17 09:04:46.320499  [info] SOME/IP routing ready.
2024-10-17 09:04:46.320827  [warning] Route "224.224.224.245/32 if: eth0 gw: n/a" state changed: up
2024-10-17 09:04:46.533061  [info] udp_server_endpoint_impl<multicast>: SO_RCVBUFFORCE: successful.
2024-10-17 09:04:46.533478  [info] udp_server_endpoint_impl<multicast>: SO_RCVBUF is: 1703936 (1703936) local port:30490
2024-10-17 09:04:46.743019  [info] create_local_server: Listening @ /tmp/vsomeip-1002
2024-10-17 09:04:46.131238  [info] endpoint_manager_impl::create_remote_client: 172.17.0.2:30509 reliable: 0 using local port: 0
2024-10-17 09:04:46.132588  [info] udp_client_endpoint_impl::connect: SO_RCVBUFFORCE successful!
2024-10-17 09:04:46.132880  [info] udp_client_endpoint_impl::connect: SO_RCVBUF is: 1703936 (1703936) local port:0 remote:172.17.0.2:30509
Sending: World
Received: Hello World
RTT [usec] 00010773
2024-10-17 09:04:46.283320  [info] RELEASE(1002): [1111.2222]
2024-10-17 09:04:46.284359  [info] Stopping vsomeip application "hello_world_client" (1002).
2024-10-17 09:04:46.284822  [info] cei::shutdown_and_close_socket_unlocked: not recreating socket  endpoint > 0x7f7f04002630 socket state > 0
2024-10-17 09:04:46.286058  [warning] BLOCKING CALL MESSAGE(1002): [1111.2222.3333:0001]
2024-10-17 09:04:47.287750  [debug] Thread destroyed. Number of active threads for hello_world_client : 0
2024-10-17 09:04:47.288241  [info] [OS=UNIX] Detached thread with id: 7f7f0ecdd640 exited successfully; Number of threads still active : 0

[fcmonteiro]

Hi @kamelfakihh, we will have to look at this, but does this also happen with vsomeip 3.4?
Just trying to understand the changes that could cause this.
Thanks

[nayakned]

@fcmonteiro Yup, I could reproduce the same behavior with vsomeip (v3.4.10) using the above mentioned benchmarks from @kamelfakihh.

Sending: World
Received: Hello World
RTT [usec] 00012189