Bug ? Rasterio + WarpVRT bad performances for GDAL3.0 + Proj6 about amazonlinux HOT 20 CLOSED

Ouch 🤕

I'll try to reproduce soon.

from amazonlinux.

@vincentsarago If you can isolate pure GDAL cases where you see dramatic performance differences , like the 0.14 vs 1.85 I can see, that would be worth opening a GDAL ticket to see if there's some low hanging fruit. Coordinate instanciatation is slower in PROJ 6 for sure compared to previous versions: but it is like we need 20 ms whereas we needed 1 ms before, so my expectation was that for most use cases that would be within the noise.

from amazonlinux.

@rouault FYI, I'm seeing a huge performance downgrade using latest commit from gdal in release/3.0 (I think it worked fine up to this commit OSGeo/gdal@776e602 (included). I'm not sure what's going on but for now, I'm switching back the the official gdal release.

My use case as usual is using rasterio to do dynamic tilling (using warped VRT). I'll try to narrow everything when I'm done fixing this

from amazonlinux.

Note:
I also tested with release/2.4 and it seems to work fine

from amazonlinux.

I think it worked fine up to this commit OSGeo/gdal@776e602 (included). I'm not sure what's going on but for now, I'm switching back the the official gdal release.

I can't think how OSGeo/gdal@776e602 could impact performance. It has been backported to release/2.4 as well. It really just avoids an error to be emitted.

from amazonlinux.

Thanks @rouault I'm still investigating
I'm still not sure what's going on, and this might be only for this project! I've tried a different combination of rasterio/gdal/proj version but for now I'm switching back to gdal2.4.

I'll continue digging deeper because I've got numerous project that depends on this

from amazonlinux.

alright narrowing down this, it seems to be a rasterio/rio-tiler problem

FYI @sgillies I'm seeing a huge performance decrease using GDAL3.0 (proj 6.2.1) when using rio tiler over remote files. I'm working on make reproductible test for now I'll let you know as soon as I have a better understanding

from amazonlinux.

Alright still working on this but I have a better sense of what is doing the performance decrease.
I think the slowdown for WarpedVRT tiling is due to reprojection (thus PROJ v6). The performance of tiling is hugely impacted by the input projection.

I know PROJ 6 shipped a lot of changes and that Rasterio supports it but there might be some optimization missing.

from amazonlinux.

What is expensive with PROJ 6 is creating a PROJ PJ* object (or instanciating a OGRCoordinateTrasnsformation object which is basically a wrapper over it). So you should try to minimize the number of those instanciations. Once a PJ / OGRCoordinateTrasnsformation is created, the peformance of using it with PROJ 6 with many points should be similar to with PROJ < 6. Normally for a warped VRT, GDAL just creates two such objects, so I don't think this would impact performance for a large enough dataset

from amazonlinux.

@vincentsarago are you making a WarpedVRT (or several) for every request? Sounds like that might no longer scale with PROJ 6.

from amazonlinux.

Indeed I am but I don’t have a choice.
I still find odd that pure GDAL is 6 times faster than rasterio for this.
Also depending on the input projection I’m getting different results
I hope to be able to share test case later this morning

from amazonlinux.

@sgillies here some numbers

There is a huge performance downgrade when using GDAL3+PROJ6, and has pointed by Even, it might be related to OGRCoordinateTrasnsformation

The main performance changes are for

rasterio._warp.WarpedVRTReaderBase: 0.290s -> 3.302s

and

rasterio._warp._calculate_default_transform 0.001s -> 1.033s

GDAL 2

Tile Read Time 0.761 seconds

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    1.159    1.159    1.160    1.160 __init__.py:57(open)
        1    0.460    0.460    0.460    0.460 utils.py:313(has_alpha_band)
        1    0.290    0.290    0.290    0.290 {method 'read' of 'rasterio._warp.WarpedVRTReaderBase' objects}
      119    0.007    0.000    0.012    0.000 hooks.py:390(_alias_event_name)
        2    0.005    0.002    0.005    0.002 {method 'to_epsg' of 'rasterio._crs._CRS' objects}
     6620    0.003    0.000    0.003    0.000 {method 'index' of 'list' objects}
        2    0.002    0.001    0.003    0.001 {method 'start' of 'rasterio._env.GDALEnv' objects}
     8320    0.002    0.000    0.002    0.000 {method 'split' of 'str' objects}
        1    0.001    0.001    0.761    0.761 utils.py:337(_tile_read)
        1    0.001    0.001    0.002    0.002 {rasterio._warp._calculate_default_transform}

GDAL 3

Tile Read Time 5.569 seconds

        1    3.302    3.302    3.302    3.302 {method 'read' of 'rasterio._warp.WarpedVRTReaderBase' objects}
        1    1.200    1.200    1.201    1.201 __init__.py:57(open)
        1    1.033    1.033    1.034    1.034 {rasterio._warp._calculate_default_transform}
        1    0.515    0.515    5.569    5.569 utils.py:337(_tile_read)
        1    0.448    0.448    0.448    0.448 utils.py:313(has_alpha_band)
        2    0.267    0.134    0.268    0.134 {rasterio._base._transform}
      119    0.007    0.000    0.012    0.000 hooks.py:390(_alias_event_name)
     6620    0.003    0.000    0.003    0.000 {method 'index' of 'list' objects}

