Println with parrallel iterators behaving wierdly

Programming Rust
1

Hello,

I’m very new to rust.
Solving the bottle song exercice, I was curious about building verses in parallel.
I used into_par_iter and added something to print in threads to verify it’s printed in a nearly random order :
Here is the test: (I’ll past the full code at the end)

    let millis = time::Duration::from_millis(bottles as u64 * 30);
    thread::sleep(millis);
    println!("recite_verse {}", bottles);

However I get some incoherent outputs.
For the “All verses” test (input 10,10) for example, I get :

recite_verse 5
recite_verse 4
recite_verse 10
recite_verse 3
recite_verse 2
recite_verse 1
recite_verse 9
recite_verse 8
recite_verse 7
recite_verse 6
recite_verse 10
recite_verse 9

It’s like verse 10 and 9 are built two times.
But the final song is correct so I guess it’s a printing issue. (I just altered it a bit for the test to fail and have an output)
I checked on forums it seems println is “synchronized” So I wonder what is happening. Does someone have an idea?

The full code :

use rayon::prelude::*;
use std::{thread, time};

fn in_english(number : u32) -> &'static str {
    static NUMBERS_AS_WORDS: [&str; 11] = [
        "No",
        "One",
        "Two",
        "Three",
        "Four",
        "Five",
        "Six",
        "Seven",
        "Eight",
        "Nine",
        "Ten",
    ];
    NUMBERS_AS_WORDS[number as usize]
}

fn write_bottles(bottles: u32) -> String {
    format!("bottle{}", if bottles == 1 {""} else {"s"})
}

fn recite_first_sentence(bottles: u32) -> String {
    format!("{} green {} hanging on the wall,\n", in_english(bottles),  write_bottles(bottles))
}

fn recite_last_sentence(bottles: u32) -> String {
    format!("There'll be {} green {} hanging on the wall.", 
            in_english(bottles-1).to_lowercase(),
            write_bottles(bottles-1)
           )
}
    
fn recite_verse(bottles: u32) -> String {
    //TEST here
    let millis = time::Duration::from_millis(bottles as u64 * 30);
    thread::sleep(millis);
    println!("recite_verse {}", bottles);
    
    format!("{first_sentence}\
             {first_sentence}\
             WRONG And if one green bottle should accidentally fall,\n\
             {last_sentence}",
             first_sentence = recite_first_sentence(bottles), 
             last_sentence = recite_last_sentence(bottles))
}

pub fn recite(start_bottles: u32, take_down: u32) -> String {
    ((start_bottles-take_down+1)..start_bottles+1)
        .into_par_iter()
        .rev()
        .map(recite_verse)
        .collect::<Vec<String>>()
        .join("\n\n")
}

Thanks for your help :slight_smile:

1 Like
2

That is extremely strange.

Tests are run in parallel using threads. That means all tests write to stdout of the same process… the test runner probably does some bookkeeping to figure out which test printed what. My best guess is that since you’re spawning threads on your own, the test runner becomes confused about which test printed what. But that honestly doesn’t seem like a good guess, it doesn’t explain why the same output is captured multiple times.

This doesn’t happen when the all_verses test is run on its own. I have tried running some other combinations of tests and sometimes the output completely vanishes…

Btw. you can show the output of tests even if they pass with cargo test -- --show-output.

2 Likes
3

OK! I didn’t know several tests were running in parallel at the same time!
Your hypothesis seems to explain it very well.
I guess what happened is that the test “first generic verse” (9 and 10) and “all verses” ran in the same time, the test runner confused both and put all logs on the “all verses” test! (and I guess nothing in the other one)
I can try further more with

cargo test -- --test-threads=1

Thanks for the tip. For now I use the editor in the browser. I need a fresh linux installation before running stuff locally.
Thanks a lot :slight_smile:

1 Like