jradius session lock引起的性能下降问题排查

session lock影响性能

问题描述：

在我们使用jradius时，发现线上请求大于10 req/s时，jradius出现性能极差，部分请求响应大概要5s甚至更长才能响应出去。

分析过程：

1.响应慢，我通过btrace分析几个时间关键点，发现我们自定义的auth handler响应基本能在20ms左右响应，但是整个处理结束需要5s，大部分出问题都是这种场景；

btrace脚本如下：

package com.madding.shared.btrace;import com.sun.btrace.BTraceUtils;import com.sun.btrace.annotations.BTrace;import com.sun.btrace.annotations.Kind;import com.sun.btrace.annotations.Location;import com.sun.btrace.annotations.OnMethod;import com.sun.btrace.annotations.TLS;/** * 类MethodTimeUsage.java的实现描述： * 追踪运行时某个方法具体消耗的时间 *  * @author madding.lip May 16, 2012 9:31:22 AM */@BTracepublic class TraceMethodTimeSpend {    public final static String className = "com.***********.handler.NewNACHandler";    public final static String classMethod = "handle";    public final static String frp = "net.jradius.freeradius.FreeRadiusProcessor";    public final static String pr = "processRequest";        @TLS    static long beginTime;    @TLS    static long frp_pr_time;        @OnMethod(clazz = className, method = classMethod)    public static void beginTrace() {        beginTime = BTraceUtils.timeMillis();    }    @OnMethod(clazz = className, method = classMethod, location = @Location(Kind.RETURN))    public static void endTrace() {        BTraceUtils.println(            BTraceUtils.strcat(                BTraceUtils.strcat(                  BTraceUtils.strcat(className , BTraceUtils.strcat(".", BTraceUtils.strcat(classMethod ,": "))),                    BTraceUtils.str(BTraceUtils.timeMillis() - beginTime)),                        "ms"));    }    @OnMethod(clazz = frp, method = pr)    public static void beginTrace_frp_pr() {        frp_pr_time = BTraceUtils.timeMillis();    }    @OnMethod(clazz = frp, method = pr, location = @Location(Kind.RETURN))    public static void endTrace_frp_pr() {        BTraceUtils.println(            BTraceUtils.strcat(                BTraceUtils.strcat(                  BTraceUtils.strcat(frp , BTraceUtils.strcat(".", BTraceUtils.strcat(pr ,": "))),                    BTraceUtils.str(BTraceUtils.timeMillis() - frp_pr_time)),                        "ms"));    }}

2.并发越高，这种问题出现概率越高；

分析代码，发现每个请求过来都，都要过下FreeRadiusProcessor.processRequest方法，代码如下：

    protected void processRequest(ListenerRequest listenerRequest) throws Exception    {        FreeRadiusRequest request = (FreeRadiusRequest) listenerRequest.getRequestEvent();        try        {         try        {            request.setApplicationContext(getApplicationContext());            request.setReturnValue(runPacketHandlers(request));        }        catch (Throwable th)        {            request.setReturnValue(JRadiusServer.RLM_MODULE_FAIL);            RadiusLog.error(">>> processRequest(): Error during processing RunPacketHandlers block", th);        }

该行代码：

request.setReturnValue(runPacketHandlers(request));

会调用

protected int runPacketHandlers(JRadiusRequest request)

作

sessionManager.lock(session);

 while() { handle() }

sessionManager.unlock(session, true);

看到这里，怀疑点出来了，分析sessionManager.lock,unlock实现，其代码调用RadiusSession lock，unlock，导致并发时都会所session对象，并且代码实现比较差；

分析代码后，发现lock本身对代码没扫描影响，因此mock了一个sessionManager，空实现了其lock unlock代码；

问题就不再出现，最后欣赏下RadiusSession 的lock，unlock代码：

public void lock(){synchronized (this){//check whether we are locked, if so... enter wait()while (this.locked){try{this.wait();}catch (InterruptedException e){Thread.yield();}}this.locked = true;}}public void unlock(){synchronized (this){//set unlocked, notify onethis.locked = false;this.notify();}}