Same file, same mercator tile

import pstats
import cProfile

import mercantile
import rasterio
from rio_tiler import utils

def profileit(func):
    """Profiling."""
    def wrapper(*args, **kwargs):
        prof = cProfile.Profile()
        retval = prof.runcall(func, *args, **kwargs)
        ps = pstats.Stats(prof)
        ps.strip_dirs().sort_stats('time', 'cumulative').print_stats(20)
        return retval
    return wrapper


@profileit
def _rio_tiler_read(src_path, bounds, tilesize=256):
    with rasterio.Env():
        utils.tile_read(
            src_path,
            bounds,
            tilesize,
            tile_edge_padding=0,
            warp_vrt_option=dict(SOURCE_EXTRA=1),
        )
    return True

src_path = "https://s3.amazonaws.com/opendata.remotepixel.ca/bench_tiler/LC08_L1TP_040013_20191014_20191029_01_T1_B4.tif"
z, x, y = 9, 115, 123
tile = mercantile.Tile(x=x, y=y, z=z)
tile_bounds = mercantile.xy_bounds(tile)
_rio_tiler_read(src_path, tile_bounds)

ARG GDAL_VERSION
FROM remotepixel/amazonlinux:gdal${GDAL_VERSION}-py3.7

RUN pip3 install rio-tiler mercantile --no-binary rasterio

docker build --build-arg GDAL_VERSION=3.0 --tag img:latest  .
docker run \
    --name bench \
    --env GDAL_HTTP_MULTIPLEX=YES \
    --env GDAL_HTTP_VERSION=2 \
    --env GDAL_HTTP_MULTIRANGE=YES \
    --env GDAL_HTTP_MERGE_CONSECUTIVE_RANGES=YES \
    --env VSI_CACHE=TRUE \
    --env VSI_CACHE_SIZE=1073741824 \
    --env CPL_DEBUG=ON \
    --rm -it img:latest /bin/bash

from amazonlinux.

More on projection

performance is also dependent to the input projection

EPSG:32614

file: https://s3.amazonaws.com/opendata.remotepixel.ca/bench_tiler/LC08_L1TP_040013_20191014_20191029_01_T1_B4.tif

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    3.872    3.872    3.872    3.872 {method 'read' of 'rasterio._warp.WarpedVRTReaderBase' objects}
        1    1.364    1.364    1.364    1.364 __init__.py:57(open)
        1    1.092    1.092    1.093    1.093 {rasterio._warp._calculate_default_transform}
        1    0.529    0.529    0.530    0.530 utils.py:313(has_alpha_band)
        1    0.519    0.519    6.299    6.299 utils.py:337(_tile_read)

EPSG:4326

file: https://s3.amazonaws.com/opendata.remotepixel.ca/bench_tiler/LC08_L1TP_040013_20191014_20191029_01_T1_B4_WGS84_cog.tif

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.865    0.865    0.866    0.866 __init__.py:57(open)
        1    0.555    0.555    0.556    0.556 utils.py:313(has_alpha_band)
        1    0.206    0.206    0.206    0.206 {method 'read' of 'rasterio._warp.WarpedVRTReaderBase' objects}
        1    0.068    0.068    0.068    0.068 {rasterio._warp._calculate_default_transform}
        1    0.003    0.003    0.837    0.837 utils.py:337(_tile_read)

EPSG:3347

file: https://s3.amazonaws.com/opendata.remotepixel.ca/bench_tiler/LC08_L1TP_040013_20191014_20191029_01_T1_B4_CaLambert_cog.tif

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    9.892    9.892    9.892    9.892 {method 'read' of 'rasterio._warp.WarpedVRTReaderBase' objects}
        1    3.043    3.043    3.043    3.043 {rasterio._warp._calculate_default_transform}
        1    1.545    1.545   15.766   15.766 utils.py:337(_tile_read)
        1    0.938    0.938    0.938    0.938 __init__.py:57(open)
        2    0.716    0.358    0.717    0.358 {rasterio._base._transform}
        1    0.566    0.566    0.566    0.566 utils.py:313(has_alpha_band)

from amazonlinux.

@sgillies maybe it could be related to rasterio/rasterio#1745 ?

from amazonlinux.

@sgillies I'm so sorry, this might not be on rasterio side after all but might be on rio-tiler 🤦‍♂

I'll ping you as soon as I have a better sense of what's going on!

from amazonlinux.

I set up a small benchmark suite over https://github.com/vincentsarago/rio-tiler-bench to compare gdalwarp and rio-tiler.utils._tile_read

reports:

• GDAL 2.4 https://gist.github.com/vincentsarago/3f73fb7adc8b495d4c861a5fc5afa9d5
• GDAL 3.0 https://gist.github.com/vincentsarago/928109d9ed2d509fe4d3fad088e5c262

