记一次Bug修复流程：Tornado异步处理

问题描述

我们基于tornado搭建了一个Web服务，部署了多台服务器，经由nginx转发请求，近期频繁收到nginx的499日志报警。

BUG修复流程

nginx 499状态码

nginx的499代码是指客户端调用服务端的服务， 但是服务端未能在限制的时间段内给出回应，于是客户端主动断开请求，nginx打印499日志。

增加服务部署

了解了499的问题之后，并确认nginx的配置没有问题，考虑到是我们的服务无法支撑客户端的并发请求，于是我们增加了服务器的部署，nginx的499问题有所缓解但是还是会时不时的出现。

该业务目前只是在简单维护加上手头上有其他优先级更高的项目需要开发，为此499问题暂时缓解后就没再继续深入下去，毕竟该业务每天200W的访问量大概2000多个499问题，服务的可用性应该可以了。

从差不多到4个9

4个9也就是99.99%即一个服务的可用性达到99.99%。我负责的这个服务明显还没有达到，不过这个服务已经有1年多没有更新部署了，99.8%的可用性业务方能接受。

我也说不清楚是什么促使自己再次去查看这个问题，可能是每天的告警邮件让人心里不舒服，也可能是这个周恰好可以抽出点时间，又或者是4个9的这个可用性。

问题重现

拾起了这个很久没有更新的项目，里面的代码已经很生疏了，我在开发环境进行了服务部署，开始再次查找问题。

首先从压力测试开始，使用的是siege这个压测工具

用100个并发进行压力测试1个小时，查看qps是250左右，平均响应时长是500MS，最长响应时长是2S。

按照这个数值计算单机服务可以处理3600*250个请求，我部署了3台服务器接口每天请求200W，应该完全可以处理的过来（业务方的并发量小于100），不过最大响应时间2S这个不就是超时499的情况吗？（业务方超时限制800MS）。

是不是压力测试的样本中有某些样本特别耗时呢？

样例测试

打开info日志，tornado框架内web.py会对每个请求打印一条耗时日志，我也在主处理函数进行耗时统计。

再次压力测试，siege显示存在1S以上的情况，查看服务日志却没有发现超过1S的请求日志。从siege的响应中找到1S的哪些样例单独去测试，耗时并没有超过1S，那时间耗在哪里了呢？

tornado.web.py耗时

查看日志记录是web.py的第1971行打出的

# web.py
def log_request(self, handler):
	"""Writes a completed HTTP request to the logs.

	By default writes to the python root logger.  To change
	this behavior either subclass Application and override this method,
	or pass a function in the application settings dictionary as
	``log_function``.
	"""
	if "log_function" in self.settings:
		self.settings["log_function"](handler)
		return
	if handler