性能文章>【全网首发】记一次SSL握手导致业务线程阻塞的案例分析>

【全网首发】记一次SSL握手导致业务线程阻塞的案例分析原创

468997

问题描述

产品线反馈RocketMQ某Group ID出现消息堆积,重启后正常,一段时间后再次堆积,近期堆积问题出现的频次有些高,希望能够分析解决下。
image.png

分析过程

通过以往消息堆积的案例经验:

● MQ-消息堆积-业务代码异常导致retry队列积压
MQ-消息堆积-业务线程阻塞案例分析
一次RocketMQ ons SDK Bug导致消息不断堆积到重试队列的案例分析
MQ-消息堆积-JDK Bug导致线程阻塞案例分析

相比RocketMQ和JDK bug,应用代码出现问题的概率更高一些,所以优先从业务层面排查:

● 业务代码抛出了异常导致retry队列堆积,通过【详细信息】没有发现消费失败的情况,所以排除这种情况;
● 业务线程消费慢?或者是卡死了?

线程阻塞?

根据以往经验的总结,分析线程阻塞通常有如下几种思路:

● 根据线程CPU使用率(线程阻塞的情况下,CPU使用率通常很低)

● 通过对RocketMQ Listener执行耗时进行监控:一种检测线程阻塞的实现思路

● 通过对线程池线程执行时间进行监控(不做详细描述)
监控runWorker的退出时间
监控beforeExecute(wt, task)开始执行时间
监控afterExecute(task, thrown)开始执行时间

● 卡死线程的线程栈是不变得,可以通过不断查看线程栈进行分析

在没有任何系统建设的情况下,通过不断查看线程栈是可操作性最高的,下面是堆栈信息:
image.png

将【堆栈信息】中的线程浏览了一下,发现非常多的线程都处于上面线程的状态,相比较线程消费慢,现在更倾向于线程卡死了。
接下来分析上图中tid=354457的线程,为了方便分析线程栈,可以使用arthas thread命令,通过不断执行thread 354457来观察线程栈的变化:
image.png

通过不断执行,线程都保持上图状态,可以确定线程卡死了。
通过以上线程栈可知,业务代码使用apache httpclient框架发起的SSL请求,在SSL握手的时候发生了阻塞,接下来分析具体阻塞在SSL握手的哪个阶段。

SSL握手

在具体分析SSL握手阻塞在哪个阶段之前,我们先了解下SSL握手过程,以便更好理解代码的实现逻辑。

握手概述

image.png
TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256说明

  • TLS 是双方通信的协议;
  • ECDHERSA都是非对称加密算法,用于传递秘钥;ECDHE 是秘钥交换算法,RSA 是签名算法;
  • WITH是连接字符串;
  • AES-128-GCM 是对称加密算法,也就是后面双方交换应用信息时使用的算法;
  • SHA256是消息摘要算法

TLS协议

RSA握手过程

image.png

代码分析

业务代码

根据线程栈,使用arthas jad反编译代码,相关代码整理后如下:
image.png

SSLSocket握手

SSL握手主要流程:创建Socket、socket建立与服务端连接、SSL握手,主要代码整理如下:
image.png
由于【创建Socket】和【socket建立于服务端连接】与问题关联不大,下面主要分析创建SSLSocket和建立SSL握手的过程。

创建SSLSocket

SSLSocketFactoryImpl
public Socket createSocket(Socket s, String host, int port,
                           boolean autoClose) throws IOException {
    return new SSLSocketImpl(context, s, host, port, autoClose);
}
SSLSocketImpl
SSLSocketImpl(SSLContextImpl context, Socket sock, String host,
              int port, boolean autoClose) throws IOException {
    super(sock);
    // We always layer over a connected socket
    if (!sock.isConnected()) {
        throw new SocketException("Underlying socket is not connected");
    }
    this.host = host;
    this.serverNames =
        Utilities.addToSNIServerNameList(this.serverNames, this.host);
    init(context, false);
    this.autoClose = autoClose;
    doneConnect();
}
init
private void init(SSLContextImpl context, boolean isServer) {
    sslContext = context;
    sess = SSLSessionImpl.nullSession;
    handshakeSession = null;

    /*
    * role is as specified, state is START until after
    * the low level connection's established.
    */
    roleIsServer = isServer;
    connectionState = cs_START;
    ... ...

    enabledCipherSuites =
        sslContext.getDefaultCipherSuiteList(roleIsServer);
    enabledProtocols =
        sslContext.getDefaultProtocolList(roleIsServer);
    ... ...
    input = new AppInputStream(this);
    output = new AppOutputStream(this);
}
doneConnect
void doneConnect() throws IOException {
    /*
    * Save the input and output streams.  May be done only after
    * java.net actually connects using the socket "self", else
    * we get some pretty bizarre failure modes.
    */
    sockInput = super.getInputStream();
    sockOutput = super.getOutputStream();
    
    /*
    * Move to handshaking state, with pending session initialized
    * to defaults and the appropriate kind of handshaker set up.
    */
    initHandshaker();
}
private void initHandshaker() {
    ... ...
    // state is either cs_START or cs_DATA
    if (connectionState == cs_START) {
        connectionState = cs_HANDSHAKE;
    } else { // cs_DATA
        connectionState = cs_RENEGOTIATE;
    }
    ......
    handshaker = new ClientHandshaker(this, sslContext,
                                      enabledProtocols,
                                      protocolVersion, connectionState == cs_HANDSHAKE,
                                      secureRenegotiation, clientVerifyData, serverVerifyData);
    handshaker.setSNIServerNames(serverNames);
    handshaker.setEnabledCipherSuites(enabledCipherSuites);
    handshaker.setEnableSessionCreation(enableSessionCreation);
}

