jetty链接超时过期
Jetty误判长连接为超时连接的问题
在上一篇中介绍了jetty的反映器模型,selector线程与业务子线程交互的点有:
1、分发事件给子线程做,启动子线程;
2、子线程发现阻塞或者连接关闭等时间时,注册内部changes,等待selector线程调度;
3、检测超时连接,并且关闭连接。
在检测超时连接上面,jetty存在较多的问题,可能会误判。下面是一个典型的问题,问题一步一步定位的过程也是非常艰难和曲折的,但是最终问题找到的时候却发现不过如此。
具体的问题出在下面这个判断表达式上面,下面这个方法是由主线程派生一个子线程的来调用的,在这个线程里面对所有的连接进行超时检查。
// Idle tick if (now-_idleTick>__IDLE_TICK) { _idleTick=now; final long idle_now=((_lowResourcesConnections>0 && selector.keys().size()>_lowResourcesConnections)) ?(now+_maxIdleTime-_lowResourcesMaxIdleTime) :now; dispatch(new Runnable() { public void run() { for (SelectChannelEndPoint endp:_endPoints.keySet()) { endp.checkIdleTimestamp(idle_now); } } }); }
被调用的方法:
/* ------------------------------------------------------------ */ public void checkIdleTimestamp(long now) { if (_idleTimestamp!=0 && _maxIdleTime!=0 && now>(_idleTimestamp+_maxIdleTime)) { idleExpired(); } }
_idleTimestamp是每个连接实例中标志连接上次空闲的开始时间,如果该值为0,则说明连接处于非空闲,当子线程在处理请求时会频繁地将该变量在0值与空闲的时间点之间切换,而该变量本身是寄存器变量,可以保证变量本身在多线程之间的同步。但是上面是一个表达式,假如运行的时序是下面这样的:
1、子线程刚刚将连接置为空闲,那么_idleTimestamp大于0;
2、主线程开始判断该连接是否超时,判断到_idleTimestamp>0满足;
3、当程序继续运行时,子线程又将_idleTimestamp切换为0;
4、主线程开始判断now>(_idleTimestamp+_maxIdleTime)的条件,发现也满足;
5、最终,所有判断条件均为真,进入关闭连接的流程,连接被关闭。
这样就形成一个误判。本来连接上的请求正在处理,却被提前关闭了,最终会导致某一个请求处理失败,并且是莫名其妙的失败,网络抓包能发现是服务端关闭了连接,但是到底是谁关闭了连接都很难知道,最终通过在关闭socket的地方记录堆栈,待到堆栈累计到一定程度时,将其打印到日志中,结合抓包数据就能发现问题所在。
问题明确了,修改方法也简单:
/* ------------------------------------------------------------ */ public void checkIdleTimestamp(long now) { long idleTimestamp = _idleTimestamp; if (idleTimestamp!=0 && _maxIdleTime!=0 && now>(idleTimestamp+_maxIdleTime)) { idleExpired(); } }
这样就避免了在计算表达试的过程中全局变量的值被改变了。问题解决。
这个问题解决之后,紧随其后,又发现了另外一个更加奇怪的现象:
发现在连接启动之后,业务已经在处理中,最终业务处理完成,但是对外回复响应时却发现连接已经被关闭了。这个问题与上面的问题很像,但是不是同一个问题。经过上面的分析定位,对这里已经有一定的积累,很快就找到了连接关闭的根源,还是在检查超时连接上面。
经过反复推敲,发现问题出在下面3个函数的配合上面,当一个连接上面接近200秒(连接最大超时时间)都没有任何请求,而此时一个新的请求已经启动,但是还没有来得及调用cancelIdle来置空闲标志为0,这时请求已经开始处理,就在这个时候,主线程开始检查连接是否超时,结果发现已经超过200秒,连接上面没有处理任何数据,走入关闭连接的流程。
而此时业务线程已经在处理数据,等待数据处理完成,需要回复响应的时候才发现此连接已经断开了。这样客户端无法收到任何讯息。服务端记录该请求失败,但实际上请求已经处理成功。
/* ------------------------------------------------------------ */ public void scheduleIdle() { _idleTimestamp=System.currentTimeMillis(); } /* ------------------------------------------------------------ */ public void cancelIdle() { _idleTimestamp=0; } /* ------------------------------------------------------------ */ public void checkIdleTimestamp(long now) { long idleTimestamp = _idleTimestamp; if (idleTimestamp!=0 && _maxIdleTime!=0 && now>(idleTimestamp+_maxIdleTime)) { idleExpired(); } }
这个问题的修改方法稍微复杂一点:
/* ------------------------------------------------------------ */ public void scheduleIdle() throws IOException { synchronized (idleClosing) { if (idleClosing.get()) { throw new IOException("the connection was closed right now. this request will be responsed a wrong value."); } else { _idleTimestamp=System.currentTimeMillis(); } } } /* ------------------------------------------------------------ */ public void cancelIdle() { _idleTimestamp=0; } /* ------------------------------------------------------------ */ public void checkIdleTimestamp(long now) { long idleTimestamp = _idleTimestamp; if (idleTimestamp!=0 && _maxIdleTime!=0 && now>(idleTimestamp+_maxIdleTime)) { synchronized (idleClosing ) { if (_idleTimestamp == 0) { Log.warn("the request is doing. it cannot be closed!"); return; } else { idleClosing.set(true); } } idleExpired(); } }
已有 0 人发表留言,猛击->> 这里<<-参与讨论
ITeye推荐