tornado记录请求处理时间

class TestHandler(tornado.web.RequestHandler):
    @tornado.web.asynchronous
    @tornado.gen.engine
    def get(self):
        try:
            logger.error('query[%s] time[%s]'%(str_req, self.request.request_time()))
        except:
            logger.error('error [%s][%s]'% (self.request.uri, traceback.format_exc()))
            self.write('')
        finally:
            try:
                self.finish()
            except:
                pass

          如上代码，其中self.request.request_time()，记录的时间是请求开始处理到现在的时间，而并到达时间到发送时间。因此在并发量过大时，调用接口的代码可能发生超时，而此时间打印出来的时间却不存在超时，因为它不包括在epoll事件队列中的等待时间。

         下面为request_time()函数原型。

 

class HTTPRequest(object):
       def __init__(self, method, uri, version="HTTP/1.0", headers=None,
                 body=None, remote_ip=None, protocol=None, host=None,
                 files=None, connection=None):
        ...
        self._start_time = time.time()
        self._finish_time = None
        ...
       

    def request_time(self):
        """Returns the amount of time it took for this request to execute."""
        if self._finish_time is None:
            return time.time() - self._start_time
        else:
            return self._finish_time - self._start_time

 

           其中 self._start_time 是在HTTPRequest初始化是被赋值。而初始化的位置就在开始处理数据包的时刻，代码位于HTTPConnection类的解析请求头部函数_on_headers中。

   

//HttpServer.py
class HTTPConnection(object):

    def _on_headers(self, data):
        try:
           ...

            self._request = HTTPRequest(
                connection=self, method=method, uri=uri, version=version,
                headers=headers, remote_ip=remote_ip)

            ...
        except _BadRequestException, e:
            logging.info("Malformed HTTP request from %s: %s",
                         self.address[0], e)
            self.close()
            return