startHandshake:建立SSL握手

startHandshake调用performInitialHandshake,主要逻辑如下:

private void performInitialHandshake() throws IOException {
    synchronized (handshakeLock) {
        if (getConnectionState() == cs_HANDSHAKE) {
            kickstartHandshake();
            ... ...
            readRecord(inrec, false);
            inrec = null;
        }
    }
}
kickstartHandshake

发送ClientHello

private synchronized void kickstartHandshake() throws IOException {
    ... ...
    handshaker.activate(null);
    // 发送ClientHello
    handshaker.kickstart();
}
readRecord
private void readRecord(InputRecord r, boolean needAppData)throws IOException {
    int state;
    synchronized (readLock) {
        while (((state = getConnectionState()) != cs_CLOSED) &&
               (state != cs_ERROR) && (state != cs_APP_CLOSED)) {
            try {
                // 读取服务端响应
                r.setAppDataValid(false);
                r.read(sockInput, sockOutput);
            } catch (SSLProtocolException e) {
                ... ...
            } catch (EOFException eof) {
                ... ...
            }
            try {
                //解析响应报文
                r.decrypt(readAuthenticator, readCipher);
            } catch (BadPaddingException e) {
                ... ...
            }

            synchronized (this) {
                switch (r.contentType()) {
                    case Record.ct_handshake:
                        ... ...
                        handshaker.process_record(r, expectingFinished);
                        expectingFinished = false;

                        if (handshaker.invalidated) {
                            handshaker = null;
                            receivedCCS = false;
                            if (connectionState == cs_RENEGOTIATE) {
                                connectionState = cs_DATA;
                            }
                        } else if (handshaker.isDone()) {
                            secureRenegotiation =
                                handshaker.isSecureRenegotiation();
                            clientVerifyData = handshaker.getClientVerifyData();
                            serverVerifyData = handshaker.getServerVerifyData();

                            sess = handshaker.getSession();
                            handshakeSession = null;
                            handshaker = null;
                            connectionState = cs_DATA;
                            receivedCCS = false;
                            
                            if (handshakeListeners != null) {
                                HandshakeCompletedEvent event =
                                    new HandshakeCompletedEvent(this, sess);

                                Thread t = new NotifyHandshakeThread(
                                    handshakeListeners.entrySet(), event);
                                t.start();
                            }
                        }

                        if (needAppData || connectionState != cs_DATA) {
                            continue;
                        }
                        break;

                    case Record.ct_application_data:
                        ... ...
                        break;

                    case Record.ct_alert:
                        recvAlert(r);
                        continue;

                    case Record.ct_change_cipher_spec:
                        ... ...
                        continue;

                    default:
                        ... ...
                        continue;
                }
                if (connectionState < cs_ERROR) {
                    checkSequenceNumber(readAuthenticator, r.contentType());
                }

                return;
            }
        }
        r.close();
        return;
    }
}

分析结论

通过线程栈及源码分析:SSLSocket已经将ClientHello发送给服务端,当前正阻塞在读取服务端响应,由于设置的socketTimeout没有起作用,在服务端一直没有响应的情况下,线程一直阻塞在读取服务端响应。

结论验证

验证的方式主要想到了以下几种

方式一 问题复现

通过curl模拟请求进行了问题复现

方式二 tcpdump抓包

通过分析tcpdump报文进行验证(未实施)

方式三 打开SSL debug

借助arthas在不重启应用的情况下,动态打开了SSL debug日志,方式如下:

