8

I have a minimal starlette app running via uvicorn doing nothing but returning a ping. Strangely, even with a single thread, I have 45 file handles to my log file. The handles increase with hits to the app and plateau at 45. I'm counting file handles using lsof:

lsof | grep kml-bkny.log

Of course, this is a minimal re-production. In actuality, my overall app is producing thousands of file handles. Some (~200) I would expect given threads*controller modules. However, I cant account for where thousands of file handles are being created. In my real program they dont plateau either, they grow forever.

here is my app (api.py):

import logging

from starlette.applications import Starlette
from starlette.responses import JSONResponse

logger = logging.getLogger("kml")
logger.setLevel(logging.DEBUG)
handler = logging.FileHandler('/tmp/kml-bkny.log')
logger.addHandler(handler)

def controller_ping(request):
    try:
        logger.debug("Received /ping request")
        return JSONResponse({}, status_code=200)
    except Exception as e:
        logger.error(e)
        return JSONResponse({}, status_code=500)

app = Starlette()
app.add_route(path='/kml/ping', methods=['GET'], route=controller_ping)

I run this on the command line as such:

uvicorn api:app

I test the app using a simple script:

import time
import requests

while True:
    time.sleep(1)
    for _ in range(10):
        r = requests.get(f'http://localhost:8000/kml/ping', timeout=5)

This is running on Ubuntu 18.04 with starlette==0.13.3 and uvicorn==0.11.3 on Python 3.6

As a comparison, there is no such effect when running w/o starlette+uvicorn. The below control program will produce 2 and only 2 file handles on lsof:

import logging
import time

logger = logging.getLogger("kml")
logger.setLevel(logging.DEBUG)
handler = logging.FileHandler('/tmp/kml-bkny.log')
logger.addHandler(handler)

while True:
    time.sleep(1)
    for _ in range(10):
        logger.debug("Received /ping request")

Why would so many file handles be created that I see on lsof when introducing starlette and uvicorn?

Community
  • 1
  • 1
CoderOfTheNight
  • 944
  • 2
  • 8
  • 21
  • 1
    I have 2 questions: how long does it take to get 45 file handles to your log file and how do you count them ? I tried with latest master uvicorn, both starlette 0.13.2 and 10.13.3 and when I do the lsof you provided I always have 6 occurrences of the /tmp/kml-bkny.log file but maybe the 45 is another number. – euri10 Apr 24 '20 at 07:29
  • Dear @euri10 - Thank you for the thoughts. I'm counting file handles using lsof: "lsof | grep kml-bkny.log | wc -l" This gives a quick count, which I loop to get a running count over time. "lsof | grep kml-bkny.log" This allows me to deep dive into the results and ensure the involved pids track back to my uvicorn process (they do) – CoderOfTheNight Apr 24 '20 at 09:21
  • Dear @euri10 - With regards to how quickly the number goes up, you'll see the test client continuously throws 10 simple GET requests with a second gap. Under this scenario, it goes to 45 open log files in about 10 seconds. But you raise a good point, i'll do a matrix of tests with longer gaps, more/less groups of get requests, and most importantly, see if there is runoff *after* I stop the inbound requests. – CoderOfTheNight Apr 24 '20 at 09:24
  • 1
    ok, would you test if this reproduces on uvicorn's master please ? I cant reproduce it on master, didnt test on 0.11.3, that's the only diff I see and recently changes were added to logging that maybe solved it. I see a stable 6 handles from the lsof – euri10 Apr 24 '20 at 13:18
  • 1
    How many distinct pids do you see for `uvicorn` in the `lsof` output? – Vinay Sajip Oct 07 '21 at 05:58

0 Answers0