Service call performance

asked 2020-01-02 04:19:54 -0500

FabianMene gravatar image

updated 2020-01-02 06:57:50 -0500

I am trying to understand what factors determine the performance of a service call, as I have run into issues with large numbers of nodes and service servers.

In a testing environment, I have 10 identical server nodes where each opens a service server. The service is identical and just passes a string back and forth (to simulate various message sizes). A single client node then calls the services of all server nodes in sequence. Even though everything should be identical across the 10 server nodes, the resulting performance is not - the first service call takes significantly longer than the following (example output in nanoseconds)

[ INFO] [1577959147.786911753]: /server_nodes/n0: 145694089
[ INFO] [1577959147.792063118]: /server_nodes/n1: 5116999
[ INFO] [1577959147.795988735]: /server_nodes/n2: 3898928
[ INFO] [1577959147.801337292]: /server_nodes/n3: 5322671 
[ INFO] [1577959147.806288065]: /server_nodes/n4: 4925818
[ INFO] [1577959147.812728372]: /server_nodes/n5: 6415972
[ INFO] [1577959147.820323804]: /server_nodes/n6: 7569233
[ INFO] [1577959147.832358934]: /server_nodes/n7: 11996631 
[ INFO] [1577959147.837201605]: /server_nodes/n8: 4817895
[ INFO] [1577959147.840539174]: /server_nodes/n9: 3316493

Here's how the service is called from the client node's side:

for (std::string name : nodeNames)
{
pkg::Srv srv;
srv.request.in = std::string(1000, '0');

std::chrono::high_resolution_clock::time_point startTime, endTime;

startTime = std::chrono::high_resolution_clock::now();
ros::ServiceClient client =
      nh.serviceClient<pkg::Srv>(serviceName);
success = client.call(srv);
endTime = std::chrono::high_resolution_clock::now();

if (success)
{
   ROS_INFO_STREAM(name << ": " <<
      std::chrono::duration_cast<std::chrono::nanoseconds>(endTime - startTime).count());
}
else
{
  ROS_WARN("Service call failed");
}
}

It would appear like the first service call carries a significant overhead that is then not repeated with the later calls, maybe because of some caching taking place?

Could somebody explain why this occurs?

edit retag flag offensive close merge delete