Skip to content
This repository has been archived by the owner on Apr 11, 2020. It is now read-only.

Bug ? Rasterio + WarpVRT bad performances for GDAL3.0 + Proj6 #10

Closed
vincentsarago opened this issue Nov 16, 2019 · 20 comments
Closed

Bug ? Rasterio + WarpVRT bad performances for GDAL3.0 + Proj6 #10

vincentsarago opened this issue Nov 16, 2019 · 20 comments

Comments

@vincentsarago
Copy link
Member

No description provided.

@vincentsarago
Copy link
Member Author

@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

@vincentsarago
Copy link
Member Author

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

@rouault
Copy link

rouault commented Nov 17, 2019

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.

@vincentsarago
Copy link
Member Author

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

@vincentsarago
Copy link
Member Author

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

@vincentsarago
Copy link
Member Author

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.

@rouault
Copy link

rouault commented Nov 19, 2019

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

@sgillies
Copy link

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

@vincentsarago
Copy link
Member Author

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

@vincentsarago vincentsarago changed the title Revert recent change: latest gdal3.0-py3.7 break everything ! Bug ? Rasterio + WarpVRT bad performances for GDAL3.0 + Proj6 Nov 19, 2019
@vincentsarago
Copy link
Member Author

@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

Script

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)

Dockerfile

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

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

Makefile

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

@vincentsarago
Copy link
Member Author

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)

@sgillies
Copy link

Ouch 🤕

I'll try to reproduce soon.

@vincentsarago

This comment has been minimized.

@vincentsarago
Copy link
Member Author

@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!

@vincentsarago

This comment has been minimized.

@vincentsarago
Copy link
Member Author

@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 ;-)

@rouault
Copy link

rouault commented Nov 26, 2019

@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.

@vincentsarago
Copy link
Member Author

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

# proj
RUN mkdir /tmp/proj \
&& curl -sfL http://download.osgeo.org/proj/proj-$PROJ_VERSION.tar.gz | tar zxf - -C /tmp/proj --strip-components=1 \
&& cd /tmp/proj \
&& CFLAGS="-O2 -Wl,-S" CXXFLAGS="-O2 -Wl,-S" ./configure --prefix=$PREFIX \
&& make -j $(nproc) --silent && make install && make clean \
&& rm -rf /tmp/proj
# geos
RUN mkdir /tmp/geos \
&& curl -sfL http://download.osgeo.org/geos/geos-$GEOS_VERSION.tar.bz2 | tar jxf - -C /tmp/geos --strip-components=1 \
&& cd /tmp/geos \
&& CFLAGS="-O2 -Wl,-S" CXXFLAGS="-O2 -Wl,-S" ./configure --prefix=$PREFIX \
&& make -j $(nproc) --silent && make install && make clean \
&& rm -rf /tmp/geos
ENV PKG_CONFIG_PATH=$PREFIX/lib/pkgconfig/
# gdal
ENV GDAL_VERSION=3.0.2
RUN mkdir /tmp/gdal \
&& curl -sfL https://github.com/OSGeo/gdal/archive/v${GDAL_VERSION}.tar.gz | tar zxf - -C /tmp/gdal --strip-components=2
RUN cd /tmp/gdal \
&& CFLAGS="-O2 -Wl,-S" CXXFLAGS="-O2 -Wl,-S" ./configure \
--prefix=$PREFIX \
--with-proj=$PREFIX \
--with-geos=$PREFIX/bin/geos-config \
--with-curl \

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.

@vincentsarago
Copy link
Member Author

vincentsarago commented Nov 26, 2019

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.

@vincentsarago
Copy link
Member Author

vincentsarago commented Nov 26, 2019

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

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Development

No branches or pull requests

3 participants