BUG: Garbage collection order of magnitude slower in numpy>=1.22

Describe the issue:

Cross post from scikit-learn's repository:

from sklearn.neighbors import KDTree
import time

def mwe(n):
    start = time.time()
    a = KDTree([[1]]).query_radius([[1]]*int(n), 1)
    print(f'Function completed in: {time.time()-start:.2f} seconds')

start = time.time()
mwe(1e6)
print(f'Function returned after {time.time()-start:.1f} seconds')

start = time.time()
mwe(1e7)
print(f'Function returned after {time.time()-start:.1f} seconds')

With numpy==1.24.3, this results in the output:

Function completed in: 0.36 seconds
Function returned after 4.4 seconds

Function completed in: 3.75 seconds
Function returned after 44.0 seconds

Compare this to the output with numpy==1.21.6:

Function completed in: 0.57 seconds
Function returned after 0.6 seconds

Function completed in: 5.73 seconds
Function returned after 6.4 seconds

This appears to be related to garbage collecting many numpy arrays nested in a ragged object array.

Runtime information:

.[{'simd_extensions': {'baseline': ['SSE', 'SSE2', 'SSE3'],
'found': ['SSSE3',
'SSE41',
'POPCNT',
'SSE42',
'AVX',
'F16C',
'FMA3',
'AVX2'],
'not_found': ['AVX512F',
'AVX512CD',
'AVX512_SKX',
'AVX512_CLX',
'AVX512_CNL',
'AVX512_ICL']}},
{'filepath': 'env_crest\Library\bin\mkl_rt.2.dll',
'internal_api': 'mkl',
'num_threads': 6,
'prefix': 'mkl_rt',
'threading_layer': 'intel',
'user_api': 'blas',
'version': '2023.1-Product'}]

I can't reproduce with any of the NumPy versions. Are you sure you are not changing other things rather than just numpy?
Also where did you get NumPy from, since MKL isn't a NumPy wheel build clearly, from conda? Or even the intel conda channel, or...?

OK, this increased my frustration with getting a nice setup on windows to run, but I found the issue: In certain paths that shouldn't really ever be taken much, we call a getenv, which apparently is infinitely slow on windows compared to linux.

Sorry about that - I've copied the full version information from the linked scikit issue here:

System:
    python: 3.10.12 | packaged by Anaconda, Inc. | (main, Jul  5 2023, 19:09:20) [MSC v.1916 64 bit (AMD64)]
executable: env_crest\python.exe
   machine: Windows-10-10.0.19045-SP0

Python dependencies:
      sklearn: 1.2.1
          pip: 23.1.2
   setuptools: 67.8.0
        numpy: 1.23.5
        scipy: 1.10.1
       Cython: None
       pandas: 1.5.3
   matplotlib: 3.7.1
       joblib: 1.2.0
threadpoolctl: 2.2.0

Built with OpenMP: True

threadpoolctl info:
       filepath: env_crest\Library\bin\mkl_rt.2.dll
         prefix: mkl_rt
       user_api: blas
   internal_api: mkl
        version: 2023.1-Product
    num_threads: 6
threading_layer: intel

       filepath: env_crest\vcomp140.dll
         prefix: vcomp
       user_api: openmp
   internal_api: openmp
        version: None
    num_threads: 12

But yes, based on the conversation there, it seems the problem is isolated to windows environments. Glad you were able to track it to the getenv call; thanks for digging into it.

@seberg

@seberg Sorry to put this back on your plate, but I think there actually may be something else going on as well, even using numpy==1.21.6. I'm not positive it's a garbage collection issue or exactly related, because it's difficult to pin down exactly what is happening due to multithreading.

In reality I'm using dask, but I've replicated it using just the base ThreadPoolExecutor as well:

from concurrent.futures import ThreadPoolExecutor
from scipy.spatial import KDTree 

import numpy as np
import time, psutil

N_ELE = 5e5


def concat1(x):
    return np.concatenate(x, dtype=np.int64)

def concat2(x):
    total = np.r_[0, np.cumsum(list(map(len, x)))]
    y = np.empty(total[-1], dtype=np.int64)
    for i, n in enumerate(x):
        y[total[i]:total[i+1]] = n
    return y 

def mwe(concat):
    a = KDTree([[1]]).query_ball_point([[1]]*int(N_ELE), 1)
    return concat(a)

