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
 */
@BTrace
public 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 one
			this.locked = false;
			this.notify();
		}
	}