Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use posix_spawn() on unix if program is a path #77455

Merged
merged 1 commit into from
Oct 17, 2020

Conversation

asm89
Copy link
Contributor

@asm89 asm89 commented Oct 2, 2020

Previously Command::spawn would fall back to the non-posix_spawn based
implementation if the PATH environment variable was possibly changed.
On systems with a modern (g)libc posix_spawn() can be significantly
faster. If program is a path itself the PATH environment variable is
not used for the lookup and it should be safe to use the
posix_spawnp() method. 1

We found this, because we have a cli application that effectively runs a
lot of subprocesses. It would sometimes noticeably hang while printing
output. Profiling showed that the process was spending the majority of
time in the kernel's copy_page_range function while spawning
subprocesses. During this time the process is completely blocked from
running, explaining why users were reporting the cli app hanging.

Through this we discovered that std::process::Command has a fast and
slow path for process execution. The fast path is backed by
posix_spawnp() and the slow path by fork/exec syscalls being called
explicitly. Using fork for process creation is supposed to be fast, but
it slows down as your process uses more memory. It's not because the
kernel copies the actual memory from the parent, but it does need to
copy the references to it (see copy_page_range above!). We ended up
using the slow path, because the command spawn implementation in falls
back to the slow path if it suspects the PATH environment variable was
changed.

Here is a smallish program demonstrating the slowdown before this code
change:

use std::process::Command;
use std::time::Instant;

fn main() {
    let mut args = std::env::args().skip(1);
    if let Some(size) = args.next() {
        // Allocate some memory
        let _xs: Vec<_> = std::iter::repeat(0)
            .take(size.parse().expect("valid number"))
            .collect();

        let mut command = Command::new("/bin/sh");
        command
            .arg("-c")
            .arg("echo hello");

        if args.next().is_some() {
            println!("Overriding PATH");
            command.env("PATH", std::env::var("PATH").expect("PATH env var"));
        }

        let now = Instant::now();
        let child = command
            .spawn()
            .expect("failed to execute process");

        println!("Spawn took: {:?}", now.elapsed());

        let output = child.wait_with_output().expect("failed to wait on process");
        println!("Output: {:?}", output);
    } else {
        eprintln!("Usage: prog [size]");
        std::process::exit(1);
    }
    ()
}

Running it and passing different amounts of elements to use to allocate
memory shows that the time taken for spawn() can differ quite
significantly. In latter case the posix_spawnp() implementation is 30x
faster:

$ cargo run --release 10000000
...
Spawn took: 324.275µs
hello
$ cargo run --release 10000000 changepath
...
Overriding PATH
Spawn took: 2.346809ms
hello
$ cargo run --release 100000000
...
Spawn took: 387.842µs
hello
$ cargo run --release 100000000 changepath
...
Overriding PATH
Spawn took: 13.434677ms
hello

@rust-highfive
Copy link
Collaborator

Thanks for the pull request, and welcome! The Rust team is excited to review your changes, and you should hear from @kennytm (or someone else) soon.

If any changes to this PR are deemed necessary, please add them as extra commits. This ensures that the reviewer can see what has changed since they last reviewed the code. Due to the way GitHub handles out-of-date commits, this should also make it reasonably obvious what issues have or haven't been addressed. Large or tricky changes may require several passes of review and changes.

Please see the contribution instructions for more information.

@rust-highfive rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Oct 2, 2020
@jyn514 jyn514 added the T-libs Relevant to the library team, which will review and decide on the PR/issue. label Oct 2, 2020
@asm89
Copy link
Contributor Author

asm89 commented Oct 2, 2020

Somewhat related, but I wonder what a good place would be to document the fallback to the slow path. The behavior was quite surprising, especially because it triggered when PATH is touched. This will still be the case for Commands where the program is not a path.

