Bad multi-threaded parallel execution efficiency question.

[GoodManWEN]

🌍 Environment

• Your operating system and version: Windows 10 20H2
• Your python version: python 3.8.7
• How did you install python (e.g. apt or pyenv)? Did you use a virtualenv?: from exe file / no.
• Your Rust version (rustc --version): 1.51.0 (beta)
• Your PyO3 version: 0.13.2
• Have you tried using latest PyO3 master (replace version = "0.x.y" with git = "https://github.com/PyO3/pyo3")?: no

💥 Description

Hi everyone, I recently migrated some of my algorithms from python written to rust, the code is around 5,000 lines in total. The bad news is, I found that despite the excellent single-threaded execution efficiency, the pyo3 extension plugin in multi-threaded parallel mode does not execute very nicely. After releasing the GIL, running on my 8-core CPU, I was expecting a 4-8x speedup, but the actual speedup was only 2x.

I'm cautiously assuming this is caused by the type conversions between python and rust (convert python lists into rust vectors and then convert back) are all being executed under the GIL, this may be related to the fact that the data type I passed in was som ralatively long two-dimensional python lists. I would like to ask if this situation can be improved (the low-efficiency may be caused by my wrong calling method), or if it is my requirements that make it can not improve at all.

Minimum Implementation

lib.rs:
It accepts a M by N matrix and returns after each item +1. The algorithm is much more complex in real production.

use pyo3::prelude::*;
use pyo3::wrap_pyfunction;

fn multithread_logic<const N:usize>(matrix: Vec<[f64;N]>
) -> Vec<Vec<f64>> {
    let height = matrix.len() ;
    let width = N;
    let mut result = Vec::new();
    for i in 0..height{
        let mut row:Vec<f64> = Vec::new();
        for j in 0..width {
            row.push(matrix[i][j] + 1.0);
        }
        result.push(row);
    }
    result
}

#[pyfunction]
fn multithread(
    py: Python,
    matrix: Vec<[f64;32]>,
) -> Vec<Vec<f64>> {
    py.allow_threads(|| multithread_logic(matrix))
}

#[pymodule]
fn testlib(_py: Python, m: &PyModule) -> PyResult<()> {
    m.add_function(wrap_pyfunction!(multithread, m)?)?;
    Ok(())
}

call.py:
Uses a simple way to compare the speed of single-thread and multi-threaded execution speed. Time increases linearly in the actual execution, I'd like to know if this is due to my mismanagement of GIL.

import testlib
import time
import threading

matrix = [list(range(32)) for _ in range(2000)]

def single_thread(matrix):
    for i in range(1000):
        testlib.multithread(matrix)

st_time = time.time()
single_thread(matrix)
print(f"Single thread time: {time.time() - st_time} s")

st_time = time.time()
threads = []
for _ in range(8):
    threads.append(threading.Thread(target = single_thread , args = (matrix,)))
for _ in threads:
    _.start()
for _ in threads:
    _.join()
print(f"Multi-threaded time: {time.time() - st_time} s")

[messense]

    matrix_for_each_thread = deepcopy(matrix)

Why is this copy needed?

[GoodManWEN]

@messense I'm worring about competition for resources between threads, which may be unnecessary, I'm not sure.

[messense]

Python objects are ref-counted, and you are not modifying the input in the Rust side, it should be fine to just pass matrix

[messense]

Otherwise you are also measuring the deepcopy cost in multi-threaded case.

[messense]

def single_thread(num , matrix):
    for i in range(1000):
        testlib.multithread(matrix)

I don't think it's using the num input? Did you mean

def single_thread(num , matrix):
    for i in range(num):
        testlib.multithread(matrix)

[GoodManWEN]

It is reasonable to assume so, but the overhead of copy in this example should not be the main cost. Even if executing deepcopy, it only executes 8 times, where python execution is not slow for a 2000x32 matrix.

[GoodManWEN]

num is used to track the execution of each thread (to distinguish between threads), I removed the relevant code in the minimum implementation thus make an ambiguity, I have modified the code above.

[GoodManWEN]

The results of my execution is

Single thread time: 4.926007509231567 s
Multi-threaded time: 30.748129844665527 s

[messense]

def single_thread(matrix):
    for i in range(1000):
        testlib.multithread(matrix)

It could be that in multi-threaded environment you are releasing and re-acquiring the GIL 1000 times in this loop, it's not the case in single-threaded environment.

Edit: It's wrong, testlib.multithread release the GIL inside.

[messense]

I can reproduce locally.

Note that it could be much faster if you put the loop in Rust code and call it from Python, for example

#[pyfunction]
fn multithread_loop(
    py: Python,
    matrix: Vec<[f64;32]>,
    iterations: usize,
) -> () {
    py.allow_threads(|| {
        for _ in 0..iterations {
            multithread_logic(matrix.clone());
        }
    })
}

[messense]

Looks like most of time is spent in type conversions.

Meanwhile, take a look at this comment: #1480 (comment)

[GoodManWEN]

@messense Your analysis tools are cool. Indeed its better to run the loop in rust, the reason for the testing approach is to simulate my production environment, in my actual business I have several filters that operate on 2D matrices, who run some complex logic that is difficult to optimize with numpy thus I tend to implement in embeded dlls.

In the original python implementation, the execution time of a single filter is around 200 seconds, makes it a long time in serial execution. After switching to rust, I can expect a 70x-90x acceleration in the purely algorithmic part, individual filter execution times can be reduced to milliseconds including conversion overhead.

In my testing of the actual production code (they are too long to discuss in github issue), the overall execution time for each filter is 2.3 seconds (python overall call time for 100 loop times in 230s). And in rust, I used some other code to find out it takes about 1.51 seconds between releasing gil and before returning.

rust sample code as following,

use std::time::Instant;

fn multithread_logic<const N:usize>(matrix: Vec<[f64;N]>
) -> Vec<Vec<f64>> {
   let st_time = Instant::now();
   // ... logic
   st_time.elapsed().as_micros();
    // return
}

#[pyfunction]
fn multithread(
    py: Python,
    matrix: Vec<[f64;32]>,
) -> Vec<Vec<f64>> {
    py.allow_threads(|| multithread_logic(matrix))
}

To be honest this test result does not meet my expectations. In my production code test, the result of 230s execution for a single thread takes 1210 seconds for 8 threads to execute (I'm sure that this result is not limited by the hardware which means it's much worse than the best execution efficiency). Under ideal conditions, if the code part in rust can achieve a perfect parallel efficiency of 100%, then it means that only 0.7 seconds are needed to be linear executed in a 2.3s execution. Parallel time should not be as high as 1210 seconds.

---

Edit after #1480
Anyway thanks for reply. If I understand correctly, there is nothing wrong with the way I release gil in the example, so unless using numpy, this is not a problem that can be optimized at the user level at this stage.

I'm not sure if you've noticed in the reproduction, even though conversion overhead takes up most of the time, they do it in rust code, and if this process not run under gil, then the cpu usage will be pertty high with multiple threads executing. But in my tests, the actual occupancy rate is relatively low, not more than 50% in total.

[messense]

even though conversion overhead takes up most of the time, they do it in rust code, and if this process not run under gil

It has to run under GIL because it's using PyIter_Next to iterate the input matrix to build a Vec<[f64;32]>

Your analysis tools are cool.

It's Instruments.app from Xcode on macOS.