学步园

最近写了个java的服务器程序（基于Mina）在linux上运行，测试性能的时候发现任何一个request发送出去总是会有40ms的延迟再接受到response。一开始以为是逻辑处理和算法的问题，优化了半天，发现延迟依然如故，即便最简单的request也还需要40ms的延迟。而且，相同的一段程序，在我的windows笔记本上运行，就不存在这个40ms的延迟。

之所以文章题目取名“灵异”，是因为我现在也只是找到了一个解决方案，但仍然不清楚问题出在什么地方...

为了解释得更清楚，简化了服务器的代码，直接采用Mina example中的TimeServer。并且为了排除网络因素，将server和client部署在同一个机器上。

Server代码：

public static void main(String[] args) throws IOException {<br /> // Create the acceptor<br /> IoAcceptor acceptor = new NioSocketAcceptor();</p> <p> // Add two filters : a logger and a codec<br /> acceptor.getFilterChain().addLast( "logger", new LoggingFilter() );<br /> acceptor.getFilterChain().addLast( "codec", new ProtocolCodecFilter( new TextLineCodecFactory( Charset.forName( "UTF-8" ))));</p> <p> // Attach the business logic to the server<br /> acceptor.setHandler( new TimeServerHandler() );<br /> // Configurate the buffer size and the iddle time<br /> acceptor.getSessionConfig().setReadBufferSize( 2048 );<br /> acceptor.getSessionConfig().setIdleTime( IdleStatus.BOTH_IDLE, 10 );</p> <p> // And bind !<br /> acceptor.bind( new InetSocketAddress(PORT) );<br /> }

//TimeServerHandler.java<br /> @Override<br /> public void messageReceived( IoSession session, Object message ) throws Exception<br /> {<br /> logger.debug("message received");</p> <p> String str = message.toString();</p> <p> if( str.trim().equalsIgnoreCase("quit") ) {<br /> // "Quit" ? let's get out ...<br /> session.close(true);<br /> return;<br /> }<br /> // Send the current date back to the client<br /> Date date = new Date();<br /> session.write( date.toString() );<br /> System.out.println("Message written...");<br /> }

这段代码构造了一个简单的Server，接收带有"/r/n"后缀的request，然后获取服务器的时间，将时间以字符串的形式发送回去。

客户端发送程序如下：

String idstr = Integer.toString(id);<br /> sendMessageWithDelimiter(sock, idstr);</p> <p> String response = recvMessageWithDelimiter(sock);

private static byte[] delimiter = {'/r','/n'};</p> <p> public static void sendMessageWithDelimiter(Socket sock, String message) throws Exception {<br /> OutputStream output = sock.getOutputStream();</p> <p> output.write(message.getBytes());<br /> output.write(delimiter);<br /> }

这里的变量id就是一个int型，需要将id转换成string类型再进行发送。

所以，其实就是发送一个带有“/r/n”后缀的字符串。

就是这样一个简单的request/response交互程序，每个消息的延迟都需要40ms。

于是将mina的logger打开，发现类似这样的log：

 INFO 2011-01-07 11:32:08,402
[NioProcessor-2] (LoggingFilter.java:141) - RECEIVED: HeapBuffer[pos=0 lim=1 cap=1024: 33]

DEBUG 2011-01-07 11:32:08,402
[NioProcessor-2] (ProtocolCodecFilter.java:220) - Processing a MESSAGE_RECEIVED for session 1
 INFO 2011-01-07 11:32:08,447
[NioProcessor-2] (LoggingFilter.java:141) - RECEIVED: HeapBuffer[pos=0 lim=2 cap=1024: 0D 0A]

DEBUG 2011-01-07 11:32:08,447 [NioProcessor-2] (ProtocolCodecFilter.java:220) - Processing a MESSAGE_RECEIVED for session 1
DEBUG 2011-01-07 11:32:08,449 [NioProcessor-2] (TimeServerHandler.java:56) - message received
Message written...
 INFO 2011-01-07 11:32:08,449 [NioProcessor-2] (LoggingFilter.java:141) - SENT: HeapBuffer[pos=0 lim=0 cap=0: empty]
DEBUG 2011-01-07 11:32:08,450 [NioProcessor-2] (TimeServerHandler.java:74) - message sent

log的第一行表示，mina在402ms的时候接收到了一个byte的数据，这个byte的值是33，正好是id被转换成String后的值。

log的第三行表示，mina在447ms的时候接收到了两个byte的数据，分别是0D和0A，正好对应于"/r/n"。

而这两次接收数据之间相差了447 - 402 = 45 ms。

几乎等于每次交互的延迟。

所以，我至少发现了，40ms这么多的时间都消耗在哪了。

但是，不明白的是，在客户端，两次output.write操作是按顺序立即执行的，可服务器端显示，它接收这两个数据之间有40+ms的空隙。

于是再次修改了客户端代码，如下：

private static byte[] delimiter = {'/r','/n'};</p> <p> public static void sendMessageWithDelimiter(Socket sock, String message) throws Exception {<br /> BufferedOutputStream output = new BufferedOutputStream(sock.getOutputStream());</p> <p> output.write(message.getBytes());<br /> output.write(delimiter);<br /> output.flush();<br /> }

我用BufferedOutputStream发送数据，意味着，只有当output.flush()被调用的时候，write这个操作才真正的执行。

采用新的客户端之后，服务器端的log如下：

 INFO 2011-01-07 12:01:29,438 [NioProcessor-2] (LoggingFilter.java:141) - RECEIVED: HeapBuffer[pos=0 lim=3 cap=1024: 33 0D 0A]
DEBUG 2011-01-07 12:01:29,439 [NioProcessor-2] (ProtocolCodecFilter.java:220) - Processing a MESSAGE_RECEIVED for session 1
DEBUG 2011-01-07 12:01:29,439 [NioProcessor-2] (TimeServerHandler.java:56) - message received
Message written...
 INFO 2011-01-07 12:01:29,439 [NioProcessor-2] (LoggingFilter.java:141) - SENT: HeapBuffer[pos=0 lim=0 cap=0: empty]
DEBUG 2011-01-07 12:01:29,441 [NioProcessor-2] (TimeServerHandler.java:74) - message sent

可以看出，40+ms的延迟已经没有了。

并且，mina能够一次就将客户端发送的request完整的读到。

另外，需要指出的是，即便在旧的客户端程序的末尾添加"output.flush"，40ms的延迟依然存在。

所以，目前为止，我所知道的是，采用新的客户端代码可以解决40ms延迟这个问题。得到的教训是，以后写socket，尽量将一条消息一次性的写入，而不要分几次写操作。

但是，40ms延迟的由来凭借上面的实验仍然看不清楚。特别是，之前提到过，旧的代码如果在windows上运行一点问题没有。这里只提供两个猜测：

猜测一：

客户端的原因。众所周知，当对socket调用write操作时，如果返回成功只是意味着将用户内存中的数据写入到了网卡的缓冲区中，并不意味着数据已经发送了。所以，虽然客户端是连着调用了两个write操作，但这只意味着数据都被放入了网卡的缓冲区。而网卡在发送这两个数据之间有可能产生一个40ms的间隙。

猜测二：

Mina底层采用的是Nio Selector这种IO多路复用的机制。一旦某个socket有数据就会产生一个read_event。那么，一个可能的原因是客户端的两个write操作，数据到达服务器端时虽然是紧挨着，但mina产生了两个read_event，又因为某种原因，导致这两个read_event之间出现了40ms的延迟...（这猜测我自己都有些听不下去了）

总之，原因依旧不明。如果有高人愿意指点一下就最好了。