Search code examples
flaskiiswfastcgi

Long time to first byte for my Flask app homepage

I have a Flask site deployed to IIS via wfastcgi configuration.

When I use chrome or firefox developer tools to analyse the loading time of the homepage, I find many seconds (ranging from 6 to 10 in average) as waiting time to receive the first byte.

It was even 30 seconds before, but then I "optimized" my python code to avoid any db sql operation at loading time. Then I've followed the hints of this blog of nspointers, and now from the taskbar of the server I see the w3wp.exe for my app pool identity

w3wp.exe – It is the IIS worker process for the application pool

staying up and running even during idle time. But that is not true for the other

python.exe – The main FastCGI process for the Django or flask applications.

and I'm not sure if this is a problem and just in case what I am supposed to do, aside from the step 4 described in the mentioned post.

Now in the “Edit FastCGI Application” dialog under “Process Model” edit the “Idle Timeout” and set it to 2592000 which is the max value for that field in seconds

I've also looked at the log written by the Flask app and compared it to the log written by IIS and this is the most important point in making me believe that the issue is in the wfastcgi part, before the execution of the python code.

Because I see that the time-taken of the IIS log matches with the client time reported by chrome or firefox as TTFB and the log written by python at the start of the execution is logged at almost the same time of the time written by IIS, that

corresponds to the time that the request finished

(as I thought indeed and as I find it's confirmed by this answer)

So in conclusion, based on what I tried and what I understand, I suspect that IIS is "wasting" many seconds to "prepare" the python wfascgi command, before actually starting to execute my app code to produce a response for the web request. It is really too much in my opinion, since other applications I've developed (for example in F# WebSharper) under IIS without this mechanism of wfastcgi load immediately in the browser and the difference in the response time between them and the python Flask app is quite noticeable. Is there anything else I can do to improve the response time?

Solution

  • Ok, now I have the proof I was searching and I know where the server is actually spending the time. So I've researched a bit about the wfastcgi and finally opened the script itself under venv\Lib\site-packages.

    Skimming over the 900 lines, you can spot the relevant log part:

    def log(txt):
    """Logs messages to a log file if WSGI_LOG env var is defined."""
    if APPINSIGHT_CLIENT:
        try:
            APPINSIGHT_CLIENT.track_event(txt)
        except:
            pass
    
    log_file = os.environ.get('WSGI_LOG')
    if log_file:
        with open(log_file, 'a+', encoding='utf-8') as f:
            txt = txt.replace('\r\n', '\n')
            f.write('%s: %s%s' % (datetime.datetime.now(), txt, '' if txt.endswith('\n') else '\n'))

    Now, well knowing how to set the environment variables, I defined a specific WSGI_LOG path, and here we go, now I see those 5 seconds TTFB from chrome (as well as the same 5 seconds from IIS log with time 11:23:26 and time-taken 5312) in the wfastcgi.py log.

    2021-02-01 12:23:21.452634: wfastcgi.py 3.0.0 initializing
2021-02-01 12:23:26.624620: wfastcgi.py 3.0.0 started

    So, of course, wfastcgi.py is the script one would possibly try to optimize...

    BTW, after digging into it, that time is due to importing the main flask app

    handler = __import__(module_name, fromlist=[name_list[0][0]])

    What remains to be verified is the behavior of rerunning the process (and the import of the main flask module, that is time consuming) for each request.

    In conclusion, I guess it is a BUG, but I have solved it by deleting the "monitoring changes to file" FastCGI settings as per the screenshot below.

    enter image description here

    The response time is under a second.