Spin once with timeout of zero causes segfault

[azerupi]

Edit: This is due to spin_once using the default for timeout which is None and thus waits infinitely long for the next work item. It seems consistent with rclcpp and rclpy, nevermind the initial report. However when setting the timeout to zero I do it a segfault. See #518 (comment)

---

@mxgrey on main, it seems that calling executor.spin with the spin_once option often blocks and doesn't return anymore. After a while it returns but that can take multiple minutes. I assume this is related to the recent async workers PR #446

I'm able to reproduce with this minimal example.

use rclrs::*;
use std::time::Instant;

fn main() -> Result<(), RclrsError> {
    let context = Context::default_from_env()?;
    let mut executor = context.create_basic_executor();

    let node = executor.create_node("spin_once")?;

    let start = Instant::now();

    loop {
        let spin_options = SpinOptions::spin_once();
        // Do something

        // Spin the ROS executor once per loop iteration
        println!(
            "{:?}: Spinning the ROS executor",
            Instant::now().duration_since(start)
        );
        for err in executor.spin(spin_options) {
            println!("Error spinning executor: {}", err);
        }
    }
}

This produces the following output:

     Running `target/debug/executor_spin_once`
959ns: Spinning the ROS executor
1.520136ms: Spinning the ROS executor
60.030143ms: Spinning the ROS executor
60.753941ms: Spinning the ROS executor
61.184555ms: Spinning the ROS executor
61.732767ms: Spinning the ROS executor
142.934665ms: Spinning the ROS executor
36.835954541s: Spinning the ROS executor
515.193405684s: Spinning the ROS executor
515.197877282s: Spinning the ROS executor
515.199235729s: Spinning the ROS executor
515.200072409s: Spinning the ROS executor
515.204577531s: Spinning the ROS executor
515.20505359s: Spinning the ROS executor
515.296711749s: Spinning the ROS executor
515.297077096s: Spinning the ROS executor
515.298727927s: Spinning the ROS executor
515.299056657s: Spinning the ROS executor
515.572422362s: Spinning the ROS executor
515.576059027s: Spinning the ROS executor
515.578894946s: Spinning the ROS executor
515.579868122s: Spinning the ROS executor
515.582508512s: Spinning the ROS executor
515.58318564s: Spinning the ROS executor
515.649431917s: Spinning the ROS executor
515.64980933s: Spinning the ROS executor
515.821898359s: Spinning the ROS executor
515.822612154s: Spinning the ROS executor
515.823036055s: Spinning the ROS executor
515.824254962s: Spinning the ROS executor
613.053811476s: Spinning the ROS executor
613.054233761s: Spinning the ROS executor
613.054571505s: Spinning the ROS executor
613.055475553s: Spinning the ROS executor
617.722171324s: Spinning the ROS executor
617.725393116s: Spinning the ROS executor
617.726446308s: Spinning the ROS executor
617.726917001s: Spinning the ROS executor
617.729313804s: Spinning the ROS executor
617.787985176s: Spinning the ROS executor
617.788492489s: Spinning the ROS executor
690.09367819s: Spinning the ROS executor
690.096920025s: Spinning the ROS executor
690.098053481s: Spinning the ROS executor
690.098669179s: Spinning the ROS executor
690.100041836s: Spinning the ROS executor
690.100476962s: Spinning the ROS executor
690.100905686s: Spinning the ROS executor
690.10149059s: Spinning the ROS executor
690.102103217s: Spinning the ROS executor
690.102628434s: Spinning the ROS executor
690.102957312s: Spinning the ROS executor
690.103937821s: Spinning the ROS executor
690.104271151s: Spinning the ROS executor
690.104579495s: Spinning the ROS executor
690.10682558s: Spinning the ROS executor
690.107354417s: Spinning the ROS executor
690.107915881s: Spinning the ROS executor
690.108267309s: Spinning the ROS executor
690.108673793s: Spinning the ROS executor
690.109556136s: Spinning the ROS executor
690.110095288s: Spinning the ROS executor
690.110653009s: Spinning the ROS executor
690.111032795s: Spinning the ROS executor
690.111569118s: Spinning the ROS executor
690.112244265s: Spinning the ROS executor
690.112652687s: Spinning the ROS executor
690.113038728s: Spinning the ROS executor
690.113524153s: Spinning the ROS executor
690.114183974s: Spinning the ROS executor
690.114682071s: Spinning the ROS executor
690.115168713s: Spinning the ROS executor
711.100305683s: Spinning the ROS executor
711.10129357s: Spinning the ROS executor

