因此,运行后一段时间,接收到了超时异常:
Traceback (most recent call last): File "test_asynchttpclient.py", line 72, inIOLoop.current().run_sync(run) File "/usr/local/lib/python2.7/dist-packages/tornado/ioloop.py", line 458, in run_sync return future_cell[0].result() File "/usr/local/lib/python2.7/dist-packages/tornado/concurrent.py", line 238, in result raise_exc_info(self._exc_info) File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 1063, in run yielded = self.gen.throw(*exc_info) File "test_asynchttpclient.py", line 67, in run yield [aync_post(payload) for payload in payload_ls] File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 1055, in run value = future.result() File "/usr/local/lib/python2.7/dist-packages/tornado/concurrent.py", line 238, in result raise_exc_info(self._exc_info) File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 828, in callback result_list.append(f.result()) File "/usr/local/lib/python2.7/dist-packages/tornado/concurrent.py", line 238, in result raise_exc_info(self._exc_info) File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 1063, in run yielded = self.gen.throw(*exc_info) File "test_asynchttpclient.py", line 58, in aync_post body=payload File "/usr/local/lib/python2.7/dist-packages/tornado/gen.py", line 1055, in run value = future.result() File "/usr/local/lib/python2.7/dist-packages/tornado/concurrent.py", line 238, in result raise_exc_info(self._exc_info) File "", line 3, in raise_exc_info
tornado.httpclient.HTTPError: HTTP 599: Timeout during request
这个问题让我疑惑的地方是,我没有设置超时,为什么会抛出超时异常?是否有默认的超时设置,设置在哪里?
3.问题分析
因为我是并发测试了100条请求,所以异常信息就很乱,所以首先,我要做的就是
简化得到的信息
,我把请求改为1条,这时异常信息就很清晰了。
接着,在tornado的
源码中,搜索异常的提示
“HTTP 599: Timeout during request”,但是搜索不到。
还是从
异常提示信息入手,在异常的函数堆栈中
,提示错在:run_sync这个函数,因此进入源码查看函数定义:
def run_sync(self, func, timeout=None):
The keyword-only argument ``timeout`` may be used to set a maximum duration for the function. If the timeout expires,a `TimeoutError` is raised.
我猜测可能跟这个timeout参数有关,可能会有默认的值,
一开始我们还是尽量不要深入源码,
所以我就尝试传一个timeout值为10进去(因为之前发现是大概15秒以上才抛异常)。运行后,结果是这样:
Traceback (most recent call last): File "test_asynchttpclient.py", line 72, inIOLoop.current().run_sync(run,10)
File "/usr/local/lib/python2.7/dist-packages/tornado/ioloop.py", line 457, in run_sync
raise TimeoutError('Operation timed out after %s seconds' % timeout)
tornado.ioloop.TimeoutError: Operation timed out after 10 seconds
这时,我们发现,异常不一样!于是我试着尝试了20秒和30秒,发现20秒和30秒都是提示之前的异常。所以我想看看超时的秒数是多少,加入了打印时间。
begin 2017-07-31 10:34:25.092218
end 2017-07-31 10:34:45.111876
begin 2017-07-31 10:36:19.603607
end 2017-07-31 10:36:39.627447
相同的时间!好像每次超时都是20秒,查问题最重要的就是
关注这些规律性的东西
。因此我又实验了几次,最终的结论就是:超时就是20秒!
然后我就用20和2000(代码一般都是毫秒)去搜索源码,也没有什么发现。
没头绪的时候,就又回去看异常提示信息,异常信息和函数堆栈是查问题最重要的信息
。
tornado.httpclient.HTTPError: HTTP 599: Timeout during request
我们看到“httpclient.HTTPError”,httpclient应该是tornado的一个文件,于是我们搜索这个文件,找到了并且找到了HTTPError这个类:
classHTTPError(Exception):
"""Exception thrown for an unsuccessful HTTP request.
Attributes:
* ``code`` - HTTP error integer error code, e.g. 404.
Error code 599 is
used when no HTTP response was received, e.g. for a timeout
.
* ``response`` - `HTTPResponse` object, if any.
Note that if ``follow_redirects`` is False, redirects become HTTPErrors,
and you can look at ``error.response.headers['Location']`` to see the
destination of the redirect.
哈哈,里面提到了599错误,这不就是异常信息里面提到的599错误吗!因此,我们以关键字“HTTPError”搜索,查找传递599作为参数的调用的地方,最后发现只有两个地方是有可能:
_HTTPConnection::_on_connect
上图的代码逻辑就是:如果_HTTPConnection::request有request_timeout值,就给设置一个超时异常,所以接下来我们要看是这个request_timeout是什么。
查看AsyncHTTPClient::fetch的源码以及根据之前文章对
AsyncHTTPClient
的分析,我们知道在AsyncHTTPClient::fetch的时候,会构造request对象:
request=HTTPRequest(url=request,**kwargs)
self.defaults=dict(HTTPRequest._DEFAULTS)
request=_RequestProxy(request,self.defaults)
而这个request对象就刚好赋值给_HTTPConnection::request,因此我们去看HTTPRequest类:
哈哈,终于找到了,结合上面得出的20秒超时,我们可以确定,这个超时就是在这个位置设置的。
4.结论
AsyncHTTPClient::fetch会通过HTTPRequest类构造请求对象,并且使用HTTPRequest的一些默认的限制值,里面包括了:
connect_timeout=20.0,
request_timeout=20.0,
follow_redirects=True,
max_redirects=5,
。。。。。。
因此,即使我们调用run_sync没有设置timeout,都是AsyncHTTPClient::fetch构造的一些工具对象还是有默认的超时参数。
tip: 不知道有没有发现,超时20秒这个规律,对后面的分析起到了很重要的作用,这可能就是体现在了为什么查问题有先慢的区别上了。
最后编辑于:2017-12-09 14:46