Debug
//将sun.security.ssl.Debug静态属性设置为all
ognl '#cls=@Class@forName("sun.security.ssl.Debug"),#field=#cls.getDeclaredField("args"),#field.setAccessible(true),#field.set(#cls,"all")'
//判断设置是否生效
ognl '@sun.security.ssl.Debug@isOn("handshake")'    
ClientHandshaker
//查看debug属性定义信息
ognl '#cls=@Class@forName("sun.security.ssl.Handshaker"),#field=#cls.getDeclaredField("debug"),{#field}'
//查看debug属性
ognl '@sun.security.ssl.Handshaker@debug'
//设置isReadOnly
options strict false
ognl '#cls=@Class@forName("sun.security.ssl.Handshaker"),#field=#cls.getDeclaredField("debug"),#override=#field.overrideFieldAccessor,#override.isReadOnly=false'
//设置debug属性
ognl '#deg=@sun.security.ssl.Debug@getInstance("ssl"),#cls=@Class@forName("sun.security.ssl.Handshaker"),#field=#cls.getDeclaredField("debug"),#modifiers=#field.getClass().getDeclaredField("modifiers"),#modifiers.setAccessible(true),#modifiers.setInt(#field,#field.getModifiers() & ~@java.lang.reflect.Modifier@FINAL),#field.setAccessible(true),#field.set(#cls,#deg)'
SSLSocketImpl
//设置isReadOnly
options strict false
ognl '#cls=@Class@forName("sun.security.ssl.SSLSocketImpl"),#field=#cls.getDeclaredField("debug"),#override=#field.overrideFieldAccessor,#override.isReadOnly=false'
//设置debug属性
ognl '#deg=@sun.security.ssl.Debug@getInstance("ssl"),#cls=@Class@forName("sun.security.ssl.SSLSocketImpl"),#field=#cls.getDeclaredField("debug"),#modifiers=#field.getClass().getDeclaredField("modifiers"),#modifiers.setAccessible(true),#modifiers.setInt(#field,#field.getModifiers() & ~@java.lang.reflect.Modifier@FINAL),#field.setAccessible(true),#field.set(#cls,#deg)'
//查看debug属性
ognl '@sun.security.ssl.SSLSocketImpl@debug'
InputRecord
//设置isReadOnly
options strict false
ognl '#cls=@Class@forName("sun.security.ssl.InputRecord"),#field=#cls.getDeclaredField("debug"),#override=#field.overrideFieldAccessor,#override.isReadOnly=false'
//设置debug属性
ognl '#deg=@sun.security.ssl.Debug@getInstance("ssl"),#cls=@Class@forName("sun.security.ssl.InputRecord"),#field=#cls.getDeclaredField("debug"),#modifiers=#field.getClass().getDeclaredField("modifiers"),#modifiers.setAccessible(true),#modifiers.setInt(#field,#field.getModifiers() & ~@java.lang.reflect.Modifier@FINAL),#field.setAccessible(true),#field.set(#cls,#deg)'
//查看debug属性
ognl '@sun.security.ssl.InputRecord@debug'
OutputRecord
//设置debug属性
ognl '#deg=@sun.security.ssl.Debug@getInstance("ssl"),#cls=@Class@forName("sun.security.ssl.OutputRecord"),#field=#cls.getDeclaredField("debug"),#modifiers=#field.getClass().getDeclaredField("modifiers"),#modifiers.setAccessible(true),#modifiers.setInt(#field,#field.getModifiers() & ~@java.lang.reflect.Modifier@FINAL),#field.setAccessible(true),#field.set(#cls,#deg)'
//查看debug属性
ognl '@sun.security.ssl.OutputRecord@debug'

方式四 对象状态分析

通过源码分析可知:SSL握手成功的情况下,SSLSocket实例的connectionState==cs_DATA,handshaker==null;握手进行中的时候,connectionState==cs_HANDSHAKE,handshaker==ClientHandshaker。所以通过arthas vmtool分别查看对应SSLSocket实例connectionState、handshaker变量的值就可以判断处SSLSocket处于什么状态。

找出阻塞的SSLSocket

由于业务应用每次请求都创建新的SSLSocket,所以我们只要找出创建时间比较早的SSLSocket,基本都是阻塞的。
image.png
通过socket的创建时间,可以找出阻塞的socket。

SSLSocket握手完成

image.png

SSLSocket握手未完成

image.png
具体阻塞在SSLSocket握手的哪个阶段,可以通过ClientHandshaker属性值进行判断,例如:
客户端发送了ClientHello
● 当服务端响应ServerHello的时候,属性protocolVersion不为空,svr_random不为空,cipherSuite不为默认值SSL_NULL_WITH_NULL_NULL,keyExchange不为默认值K_NULL;
● 当服务端没有响应ServerHello的时候,属性protocolVersion为空,svr_random为空,cipherSuite为默认值SSL_NULL_WITH_NULL_NULL,keyExchange为默认值K_NULL。
● 当服务端响应ServerCertificate的时候,handshaker的session属性的peerCerts字段不为空;
● 当服务端没有响应ServerCertificate的时候,handshaker的session属性的peerCerts字段为空;
● 以上可以结合handshaker的state变量值进行分析

经验总结

优化HttpClient使用方式

  • 不使用@Deprecated相关接口及实现类
  • HttpClient使用单例形式,而不是每个请求新建一个
  • SSLSessionContext参数优化,详情见:SSL Session默认设置导致线程阻塞了几十秒的案例分析

服务端为何没有响应的原因:初步判断是由于客户端频繁SSL握手,触发了服务端的安全策略(未完待续)。

SSLSocket调试

enable debug

● 方式一:JVM启动参数添加-Djavax.net.debug=all
● 方式二:通过arthas动态打开debug

handshakeListeners

通过向SSLSocket注册handshakeListeners,当SSL握手完成的时候可以获取SSL握手完成的通知。。

X509TrustManager

该类的实现类方法checkServerTrusted通常是不做实现的,不过可以在该方法中记录下SSLSocket状态信息以方便问题排查。

点赞收藏
大禹的足迹

在阿里搬了几年砖的大龄码农,头条号:大禹的足迹

请先登录,查看9条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步
7
9