There also seems to be some effect when running ros2 CLI commands. When running ros2 topic list for the first time it unlocked for some iterations and then when running ros2 daemon stop/start it unlocks for some iterations as well.

[azerupi]

I think this is due to spin_once using the default for timeout which is None and thus waits infinitely long for the next work item? Is this expected behavior or should the expected behavior be with timeout = 0?

[azerupi]

Well actually setting the timeout to zero causes a segfault.

use rclrs::*;
use std::time::{Duration, Instant};

fn main() -> Result<(), RclrsError> {
    let context = Context::default_from_env()?;
    let mut executor = context.create_basic_executor();

    let node = executor.create_node("spin_once")?;

    let start = Instant::now();

    loop {
        // Do something

        // Spin the ROS executor once per loop iteration
        println!(
            "{:?}: Spinning the ROS executor",
            Instant::now().duration_since(start)
        );

        let spin_options = SpinOptions::spin_once().timeout(Duration::ZERO);
        for err in executor.spin(spin_options) {
            println!("Error spinning executor: {}", err);
        }
    }
}

     Running `target/debug/executor_spin_once`
66ns: Spinning the ROS executor
Error spinning executor: Timeout occurred (RCL_RET_TIMEOUT).
715.468µs: Spinning the ROS executor
Error spinning executor: Timeout occurred (RCL_RET_TIMEOUT).
963.864µs: Spinning the ROS executor
zsh: segmentation fault (core dumped)  cargo run

[mxgrey]

it seems that calling executor.spin with the spin_once option often blocks and doesn't return anymore. After a while it returns but that can take multiple minutes.

In the case that you've constructed here, this is actually the correct and intended behavior. There are no subscriptions or any other primitives available to perform work that would wake up the wait set, and you did not have a timeout set, so the executor will wait indefinitely. The first few wakeups are likely because of various services (parameter services, node graph services) doing some startup work.

If you look at the docs for rclcpp::spin_once you'll see that by default it will wait indefinitely for the first set of work to become available. That matches the behavior that we're seeing here.

Is this expected behavior or should the expected behavior be with timeout = 0?

So yes, this is the expected behavior, and if you want it to return immediately when there is no work, then you should just set the timeout to zero. There is no need to use the spin_once setting at that point, you could just do SpinOptions::default().timeout(Duration::from_secs(0)).

Well actually setting the timeout to zero causes a segfault.

This is definitely bad. I've managed to recreate the segfault on a jazzy distro with both cyclone and fastdds as the RMW implementation. I don't have an explanation for it at this time. The gdb stack trace shows the segmentation fault happening within cyclone or fastdds depending on which is being used. Beyond that I can't see much since the installed versions of these libraries don't have debug info. I'll have to build a ROS 2 workspace from source with debug symbols to investigate this further. That may take some time.

[azerupi]

In the case that you've constructed here, this is actually the correct and intended behavior.

Yes, I figured it out after posting the issue when I started looking into the internal code and comparing with rclcpp and rclpy docs. I'm sorry about the noise.

I'll have to build a ROS 2 workspace from source with debug symbols to investigate this further. That may take some time.

Thank you for looking into this! If there is anything I can do on my side to help let me know.

[mxgrey]

The timeout issue is fixed by this PR: #519

[azerupi]

I can confirm that the issue has been fixed. Thank you!