Version 2.0.6 is significantly slower

[mjimenezm00]

Description
I've been using rosbridge_suite as the bridge between my ROS2 stack and a web UI for several years. Recently, after updating to the lastest humble, I noticed a slowdown in the performance.

I traced the issue to version 2.0.6. It introduces a severe performance regression. However, release 2.0.5 works perfectly fine.

It seems the regression was introduced by commit d858f8d "fix: Reduce idle CPU consumption of websocket server".

Reverting d858f8d on top of 2.0.6 restores the previous behavior.

• Library Version: 2.0.6
• ROS Version: ROS 2 Humble
• Platform / OS: Ubuntu 22.04.5 LTS, Python 3.10.12

Expected Behavior
Same low latency and throughput as in version 2.0.5.

Actual Behavior
Starting from 2.0.6, WebSocket message delivery becomes extremely slow. Reverting commit d858f8d immediately resolves the issue.

[bjsowa]

hmm, that's interesting. What version of rclpy are you using?

[mjimenezm00]

I'm using latest humble (ros2/rclpy@c2c6202)

[bjsowa]

What client library are you using and which version?

[mjimenezm00]

roslib 1.4.1

[bjsowa]

I experience the exact opposite. 2.0.6 has much better round-trip latency and throughput than 2.0.5. Could you try running the following script:

latency_test.js

import ROSLIB from "roslib";

const MESSAGE_COUNT = 1000;
const TIMEOUT_MS = 10000;
const ROSBRIDGE_URL = "ws://127.0.0.1:9090";
const TOPIC_NAME = "/latency_test";
const MESSAGE_TYPE = "std_msgs/msg/String";

const ros = new ROSLIB.Ros({ url: ROSBRIDGE_URL });

ros.on("connection", () => {
  console.log("Connected to rosbridge.");
  run();
});

ros.on("error", (error) => {
  console.error("Connection error:", error);
  process.exit(1);
});

const topic = new ROSLIB.Topic({
  ros,
  name: TOPIC_NAME,
  messageType: MESSAGE_TYPE,
});

function runTest() {
  const latencies = [];
  let received = 0;
  let done = false;
  let startTime;

  return new Promise((resolve) => {
    const timeout = setTimeout(() => {
      if (!done) {
        done = true;
        const durationMs = performance.now() - (startTime ?? performance.now());
        topic.unsubscribe(onMessage);
        resolve({
          latencies,
          missed: MESSAGE_COUNT - received,
          messagesPerSec: received > 0 ? (received / durationMs) * 1000 : 0,
          durationMs,
        });
      }
    }, TIMEOUT_MS);

    function onMessage(message) {
      const receiveTime = performance.now();
      if (received === 0) {
        startTime = receiveTime;
      }
      const sendTime = parseFloat(message.data);
      latencies.push(receiveTime - sendTime);
      received++;

      if (received >= MESSAGE_COUNT && !done) {
        done = true;
        clearTimeout(timeout);
        const durationMs = receiveTime - startTime;
        topic.unsubscribe(onMessage);
        resolve({
          latencies,
          missed: 0,
          messagesPerSec: (MESSAGE_COUNT / durationMs) * 1000,
          durationMs,
        });
      } else if (!done) {
        topic.publish(new ROSLIB.Message({ data: String(performance.now()) }));
      }
    }

    topic.subscribe(onMessage);

    // Small delay to let subscription establish, then send the first message
    setTimeout(() => {
      topic.publish(new ROSLIB.Message({ data: String(performance.now()) }));
    }, 500);
  });
}

function printStats(latencies) {
  const sorted = [...latencies].sort((a, b) => a - b);
  const sum = sorted.reduce((a, b) => a + b, 0);
  const mean = sum / sorted.length;
  const median = sorted[Math.floor(sorted.length / 2)];
  const p95 = sorted[Math.floor(sorted.length * 0.95)];
  const p99 = sorted[Math.floor(sorted.length * 0.99)];
  const min = sorted[0];
  const max = sorted[sorted.length - 1];

  console.log(`  Messages:  ${sorted.length}`);
  console.log(`  Min:       ${min.toFixed(3)} ms`);
  console.log(`  Max:       ${max.toFixed(3)} ms`);
  console.log(`  Mean:      ${mean.toFixed(3)} ms`);
  console.log(`  Median:    ${median.toFixed(3)} ms`);
  console.log(`  P95:       ${p95.toFixed(3)} ms`);
  console.log(`  P99:       ${p99.toFixed(3)} ms`);
}

async function run() {
  console.log(`\n=== Pub/Sub Test (${MESSAGE_COUNT} messages, timeout ${TIMEOUT_MS}ms) ===`);
  const result = await runTest();

  console.log("\n  Latency:");
  printStats(result.latencies);

  console.log("\n  Throughput:");
  console.log(`    Duration:   ${result.durationMs.toFixed(1)} ms`);
  console.log(`    Throughput: ${result.messagesPerSec.toFixed(1)} msg/s`);

  if (result.missed > 0) {
    console.log(`\n  MISSED:    ${result.missed}/${MESSAGE_COUNT} messages (${((result.missed / MESSAGE_COUNT) * 100).toFixed(1)}%)`);
  }

  ros.close();
  process.exit(0);
}

Here are my results for 2.0.5:

  Latency:
  Messages:  1000
  Min:       0.430 ms
  Max:       24.672 ms
  Mean:      5.873 ms
  Median:    1.914 ms
  P95:       13.982 ms
  P99:       23.149 ms

  Throughput:
    Duration:   5872.1 ms
    Throughput: 170.3 msg/s 

and here for 2.0.6:

  Latency:
  Messages:  1000
  Min:       0.174 ms
  Max:       4.538 ms
  Mean:      0.351 ms
  Median:    0.326 ms
  P95:       0.521 ms
  P99:       0.759 ms

  Throughput:
    Duration:   347.8 ms
    Throughput: 2875.2 msg/s 

[mjimenezm00]

I tried the latency test and, if rosbridge is run standalone, it is, in fact, as you said. 2.0.6 has better performance than 2.0.5.
However, if I run my ROS2 stack and then execute the test, 2.0.5 is much better than 2.0.6.

Using 2.0.6 at different moments in my simulation:

=== Pub/Sub Test (1000 messages, timeout 10000ms) ===
 
  Latency:
  Messages:  1000
  Min:       -1040.102 ms
  Max:       23.510 ms
  Mean:      1.405 ms
  Median:    11.666 ms
  P95:       17.436 ms
  P99:       19.840 ms
 
  Throughput:
    Duration:   1165.3 ms
    Throughput: 858.1 msg/s

=== Pub/Sub Test (1000 messages, timeout 10000ms) ===
 
  Latency:
  Messages:  42
  Min:       6.345 ms
  Max:       1216.517 ms
  Mean:      222.390 ms
  Median:    148.480 ms
  P95:       911.821 ms
  P99:       1216.517 ms
 
  Throughput:
    Duration:   8614.7 ms
    Throughput: 4.9 msg/s
 
  MISSED:    958/1000 messages (95.8%)

=== Pub/Sub Test (1000 messages, timeout 10000ms) ===
 
  Latency:
  Messages:  2
  Min:       3094.442 ms
  Max:       4460.447 ms
  Mean:      3777.445 ms
  Median:    4460.447 ms
  P95:       4460.447 ms
  P99:       4460.447 ms
 
  Throughput:
    Duration:   6404.0 ms
    Throughput: 0.3 msg/s
 
  MISSED:    998/1000 messages (99.8%)`

Whereas, using 2.0.5 and running the test at the same moments:

=== Pub/Sub Test (1000 messages, timeout 10000ms) ===
 
  Latency:
  Messages:  1000
  Min:       -9925.372 ms
  Max:       24.191 ms
  Mean:      -82.023 ms
  Median:    17.103 ms
  P95:       20.908 ms
  P99:       22.567 ms
 
  Throughput:
    Duration:   1686.3 ms
    Throughput: 593.0 msg/s
 
=== Pub/Sub Test (1000 messages, timeout 10000ms) ===
 
  Latency:
  Messages:  855
  Min:       1.101 ms
  Max:       25.437 ms
  Mean:      11.097 ms
  Median:    12.589 ms
  P95:       14.899 ms
  P99:       23.919 ms
 
  Throughput:
    Duration:   9474.2 ms
    Throughput: 90.2 msg/s
 
  MISSED:    145/1000 messages (14.5%)
 
=== Pub/Sub Test (1000 messages, timeout 10000ms) ===
 
  Latency:
  Messages:  1000
  Min:       2.126 ms
  Max:       22.157 ms
  Mean:      8.265 ms
  Median:    7.873 ms
  P95:       13.920 ms
  P99:       17.261 ms
 
  Throughput:
    Duration:   8257.1 ms
    Throughput: 121.1 msg/s

[bjsowa]

It would help if you can provide some way to reproduce the issue on my end.