GDAL Error Reported in logs, but rasterio method never returns

[ryanherring]

I was hoping to be able to provide a more comprehensive way to reproduce the issue I'm seeing, but it's triggering so rarely in a remote environment that I have not been able to reproduce it on my laptop. I figured it was worth asking and seeing how I may be able to gather more info. The issue I'm seeing is that this block of code never returns (hangs indefinitely):

with rasterio.open("...") as src:
    data = src.read(masked=True)

A log message is printed out shortly after entering this block and then no other log messages are printed and the process never terminates or has any Python exception thrown.

INFO - GDAL signalled an error: err_no=2, msg='/io/gdal-3.6.4/gcore/gdalnodatamaskband.cpp, 258: cannot allocate 103862880 bytes'

The raster file I'm trying to open has the shape (6, 5478, 4740) and the dtype is float32. This read is also taking place in a loop that reads in other rasters of a similar size and this one is the 8th or so that's read in when the issue occurs.

I'm running this code over a very large number of rasters in a remote environment that uses Docker and runs in AWS. If I specify a small amount of memory (e.g. 4Gi) for the container, the call to read the data fails quickly with this exception:

numpy.core._exceptions._ArrayMemoryError: Unable to allocate 594. MiB for an array with shape (6, 5478, 4740) and data type float32

When I run the same code with a container size of 16Gi, then I hit the issue described above (error message and task hangs until manually killed).

I want to make it clear that I understand that the size of 16Gi is insufficient to read all of the data into memory. If I set the memory higher, it succeeds. The issue is that I am only able to determine that the increase in memory is necessary by observing a hanging task and manually intervening. (Our team has code that automatically retries tasks with more memory if a task failed with an out of memory exception, but since the task is hanging, that logic is unable to kick in.)

If anyone has any thoughts on how to dig into this further, please let me know!

[jmarintur]

Hi @ryanherring, what about using timeout-decorator?

[ryanherring]

@jmarintur - we do use a timeout, however that's insufficient for our current use case for two reasons:

1. The maximum time for legitimate tasks is rather high (several hours) and it is a major project to break down the tasks into sub-components due to us using ecologically defined units for parallelism and those units are large.
2. We want to catch out of memory exceptions and change behavior of subsequent runs based on those exceptions. If we kill a task manually or with a timeout, we lose that context.

[jmarintur]

In this scenario, I can think about two things you could combine. First, have a custom memory monitoring in place, e.g. via psutil, that could be used at catching not just memory issues, and, second, to reduce the cases or perhaps even get rid of them, read by blocks / windows.

[jlw5]

We do use windowed reads most of the time. But it's a good suggestion to double-check in some of these specific tasks.

We also are already doing some memory monitoring using psutil -- it's pretty low level, but we run it every 15 seconds. Interesting thought to combine that with our knowledge of how much memory is available and raise an Exception when we get to 80%? 90%? of our memory allocation. It's a little wasteful and not foolproof, but getting rid of most the gdal warnings that don't raise Exceptions would be worth it.

[jlw5]

@jmarintur This was an excellent suggestion. It's a hack but so far, it's working. 🎉
Every 15 seconds, we collect current vms memory usage with psutil.Process(self.pid).
We also set an rlimit on every process/task and we can get it with resource.getrlimit(resource.RLIMIT_AS)[0]
I added a check:

        if vms_memory > rlimit_memory - MEMORY_BUFFER:
             # raise an Exception that gets caught and triggers a retry with more memory

With MEMORY_BUFFER set to 1.5 GiB (1 GiB was not enough in our testing), this is working!
We see the GDAL INFO message about not enough memory, but we actually get to the Exception and retry.

The hanging has been a HUGE thorn in our side, so posting this solution (hack) here in case it's useful to anyone else.

[sgillies]

@ryanherring so, when memory allocation fails in Python you get a Python exception, but when memory allocation fails in a GDAL routine there may be a deadlock? The GDAL project has fixed a potential deadlock involving multi-threading decoding of TIFFs as recently as last fall: OSGeo/gdal#8561. I don't think that one was necessarily related to memory. Without knowing the version of GDAL you're using or what format you're reading, it's hard to say more. It's worth a search through GDAL's tracker for relevant open or closed issues.

[ryanherring]

@sgillies - thanks for this reply (I was away for a month). All of our data is in GeoTIFF format. While the deadlock idea seems possible to me, it doesn't seem like the most likely explanation. The fact that there is a log message printed out saying that GDAL was unable to allocate enough memory would indicate that whatever GDAL method was called returned. Of course it could print that message and then deadlock afterward, but that would be odd. Any thoughts on that?

[ryanherring]

@sgillies - I saw this in the rasterio code, but can't quite follow how it would end up being called. Is there a wrapper around this code that ensures that rasterio raises an exception in the case where we hit this code path? It's the only place in the rasterio code base where I see the string literal "GDAL signalled an error", which is what we see in our logs.

https://github.com/rasterio/rasterio/blob/main/rasterio/_err.pyx#L220-L248

[snowman2]

The fact that there is a log message printed out saying that GDAL was unable to allocate enough memory would indicate that whatever GDAL method was called returned. Of course it could print that message and then deadlock afterward, but that would be odd. Any thoughts on that?

Depending on how the code is structured, it is possible for a function to fail and write out an error message inside of a parent function that handles the error. Here is a scenario when I encountered that type of situation: OSGeo/gdal#6081

[ryanherring]

@snowman2 - that makes sense, although I don't think I'm following how that's related to the comment I made (perhaps I'm missing something?) The intent of my comment was to highlight that the error message is printed and thus unlikely (just guessing I suppose) that the GDAL code itself is failing to return and thus the error could be in the rasterio code not handling some edge case correctly (where GDAL signals an error and returns and then rasterio somehow just hangs on the result)?

[zstatmanweil]

Hi @sgillies, I am looking into this issue as well and want to make sure I understand your comments correctly. Is this "error 2" that gdal is throwing in fact a non-fatal error? So rasterio is just logging it and not throwing an exception since gdal isn't throwing a fatal error, but the program may be becoming so slow it seems to have stopped?

If my understanding above is correct, is there a way for us to indicate we do see this error as fatal so rasterio does not just log it but rather raises an exception?

[sgillies]

@zstatmanweil 👋 the INFO level log message comes from here: https://github.com/rasterio/rasterio/blob/main/rasterio/_env.pyx#L85-L94. Note the comment: sometimes GDAL will call CPLError(CE_Failure, ...) and continue. In these cases, I decided to turn down the log level. This may or may not be correct for the situation that we are in here.

In our situation, GDAL tries to allocate memory here: https://github.com/OSGeo/gdal/blob/e187124a8462439d7a94581bc1cb062d9df51ac8/port/cpl_vsisimple.cpp#L1197. This fails and pTemp is NULL at https://github.com/OSGeo/gdal/blob/v3.6.4/gcore/gdalnodatamaskband.cpp#L258, but GDAL continues to call GDALRasterBand::IRasterIO() despite the allocation failure. @rouault, can I get a check on my analysis? Am I reading the GDAL code correctly? Is GDAL in error or is Rasterio mishandling the error messages?

[rouault]

Is GDAL in error

yep, it is. Fix in OSGeo/gdal#9926

[zstatmanweil]

Thanks for the detailed explanation @sgillies and for hopping on a fix so fast @rouault !

[rouault]

@zstatmanweil Actually looking at your comments, I'm surprised you see only a slow down, but not a crash. With my fix a (potentially much) slower execution, but correct result when it completes, is going to be the expected behavior.