dubbo框架中一行日志代码引发的超时问题

前一段时间有测试反馈，我负责的一个dubbo接口调用超时，而是是稳定必现的超时。拿到问题之后第一件事当然是分析代码所有可能性能瓶颈的地方，然后并没有收获，我们的接口超时时间设置的是5s，然后单测我们的接口时间只有几十ms。相同的数据，测试怎么会出现这么大的差异呢。难道是dubbo接口的配置问题？找我们的dubbo老司机检查了一遍并没有检查出配置问题，而且工程日志也出现任何可疑的错误信息。而且换了几个账号测试发现有的账号超时，有的账号不超时，这时初步怀疑是数据问题了，然后排查许久并没有发现。

在一筹莫展之际，老司机向我介绍了一个申请，可疑在telnet控制台连接dubbo服务，再通过invoke命令手动调用dubbo服务，看能不能有些发现。telnet ip port，这样就使用telnet协议连接到dubbo服务了，这个ip是部署dubbo服务的服务器ip，端口默认情况下是从20880开始，依次递增，挨个连接然后用ls命令查看你的dubbo服务是否在那个端口上。然后执行invoke invoke com.xxx.xxx.DubboService.dubboMethod(“param1”,param2,param3)执行该dubbo接口，惊奇的发现了异常信息：

Failed to invoke method getWaitCommentOrderItemList, cause: java.util.ConcurrentModificationException
java.util.ConcurrentModificationException
at java.util.ArrayList$SubList.checkForComodification(ArrayList.java:1169)
at java.util.ArrayList$SubList.listIterator(ArrayList.java:1049)
at java.util.AbstractList.listIterator(AbstractList.java:299)
at java.util.ArrayList$SubList.iterator(ArrayList.java:1045)
at com.alibaba.dubbo.common.json.GenericJSONConverter.writeValue(GenericJSONConverter.java:98)
at com.alibaba.dubbo.common.json.GenericJSONConverter.writeValue(GenericJSONConverter.java:91)
at com.alibaba.dubbo.common.json.GenericJSONConverter.writeValue(GenericJSONConverter.java:129)
at com.alibaba.dubbo.common.json.JSON.json(JSON.java:143)
at com.alibaba.dubbo.common.json.JSON.json(JSON.java:94)
at com.alibaba.dubbo.common.json.JSON.json(JSON.java:86)
at com.alibaba.dubbo.common.json.JSON.json(JSON.java:71)
at com.alibaba.dubbo.rpc.protocol.dubbo.telnet.InvokeTelnetHandler.telnet(InvokeTelnetHandler.java:100)
at com.alibaba.dubbo.remoting.telnet.support.TelnetHandlerAdapter.telnet(TelnetHandlerAdapter.java:54)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:183)
at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52)
at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

通过日志发现接口调用时再序列化调用结果到消费端时抛出了一个ConcurrentModificationException，我们这是一个订单查询服务，经过查到代码发现：在从DB中查找出符合条件的订单后，在内存中对结果进行分页，对list做了一次SubList，而在这之后有对大list做了一次过滤操作，导致了list和Sublist的modCount不一致了，而TelnetHandler使用的是json协议，在对list进行json序列化的时候会进行遍历，从而报出了ConcurrentModificationException异常。 同理正常接口调用使用的hessian协议在序列化时也会遍历迭代器出现相同的问题，具体可以参考框架中com.alibaba.com.caucho.hessian.io.IteratorSerializer类的代码。

但是为什么这个异常会导致接口超时，出现异常了不是应该直接把异常信息返回给消费端么，经过查看dubbo框架的源码发现了问题所在，问题出现下面这段代码：

com.alibaba.dubbo.remoting.exchange.codec.ExchangeCodec.encodeResponse(Channel, ChannelBuffer, Response)



是因为红圈圈中的这行日志代码导致的，当服务出现异常时，正常情况下会把错误信息写回给客户端，但是由于那行日志代码，把要打印Response对象，这回导致调用Response对象的toString()方法，而Response的toString()，会调用mResult.toString()，mResult是一个出现并发异常的List，toString()方法会触发它的迭代器，导致又一次出现了ConcurrentModificationException，后面那行channel.send代码就执行不到了，所以响应没有返回给客户端，所以客户端等待超时了。那为啥有的账号没问题有的账号有问题呢，因为有些账号没有订单，没有订单时序列化自然不会出现问题，只有有订单的账号序列化才会报错。