How can I benchmark a tornado handler within the handler?

Question

I have written a very simple tornado handler intended to test the upload speed of some devices that are deployed remotely. The main test is going to be run in said remote devices where (thanks to cURL), I can get a detailed report on the different times the upload took.

The only thing the Tornado handler has to really do is accept a body with a number of bytes (that's pretty much it)

class TestUploadHandler(tornado.web.RequestHandler):
   def post(self):
        logging.debug("Testing upload")
        self.write("")

So, the code above works, but it is kind of... almost shameful :-D To make it a bit more... showable, I'd like to show a few more useful logs, like the time that the request took to upload or something like that. I don't know... Something a bit juicier.

Is there any way of measuring the upload speed within the Tornado handler itself? I've googled how to benchmark Tornado handlers, but all I seem to be able to find are performance comparisons between different web servers.

Thank you in advance.

Are you just trying to measure how long the `post` method takes to complete? — dano, Jul 22 '14 at 02:25
Yeah... Something that doesn't make the handler look so... empty and desolated. Some useful metric would be great (such as how long did the request take for instance would be great) :-) — BorrajaX, Jul 22 '14 at 03:06

dano · Accepted Answer · 2014-07-24T21:03:53.793

Well, it's pretty straightforward to time how long the upload itself took:

import time

class TestUploadHandler(tornado.web.RequestHandler):
   def post(self):
        logging.debug("Testing upload")
        start = time.time()
        self.write({})
        end = time.time()
        print "Time to write was {} seconds.".format(end-start)

You could also move the timing code to a decorator, if you want to use it in more than one handler:

from functools import wrap
import time

def timer(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        start  = time.time()
        ret = func(*args, **kwargs)
        end = time.time()
        print 'Function took {} seconds'.format(end-start)
        return ret 
    return wrapper

class TestUploadHandler(tornado.web.RequestHandler):
   @timer
   def post(self):
        logging.debug("Testing upload")
        self.write({})

Edit:

Given that you're trying to measure how long an upload to the server is taking from the server's perspective, the above approach isn't going to work. It looks like the closest you can get with tornado is to use the @tornado.web.stream_request_body decorator, so that you receive the request body as a stream:

@tornado.web.stream_request_body
class ValueHandler(tornado.web.RequestHandler):
    def initialize(self):
        self.start = None

    def post(self):
        end = time.time()
        print self.request
        if self.start:
            print("Upload time %s" % end-self.start)
        self.write({})

    def data_received(self, data):
        if not self.start:
            self.start = time.time()

When the first chunk of the request body is received, we save the time (as self.start). The post method will be called as soon as the complete body is received, so we get end then.

I had issues getting this to work properly with large file uploads, though. It seems to work ok for smallish files (under 100MB), though.

I'll probably use this. The decorator is a nice addition to the answer. Do you happen to know if there are more *times* reports hidden somewhere in the `handler`, or the `request`, or such? I'm asking because (in the client side) cURL offers a great report (when did the request start, how long did the DNS resolution take, how long did the upload itself take...) I was wondering whether there's something like that in the server side (I have no idea at all) Something like... *when was the handler instantiated* or *how long did it take to process the full upload stream...* Things like that?. Thx — BorrajaX, Jul 24 '14 at 13:50
@BorrajaX `RequestHandler` doesn't have anything like that, as far as I can tell. However, if you send a request using `tornado.httpclient`, the `HTTPResponse` object you get back will have a [`time_info`](http://www.tornadoweb.org/en/stable/httpclient.html?highlight=httprequest#tornado.httpclient.HTTPResponse) property, which is a dict of diagnostic timings, it specifically sites http://curl.haxx.se/libcurl/c/curl_easy_getinfo.html as a reference for the available timings from. — dano, Jul 24 '14 at 14:29
Wait, once the handler is called, isn't all the body in the server already? Doesn't this mean that the differences between `end` and `start` are going to be almost zero? — BorrajaX, Jul 24 '14 at 20:36
@BorrajaX Yes, you're right; I misinterpreted what you were trying to do. I updated my answer to show how you can try to measure the upload time from Tornado's perspective, though I'm not sure how accurate it will be. — dano, Jul 24 '14 at 21:08
upvoted because I was looking for a way to measure how much time the GET/POST request to the server takes to process. — Nikhil VJ, Mar 25 '18 at 08:14

How can I benchmark a tornado handler within the handler?

1 Answers1