def multithread(f, concat, workers, jobs=8):
    label = f'{concat.__name__} using {workers} workers'
    with ThreadPoolExecutor(max_workers=workers) as pool:
        proc = psutil.Process()
        start = time.time()
        psutil.cpu_percent()
        list(pool.map(f, [concat] * jobs))
        print(f'{label} finished in {time.time()-start:.1f} seconds')
        print(f'CPU usage: {psutil.cpu_percent()}%')
        print(f'MEM usage: {proc.memory_info().peak_wset/1e6:,.1f}MB\n')

# Function combinations generate the same result
assert((mwe(concat1) == mwe(concat2)).all())

# 1 worker vs 8 workers
multithread(mwe, concat2, 1)
multithread(mwe, concat1, 1)
print()

multithread(mwe, concat2, 8)
multithread(mwe, concat1, 8)
print()

concat2 using 1 workers finished in 7.6 seconds
CPU usage: 16.3%
MEM usage: 167.6MB

concat1 using 1 workers finished in 7.4 seconds
CPU usage: 15.9%
MEM usage: 196.3MB


concat2 using 8 workers finished in 6.4 seconds
CPU usage: 17.2%
MEM usage: 461.5MB

concat1 using 8 workers finished in 16.8 seconds
CPU usage: 24.3%
MEM usage: 1,038.2MB

The observation is that using np.concatenate with multiple threads uses more CPU, and far more peak memory, than using an explicit for loop to concatenate.

I've tried to minimize the comparisons here, but the reason I think it might be related to the previous issue is that by using scipy's KDTree (which produces a nested object array of lists) I observe the above. If I use sklearn's KDTree however (which produces a nested object array of arrays), I find that the problem exists for both concat1 and concat2 - implying there's something happening with the array representation specifically that's causing an issue.

I can open a new issue if you feel this should be treated separately.

#24248 improves the reproducer at the top of the issue. If you think there is still more to do, please open a new issue with the concatenate example.

I think this is expected, TBH. Yeah, there are a couple of things that could be tweaked, but 🤷

array assignment releases the GIL even for tiny arrays (why? dunno, probably it shouldn't)
concatenate creates the temporary arrays for everything, which means it has to convert all of those lists if they are not lists.
Since it releases the GIL, you will probably end up with that conversion happening on every worker.

Those things seem sufficient to me to explain things. Should it convert everything to array if you pass the dtype? It still needs to infer the shape, so that can't really avoided.

At that point, I don't think we are talking about a bug anymore, but rather about asking for an improvement for working with concatenate and thousands of objects.
(Which, fair, you can open an issue about.)

The getenv thing explains the big difference between linux and windows that we saw (I think), so I do consider it a performance bug that I expect has a large effect on any workflow with many small arrays.

Yeah, after minimizing it a little more, I think you're right that it's completely separate from this issue. Thanks for taking care of this one.

The one thing I don't understand about what you said in your second point above, though: if it needs to create the temporary arrays, shouldn't the issue be more apparent when the nested object is a list rather than already an array? In the reproducible I posted in the new issue, the nest_type being a list and manually setting array entries is the only way I find it works properly - if nest_type=np.array instead it doesn't seem to work with either concat function.

Concatenate works with a sequence, so ignore the first dimensions, it is always converted to a list. I understand you as: The "slow" version has [list(), list()] while the fast version has [array, array], which would make sense.

Right, and that would make sense - but what I found is that it's actually the opposite: [list(), list()] is fast, [array, array] is slow.

The slow example above has array of lists. You said the sklearn was faster? Could you try to narrow this down to an example not using KDTree in order to make this clearer? For all I know the reason may also be that this is wrapping cython memoryviews into arrays and just the added level is slow.

The MWE in the new issue now removes the sklearn/scipy KDTree dependency - it uses just numpy and you can specify the inner object with the nest_type variable.

Navigation Menu

Repository navigation

BUG: Garbage collection order of magnitude slower in numpy>=1.22 #24232

Describe the issue:

Runtime information:

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

BUG: Garbage collection order of magnitude slower in numpy>=1.22 #24232

Description

Describe the issue:

Runtime information:

Activity

seberg commented on Jul 22, 2023

seberg commented on Jul 23, 2023

BrandonSmithJ commented on Jul 23, 2023

BrandonSmithJ commented on Jul 24, 2023

mattip commented on Jul 24, 2023

seberg commented on Jul 24, 2023

BrandonSmithJ commented on Jul 24, 2023

seberg commented on Jul 24, 2023

BrandonSmithJ commented on Jul 24, 2023

seberg commented on Jul 24, 2023

BrandonSmithJ commented on Jul 24, 2023

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions