boto3 slows down Titiler's GET /cog/tiles?

[glostis]

Hi,

Thanks for this amazing library!

I've been trying to fine-tune the performance of titiler, and encountered a strange behavior.
I'm not sure where exactly in the stack the problem lies — if it's at titiler's level, or rio-tiler, or rasterio. Feel free to redirect me if this is not the appropriate place to post such an issue.

TL;DR

The short version is that, when trying to get tiles from a COG stored on S3, if boto3 is installed, the time to get the tiles is roughly doubled compared to when boto3 is not installed (note: titiler still manages to access files on S3 without boto3).

This performance drop may be related to the specific setup I have (which I will describe below), but in any case I would like to have your opinion on what is going on.

Reproducing locally

1. I have a COG stored on a local MinIO instance at s3://bucket/cog.tif.

   Details to reproduce locally

   docker run -p 9000:9000 -p 9001:9001 --rm --name minio minio/minio:latest server /data --console-address ":9001"
   # Create a bucket called `bucket`
   docker exec -it minio mc mb --ignore-existing data/bucket

   Then go to the MinIO dashboard and upload a cog.tif file.

2. In all further steps, I have exported the following environment variables:

   export AWS_ACCESS_KEY_ID=minioadmin
   export AWS_SECRET_ACCESS_KEY=minioadmin
   export AWS_S3_ENDPOINT="127.0.0.1:9000"
   export AWS_VIRTUAL_HOSTING="FALSE"
   export AWS_HTTPS="FALSE"

3. I have a minimal titiler instance, defined as below, and launched with python minititiler.py:

   Code for minimal titiler

   import logging
   
   import uvicorn
   from fastapi import FastAPI
   from titiler.core.errors import DEFAULT_STATUS_CODES, add_exception_handlers
   from titiler.core.factory import TilerFactory
   from titiler.core.middleware import LoggerMiddleware, TotalTimeMiddleware
   
   logging.basicConfig(level=logging.INFO)
   logger = logging.getLogger(__name__)
   
   app = FastAPI(title="My simple app")
   
   try:
       import boto3
       from rasterio.session import AWSSession
       cog = TilerFactory(environment_dependency=lambda: {"session": AWSSession(boto3.Session())})
   except ImportError:
       cog = TilerFactory()
   app.include_router(cog.router, tags=["Cloud Optimized GeoTIFF"], prefix="/cog")
   app.add_middleware(LoggerMiddleware, headers=True, querystrings=True)
   app.add_middleware(TotalTimeMiddleware)
   
   add_exception_handlers(app, DEFAULT_STATUS_CODES)
   
   
   if __name__ == "__main__":
       uvicorn.run(app, log_level="info")

4. I use the below script to profile the access time to get tiles, launched with python profile.py

   Code for profiling

   import argparse
   import asyncio
   import random
   import statistics
   from collections import Counter
   
   import aiohttp
   import morecantile
   from rio_tiler.io import COGReader
   
   random.seed(42)
   
   
   async def fetch(session, url, cog_url):
       async with session.get(url, params={"url": cog_url}) as response:
           return float(response.headers["server-timing"].split("=")[1]), response.status
   
   
   async def main(titiler_url, cog_url, tile_number):
       tilematrixset = morecantile.tms.get("WebMercatorQuad")
       with COGReader(cog_url, tms=tilematrixset) as cog:
           minzoom = cog.minzoom
           maxzoom = cog.maxzoom
           w, s, e, n = cog.geographic_bounds
   
       urls = []
       for zoom in range(minzoom, maxzoom + 1):
           ul_tile = tilematrixset.tile(w, n, zoom)
           lr_tile = tilematrixset.tile(e, s, zoom)
           for x in range(ul_tile.x, lr_tile.x + 1):
               for y in range(ul_tile.y, lr_tile.y + 1):
                   urls.append(f"{titiler_url}/cog/tiles/{zoom}/{x}/{y}")
   
       urls = random.choices(urls, k=tile_number)
       async with aiohttp.ClientSession() as session:
           tasks = [fetch(session, url, cog_url) for url in urls]
           results = await asyncio.gather(*tasks)
       times = [el[0] for el in results]
       codes = [el[1] for el in results]
       print("Got the following response codes:")
       for code, nb in Counter(codes).items():
           print(f"- HTTP {code}: {nb} responses")
       mean = statistics.mean(times)
       stdev = statistics.stdev(times)
       print()
       print(f"Server response time per tile: {mean:.0f} ± {stdev:.0f} ms")
   
   
   if __name__ == "__main__":
       parser = argparse.ArgumentParser()
       parser.add_argument("--titiler", help="URL to the titiler server", default="http://localhost:8000")
       parser.add_argument("--cog", help="URL to the Cloud Optimized GeoTIFF", default="s3://bucket/cog.tif")
       parser.add_argument("--number", type=int, help="Number of tiles to fetch", default=50)
       args = parser.parse_args()
       asyncio.run(main(args.titiler, args.cog, args.number))

Results

• If I run minititiler.py in a python environment which doesn't have boto3 installed (pip install titiler uvicorn):
  • The tile request times are on the order of 862 ± 240 ms according to profile.py.
  • In the titiler server logs, I see one rasterio.session:boto3 not available, falling back to a DummySession. log line per requested tile.
• If I run minititiler.py in a python environment which has boto3 installed (pip install titiler uvicorn boto3):
  • The tile request times are on the order of 1916 ± 298 ms according to profile.py.
  • In the titiler server logs, I see lots of botocore.credentials:Found credentials in environment variables. lines (in my case, 140 lines for 50 requested tiles).

1. Do you have an explanation for the slowdown caused by the presence of boto3? It's most certainly related to this conditional import in rasterio, but I don't understand why it impacts the performance of titiler.
2. As you can see in my code for minititiler.py, I've tried to use the environment_dependency field from the TileFactory to pass an already instanciated rasterio.session.AWSSession to titiler's tiling route, but it doesn't seem to make much of a difference. Maybe I'm using it wrong?

[vincentsarago]

Hi @glostis
thanks for the detailed and reproductible example 🙏

I've moved this to discussion because as you mentioned this is not a titiler issue but more a Rasterio/GDAL one!

To better understand what's going on you could try setting CPL_VSIL_SHOW_NETWORK_STATS=TRUE (ref: OSGeo/gdal#2742) or maybe https://github.com/developmentseed/tilebench

But I think this is mostly because GDAL/rasterio will first create the AWS session and then access the file, instead of just trying to access the file directly. you can try setting AWS_NO_SIGN_REQUEST=TRUE to also see if there is an impact

[vincentsarago]

Can you try to create a simple reproductible example with only a simple rasterio block and produce some numbers

with rasterio.Env(AWSSession(boto3.Session()):
    with rasterio.open("s3://my.tif") as src:
        arr = src.read(window=((100, 200), (100, 200)))

[glostis]

Sure!

I've used the following snippet (still using the same MinIO local bucket as above):

import logging

import rasterio
from rasterio.session import AWSSession, DummySession

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

try:
    import boto3
    session = AWSSession(boto3.Session())
except ImportError:
    session = DummySession()

with rasterio.Env(session):
    with rasterio.open("s3://bucket/cog.tif") as src:
        arr = src.read(window=((100, 200), (100, 200)))

I've timed 15 executions of ./venv-with-boto3/bin/python snippet.py versus ./venv-without-boto3/bin/python snippet.py using multitime where the difference between the two python virtualenvs is simply the fact that boto3 is installed.

The results:

• With boto3: 0.259 ± 0.008
• Without boto3: 0.188 ± 0.006

I've noticed that more or less the same results (~+100ms execution time with boto3) are obtained even when not accessing the file, i.e. replacing snippet.py above with just:

import rasterio

meaning that the overhead comes from the code path traversed when importing rasterio, not when instanciating an AWSSession or an Env?

[vincentsarago]

Thanks @glostis

it will be interesting to run a profiler on just import rasterio with and without boto3 to really understand what's going on.

Feel free to start a discussion in the rasterio repo directly because I'm 💯 convinced this is not a titiler/rio-tiler issue

[glostis]

I'll try to dig in that direction indeed, thanks!

The only point on which I'm still a bit unsure is why titiler's tile serving performance is affected by the slowness induced by importing rasterio when boto3 is installed. I'm not familiar with uvicorn and fastapi, but shouldn't rasterio be imported only once at startup of the server, and then kept in memory during the lifetime of the server?

[vincentsarago]

I think it's because we are creating a new rasterio.env.Env on each call https://github.com/developmentseed/titiler/blob/main/src/titiler/core/titiler/core/factory.py#L379

[JacobJeppesen]

I haven't thoroughly read through the discussion, so apologize if my input is off point, but this issue sounded a bit like some things I stumbled upon recently: mapproxy/mapproxy#422 and opendatacube/odc-stac#115 (comment) . Perhaps there's some inspiration to be found there.

Edit: Just wanted to also give a shoutout to @vincentsarago for this library. Amazing work! 🎉

[glostis]

Thanks for the pointers @JacobJeppesen!

I'm not familiar with mapproxy nor odc-stac, but at first glance the issues you've linked seem quite similar to mine indeed.