When I read tornado source code, I want to log every socket accept time, so I add a log on accept_handler like this:
def accept_handler(fd, events):
for i in xrange(_DEFAULT_BACKLOG):
if removed[0]:
# The socket was probably closed
return
try:
connection, address = sock.accept()
except socket.error as e:
# _ERRNO_WOULDBLOCK indicate we have accepted every
# connection that is available.
if errno_from_exception(e) in _ERRNO_WOULDBLOCK:
return
# ECONNABORTED indicates that there was a connection
# but it was closed while still in the accept queue.
# (observed on FreeBSD).
if errno_from_exception(e) == errno.ECONNABORTED:
continue
raise
set_close_exec(connection.fileno())
gen_log.warning('accept at {}'.format(io_loop.time()))
callback(connection, address)
My handler is a blocking function, it blocks ioloop 3s and return 'hello world'.
Then I send 10 requests simultaneously via thread, I found tornado log is like this:
[W 170916 22:06:01 netutil:278] accept at 1505624761.04
sleep at 1505624761.04
wake at 1505624764.04
[I 170916 22:06:04 web:2063] 200 GET / (192.168.10.243) 3005.47ms
[W 170916 22:06:04 netutil:278] accept at 1505624764.04
sleep at 1505624764.04
wake at 1505624767.05
[I 170916 22:06:07 web:2063] 200 GET / (192.168.10.243) 3005.02ms
[W 170916 22:06:07 netutil:278] accept at 1505624767.05
sleep at 1505624767.05
wake at 1505624770.05
[I 170916 22:11:06 web:2063] 200 GET / (192.168.10.243) 3003.87ms
[W 170916 22:11:06 netutil:278] accept at 1505625066.86
sleep at 1505625066.86
wake at 1505625069.86
[I 170916 22:11:09 web:2063] 200 GET / (192.168.10.243) 3002.22ms
[W 170916 22:11:09 netutil:278] accept at 1505625069.86
sleep at 1505625069.86
wake at 1505625072.87
[I 170916 22:11:12 web:2063] 200 GET / (192.168.10.243) 3004.91ms
[W 170916 22:11:12 netutil:278] accept at 1505625072.87
sleep at 1505625072.87
wake at 1505625075.87
[I 170916 22:11:15 web:2063] 200 GET / (192.168.10.243) 3004.71ms
[W 170916 22:11:15 netutil:278] accept at 1505625075.87
sleep at 1505625075.87
wake at 1505625078.88
[I 170916 22:11:18 web:2063] 200 GET / (192.168.10.243) 3006.12ms
[W 170916 22:11:18 netutil:278] accept at 1505625078.88
sleep at 1505625078.88
wake at 1505625081.89
[I 170916 22:11:21 web:2063] 200 GET / (192.168.10.243) 3006.07ms
[W 170916 22:11:21 netutil:278] accept at 1505625081.89
sleep at 1505625081.89
wake at 1505625084.89
[I 170916 22:11:24 web:2063] 200 GET / (192.168.10.243) 3005.07ms
[W 170916 22:11:24 netutil:278] accept at 1505625084.9
sleep at 1505625084.9
wake at 1505625087.9
[I 170916 22:11:27 web:2063] 200 GET / (192.168.10.243) 3006.34ms
it looks like tornado process requests one by one, but I think that's not true and I use wireshark finding all connections are accepted in a very short time, so I don't know how to adding a log to display every socket accept time.
In Tornado, a blocking handler blocks everything. That includes, in this case, the next call to accept() (the call to callback() at the end of the accept loop will eventually reach the handler). To have any concurrency in Tornado you must make all your handlers non-blocking (on the IOLoop thread. You can use a ThreadPoolExecutor to move work to other threads, and in those threads you can block as much as you want, but you can't call other Tornado methods).