Previously `Command::spawn` would fall back to the non-posix_spawn based
implementation if the `PATH` environment variable was possibly changed.
On systems with a modern (g)libc `posix_spawn()` can be significantly
faster. If program is a path itself the `PATH` environment variable is
not used for the lookup and it should be safe to use the
`posix_spawnp()` method. [1]

We found this, because we have a cli application that effectively runs a
lot of subprocesses. It would sometimes noticeably hang while printing
output. Profiling showed that the process was spending the majority of
time in the kernel's `copy_page_range` function while spawning
subprocesses. During this time the process is completely blocked from
running, explaining why users were reporting the cli app hanging.

Through this we discovered that `std::process::Command` has a fast and
slow path for process execution. The fast path is backed by
`posix_spawnp()` and the slow path by fork/exec syscalls being called
explicitly. Using fork for process creation is supposed to be fast, but
it slows down as your process uses more memory.  It's not because the
kernel copies the actual memory from the parent, but it does need to
copy the references to it (see `copy_page_range` above!).  We ended up
using the slow path, because the command spawn implementation in falls
back to the slow path if it suspects the PATH environment variable was
changed.

Here is a smallish program demonstrating the slowdown before this code
change:

```
use std::process::Command;
use std::time::Instant;

fn main() {
    let mut args = std::env::args().skip(1);
    if let Some(size) = args.next() {
        // Allocate some memory
        let _xs: Vec<_> = std::iter::repeat(0)
            .take(size.parse().expect("valid number"))
            .collect();

        let mut command = Command::new("/bin/sh");
        command
            .arg("-c")
            .arg("echo hello");

        if args.next().is_some() {
            println!("Overriding PATH");
            command.env("PATH", std::env::var("PATH").expect("PATH env var"));
        }

        let now = Instant::now();
        let child = command
            .spawn()
            .expect("failed to execute process");

        println!("Spawn took: {:?}", now.elapsed());

        let output = child.wait_with_output().expect("failed to wait on process");
        println!("Output: {:?}", output);
    } else {
        eprintln!("Usage: prog [size]");
        std::process::exit(1);
    }
    ()
}
```

Running it and passing different amounts of elements to use to allocate
memory shows that the time taken for `spawn()` can differ quite
significantly. In latter case the `posix_spawnp()` implementation is 30x
faster:

```
$ cargo run --release 10000000
...
Spawn took: 324.275µs
hello
$ cargo run --release 10000000 changepath
...
Overriding PATH
Spawn took: 2.346809ms
hello
$ cargo run --release 100000000
...
Spawn took: 387.842µs
hello
$ cargo run --release 100000000 changepath
...
Overriding PATH
Spawn took: 13.434677ms
hello
```

[1]: https://github.com/bminor/glibc/blob/5f72f9800b250410cad3abfeeb09469ef12b2438/posix/execvpe.c#L81
@asm89
Copy link
Contributor Author

asm89 commented Oct 12, 2020

@kennytm Could you take a look? Alternatively can I convince @rust-highfive to assign this to someone else? :)

@kennytm
Copy link
Member

kennytm commented Oct 17, 2020

@bors r+

@bors
Copy link
Contributor

bors commented Oct 17, 2020

📌 Commit 8fe6154 has been approved by kennytm

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Oct 17, 2020
@bors
Copy link
Contributor

bors commented Oct 17, 2020

⌛ Testing commit 8fe6154 with merge 4cb7ef0...

@bors
Copy link
Contributor

bors commented Oct 17, 2020

☀️ Test successful - checks-actions, checks-azure
Approved by: kennytm
Pushing 4cb7ef0 to master...

@bors bors added the merged-by-bors This PR was explicitly merged by bors. label Oct 17, 2020
@bors bors merged commit 4cb7ef0 into rust-lang:master Oct 17, 2020
@rustbot rustbot added this to the 1.49.0 milestone Oct 17, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
merged-by-bors This PR was explicitly merged by bors. S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. T-libs Relevant to the library team, which will review and decide on the PR/issue.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants