I've got a C function that performs some I/O operations and decoding that'd I'd like to call from a python script.
The C function works fine when compiled by the Visual Studio Command Line C compiler, and also works fine when called through Cython with Multithreading disabled. But when called with OpenMP multithreading, works great through the first few million loops, but then the CPU usage slowly decreases for the next few million loops, until it finally grinds to a halt and doesn't fail, but doesn't continue computations either.
The C file is as follows:
//block_reader.c
#include "block_reader.h" //contains block_data_t, decode_block, get_block_data
#include <stdio.h>
#include <stdlib.h>
#define NTHREADS 8
int decode_blocks(block_data_t *block_data_array, int num_blocks, int *values){
int block;
#pragma omp parallel for num_threads(NTHREADS)
for(block=0; block<num_blocks; block++){
decode_block(block_data_array[i], values);
}
}
int main(int argc, char *argv[]) {
int num_blocks = 250000, block_size = 4096;
block_data_t *block_data_array = get_block_data();
int *values = (long long *)malloc(num_blocks * block_size * sizeof(int));
int i, block;
for(i=0; i<1000; i++){
printf("experiment #%d\n", i+1);
decode_blocks(block_data_array, values)
}
}
}
when compiled with cl /W3 -openmp block_reader.c block_helper.c zstd.lib on the visual studio x64 command line, the main function loop gets all the way to experiment #1000, with the CPU usage at 90% the entire time (my machine has 8 logical threads, I have no idea why it's capped at 90% in pure C, I get the same issue when I remove num_threads(NTHREADS) from the openMP pragma, but I'm not really worried about it).
However when I wrap it in Cython and loop it in python:
#block_reader_wrapper.pyx
from libc.stdlib cimport malloc
from libc.stdio cimport printf
cimport openmp
cimport block_reader_defns #contains block_data_t
import numpy as np
cimport numpy as np
cimport cython
@cython.boundscheck(False) # Deactivate bounds checking.
@cython.wraparound(False) # Deactivate negative indexing.
cpdef tuple read_blocks(block_data_array):
cdef np.ndarray[np.int32_t, ndim=1] values = np.zeros(size, dtype=np.int32_t)
cdef int[::1] values_view = values
decode_blocks(block_data_array, len(block_data_array), num_blocks, &values_view[0])
return values
cdef extern from "block_reader.h":
int decode_blocks(char**, b_metadata*, unsigned int, unsigned long long*, long long*, int*)
#setup.block_reader_wrapper.py
from setuptools import setup, Extension
from Cython.Build import cythonize
import numpy
ext_modules = [
Extension(
"block_reader_wrapper",
["block_reader_wrapper.pyx", "block_reader.c", "block_helper.c"],
libraries=["zstd"],
library_dirs=["{dir}/vcpkg/installed/x64-windows/lib"],
include_dirs=['{dir}/vcpkg/installed/x64-windows/include', numpy.get_include()],
extra_compile_args=['/openmp', '-O2'], #Have tried -O2, -O3 and no optimization
extra_link_args=['/openmp'], #always gets LINK : warning LNK4044: unrecognized option '/openmp'; ignored despite the docs asking for it https://cython.readthedocs.io/en/latest/src/userguide/parallelism.html
)
]
setup(
ext_modules = cythonize(ext_modules,
gdb_debug=True,
annotate=True,
)
)
#experiment.py
from block_reader_wrapper import read_blocks
from block_data_gen import get_block_data
for i in range(1000):
print("experiment", i+1)
read_blocks(get_block_data())
I get to experiment #10 with CPU usage at 100% (and running a little faster than the 90% capped pure C), but then between experiment #11 - experiment #16 the CPU usage slowly decreases in increments of 1 logical thread worth of resources, until the CPU usage hits the bottom of 1 logical thread, however despite my task manager claiming python is using ~20% of my CPU usage, the process stops outputting data. Memory Usage is always fairly low (~10%).
I figure this must have something to do with Cython's linking of OpenMP, perhaps implicitly limiting the number of payloads that I can pass to its worker threads.
Any insight would be greatly appreciated, I need this to ultimately work on Windows and Ubuntu, which is why I choose openMP in the first place.
Edit 1: As per DavidW 's suggestion I replaced:
cdef np.ndarray[np.int32_t, ndim=1] values = np.zeros(size, dtype=np.int32_t)
with:
cdef array.array values, values_temp
values_temp = array.array('q', [])
values = array.clone(values_temp, size, zero=True)
Unfortunately this has not fixed the problem.
Edit 2 & 3: After profiling the process when it's "ground to a halt", I see that a significant portion of CPU time is spent waiting. Specifically the functions free_base and malloc_base from the module ucrtbase.dll
Edit 4: I rewrote the wrapper with ctypes instead of cython, which takes advantage of the same C -> Python API, so maybe it's no surprise that the same problem exists (although it grinds to a halt about twice as fast with ctypes over Cython).
VTune Summary:
Elapsed Time: 285419.416s
CPU Time: 22708.709s
Effective Time: 9230.924s
Spin Time: 13477.785s
Overhead Time: 0s
Total Thread Count: 10
Paused Time: 0s
Top Hotspots
Function Module CPU Time
free_base ucrtbase.dll 9061.852s
malloc_base ucrtbase.dll 8308.887s
NtWaitForSingleObject ntdll.dll 1283.721s
func@0x180020020 USER32.dll 820.759s
func@0x18001c630 tsc_block_reader.cp38-win_amd64.pyd 753.774s
[Others] N/A* 2479.716s
Effective CPU Utilization Histogram
Simultaneously Utilized Logical CPUs Elapsed Time Utilization threshold
0 279744.7901384001 Idle
1 5446.2851121 Poor
2 177.8078306 Poor
3 40.3033061 Poor
4 10.2292884 Poor
5 0 Poor
6 0 Poor
7 0 Ok
8 0 Ideal
Even though it's saying about 80% of the CPU time is Idle, a loop that should complete in 30 seconds didn't even complete after 2 days, so it's much more than 80% Idle time.
Looks like the majority of the Idle time is spent in ucrtbase.dll