Expose HTTP request handling time

Until recently, I had my Tornado applications using HTTPServerRequest::request_time to report request handling latencies. While conducting some tests with users in a bandwidth-constrained environment, I noticed that our request timings were downright awful.

I found this surprising, given that nothing significant had changed in the application prior to the test. After some fruitless exploration, a coworker suggested that Tornado might be including the time taken by the client to complete transmission of the request in request_time. Using the server and client scripts below, I verified that this is in fact the case.

import asyncio
import logging
from time import time

from tornado.httpserver import HTTPServer
from tornado.platform.asyncio import AsyncIOMainLoop
from tornado.web import Application
from tornado.web import RequestHandler


logger = logging.getLogger(__name__)


class TestHandler(RequestHandler):

    def post(self):
        logger.info('request received')

    # Lifecycle

    def prepare(self):
        self.start_time = time()

    def on_finish(self):
        tornado_time = self.request.request_time()
        logger.info(f'Tornado says request took {tornado_time} s')

        my_time = time() - self.start_time
        logger.info(f'I say it took {my_time} s')


if __name__ == '__main__':
    logging.basicConfig(level=logging.INFO)
    AsyncIOMainLoop().install()

    app = Application(
        handlers=[('/', TestHandler)],
        autoescape=None,
        debug=True,
    )

    server = HTTPServer(app)
    server.listen(8080)

    loop = asyncio.get_event_loop()
    loop.run_forever()

from time import sleep

import requests


class SlowFile:

    lines = [
        b'Now is the time',
        b'for all good men',
        b'to come to the aid',
        b'of their country',
    ]

    def __iter__(self):
        for l in type(self).lines:
            sleep(2)
            yield l


def main():
    f = SlowFile()
    requests.post('http://localhost:8080', data=f)


if __name__ == '__main__':
    main()

Tornado reports over 8 seconds, when the actual handling latency is well under a second.

I understand the reasons for exposing this cumulative number, but I also imagine that most server app developers are more interested in the number they can affect more directly – the actual handling latency. That is, the delta between when a request is fully received and when the response is fully sent.

It's easy enough to implement this myself in a RequestHandler subclass, but it seems useful enough that maybe Tornado should just expose it.

What do you think @bdarnell?

Start with HTTPServerRequest.request_time and the RequestHandler prepare/on_finish lifecycle shown in the report, then run the supplied server and slow-client scripts to reproduce the timing difference. Done means Tornado exposes handling latency separately from cumulative request_time, with the behavior verified for slow request uploads.