I'll try to make a nice looking table but quick notes:

GDAL 2.4.3 (proj 5.2.0):

the new version of rio-tiler (cogeotiff/rio-tiler#132) behave almost as gdawarp command

• fetch the same overview level
• Use same number of get requests and data
• almost same runtime

GDAL 3.0.2 (proj 6.2.1):

• the new version of rio-tiler is faster than the previous version
• fetch the same overview level
• Use same number of get requests
• Use almost the same number of bytes
• is 2x time slower than gdalwarp

so @sgillies answer to your previous question:
rio-tiler (WarpedVRT + _calculate_default_transform) is still 2-3x time slower with GDAL 3.0 while it doesn't fetch more data (or use different overviews).

Even if OGRCoordinateTrasnsformation is slower between Proj 5 and Proj 6, this doesn't explain why gdalwarp is as fast between gdal 2 and gdal3 while WarpedVRT + _calculate_default_transform is now slower.

Edit: the last point don't seems to be true, I need better number but it seems that with the new rio-tiler both gdal and rasterio takes the same amount of tile (still slower than with gdal2)

from amazonlinux.

@rouault @sgillies Thanks for dropping by!

I've published some early numbers over https://github.com/vincentsarago/rio-tiler-bench showing the expected behaviour of PROJ 6 to be slower for dynamic tiling (definitely a blocker for us).

I don't see any difference between GDAL and Rasterio so @sgillies I'm sorry that I pinged you ;-)

from amazonlinux.

I see, thanks @rouault I'll try to check all the logs and see if I can get a complete understanding.

I'll also need to make sure that I'm not compiling GDAL and PROJ with wrong options

The command I'm using is pretty straight forward

gdalwarp -q in.tif out.tif -te {left} {top} {right} {bottom} -t_srs EPSG:3857 -ts 256 256-r bilinear

I'll test with gdal provided docker images to see if I can see the same results.

from amazonlinux.

osgeo/gdal:alpine-ultrasmall-v2.4.1 (PROJ 5.2)

/ # gdalinfo --version
GDAL 2.4.1, released 2019/03/15
/ # GDAL_DISABLE_READDIR_ON_OPEN=EMPTY_DIR time gdalwarp -q -te -11036283.891926888  10410111.756214723 -10958012.374
962866  10331840.239250703 -t_srs EPSG:3857 -ts 256 256 -r bilinear -overwrite /vsicurl/https://s3.amazonaws.com/open
data.remotepixel.ca/bench_tiler/LC08_L1TP_040013_20191014_20191029_01_T1_B4.tif out.tif
real    0m 0.62s
user    0m 0.05s
sys     0m 0.05s

osgeo/gdal:alpine-ultrasmall-3.0.2 (PROJ 6.2.1)

/ # gdalinfo --version
GDAL 3.0.2, released 2019/10/28
/ # GDAL_DISABLE_READDIR_ON_OPEN=EMPTY_DIR time gdalwarp -q -te -11036283.891926888  10410111.756214723 -10958012.374962866  10331840.239250703 -t_srs EPSG:3857 -ts 256 256 -r bilinear -overwrite /vsicurl/https://s3.amazonaws.com/opendata.remotepixel.ca/bench_tiler/LC08_L1TP_040013_20191014_20191029_01_T1_B4.tif out.tif

real    0m 0.76s
user    0m 0.13s
sys     0m 0.04s

Updated the number with GDAL_DISABLE_READDIR_ON_OPEN=EMPTY_DIR to make sure timing wasn't only bias by file listing.

from amazonlinux.

remotepixel/amazonlinux:gdal2.4-py3.7

bash-4.2# gdalinfo --version
GDAL 2.4.3, released 2019/10/28
bash-4.2# time GDAL_DISABLE_READDIR_ON_OPEN=EMPTY_DIR gdalwarp -q -te -11036283.891926888  10410111.756214723 -10958012.374962866  10331840.239250703 -t_srs EPSG:3857 -ts 256 256 -r bilinear -overwrite /vsicurl/https://s3.amazonaws.com/opendata.remotepixel.ca/bench_tiler/LC08_L1TP_040013_20191014_20191029_01_T1_B4.tif out.tif

real    0m0.656s
user    0m0.060s
sys     0m0.050s

remotepixel/amazonlinux:gdal3.0-py3.7

bash-4.2# gdalinfo --version
GDAL 3.0.2, released 2019/10/28
bash-4.2# time GDAL_DISABLE_READDIR_ON_OPEN=EMPTY_DIR gdalwarp -q -te -11036283.891926888  10410111.756214723 -10958012.374962866  10331840.239250703 -t_srs EPSG:3857 -ts 256 256 -r bilinear -overwrite /vsicurl/https://s3.amazonaws.com/opendata.remotepixel.ca/bench_tiler/LC08_L1TP_040013_20191014_20191029_01_T1_B4.tif out.tif

real    0m2.493s
user    0m1.740s
sys     0m0.170s

Alright .... it make sense now 🤦‍♂, there something wrong with my docker images. I should have checked that first, I'm sorry @rouault

from amazonlinux.