前言: 2022都要结束了,发现自己今年都没有贡献博客,索性在今天晚上10点左右必须在这22年的尾巴上贡献一篇。希望大家多多指教。
一、问题现象描述
反馈功能不可用,重启所有节点恢复。
二、问题堆栈及分析
1. 堆栈
"test_google-d87c009e-5" #215 prio=5 os_prio=31 cpu=290.56ms elapsed=1353.38s tid=0x000000011f8a7000 nid=0xf307 waiting on condition [0x0000000174481000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@17.0.4.1/Native Method)
- parking to wait for <0x0000000705d07620> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(java.base@17.0.4.1/LockSupport.java:211)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.4.1/AbstractQueuedSynchronizer.java:715)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.4.1/AbstractQueuedSynchronizer.java:938)
at java.util.concurrent.locks.ReentrantLock$Sync.lock(java.base@17.0.4.1/ReentrantLock.java:153)
at java.util.concurrent.locks.ReentrantLock.lock(java.base@17.0.4.1/ReentrantLock.java:322)
at sun.net.www.http.KeepAliveCache.put(java.base@17.0.4.1/KeepAliveCache.java:96)
at sun.net.www.protocol.https.HttpsClient.putInKeepAliveCache(java.base@17.0.4.1/HttpsClient.java:671)
at sun.net.www.http.HttpClient.finished(java.base@17.0.4.1/HttpClient.java:451)
at sun.net.www.http.ChunkedInputStream.closeUnderlying(java.base@17.0.4.1/ChunkedInputStream.java:219)
at sun.net.www.http.ChunkedInputStream.processRaw(java.base@17.0.4.1/ChunkedInputStream.java:456)
at sun.net.www.http.ChunkedInputStream.readAheadBlocking(java.base@17.0.4.1/ChunkedInputStream.java:574)
at sun.net.www.http.ChunkedInputStream.readAhead(java.base@17.0.4.1/ChunkedInputStream.java:611)
at sun.net.www.http.ChunkedInputStream.read(java.base@17.0.4.1/ChunkedInputStream.java:705)
at java.io.FilterInputStream.read(java.base@17.0.4.1/FilterInputStream.java:132)
at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(java.base@17.0.4.1/HttpURLConnection.java:3678)
at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(java.base@17.0.4.1/HttpURLConnection.java:3671)
at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(java.base@17.0.4.1/HttpURLConnection.java:3659)
at com.google.api.client.http.javanet.NetHttpResponse$SizeValidatingInputStream.read(NetHttpResponse.java:175)
at java.io.FilterInputStream.read(java.base@17.0.4.1/FilterInputStream.java:82)
at java.io.FilterInputStream.read(java.base@17.0.4.1/FilterInputStream.java:82)
at com.google.api.client.http.GzipSupport$OptimisticAvailabilityInputStream.read(GzipSupport.java:77)
at java.util.zip.CheckedInputStream.read(java.base@17.0.4.1/CheckedInputStream.java:59)
at java.util.zip.GZIPInputStream.readUByte(java.base@17.0.4.1/GZIPInputStream.java:266)
at java.util.zip.GZIPInputStream.readUShort(java.base@17.0.4.1/GZIPInputStream.java:258)
at java.util.zip.GZIPInputStream.readHeader(java.base@17.0.4.1/GZIPInputStream.java:164)
at java.util.zip.GZIPInputStream.readTrailer(java.base@17.0.4.1/GZIPInputStream.java:234)
at java.util.zip.GZIPInputStream.read(java.base@17.0.4.1/GZIPInputStream.java:119)
at java.io.BufferedInputStream.fill(java.base@17.0.4.1/BufferedInputStream.java:244)
at java.io.BufferedInputStream.read1(java.base@17.0.4.1/BufferedInputStream.java:284)
at java.io.BufferedInputStream.read(java.base@17.0.4.1/BufferedInputStream.java:343)
- locked <0x000000070e8ed1f0> (a java.io.BufferedInputStream)
at java.io.BufferedInputStream.fill(java.base@17.0.4.1/BufferedInputStream.java:244)
at java.io.BufferedInputStream.read(java.base@17.0.4.1/BufferedInputStream.java:263)
- locked <0x000000070e8ec8c8> (a java.io.BufferedInputStream)
at com.google.api.client.googleapis.batch.BatchUnparsedResponse.readRawLine(BatchUnparsedResponse.java:248)
at com.google.api.client.googleapis.batch.BatchUnparsedResponse.readLine(BatchUnparsedResponse.java:272)
at com.google.api.client.googleapis.batch.BatchUnparsedResponse.<init>(BatchUnparsedResponse.java:84)
at com.google.api.client.googleapis.batch.BatchRequest.execute(BatchRequest.java:264)
。。。
。。。
2. 分析
从产线拿到的thread.log,分析出的核心的问题线程如下:
可见上图,线程阻塞在 lock 0x0000000705d07620 上。
大家可以看看堆栈是什么问题。
这里可以看到业务上是谷歌的sdk在发起http request,
此处没有使用第三方的http线程池,比如okhttp,httpclient之类,此处是调用java提供的HttpURLConnection来进行request的。
这个地方为什么会阻塞?
我们来看阻塞的点:
等待锁,那必然有占用锁的情况,我们可以查找thread.log,看看是什么线程占有了锁,在运行状态。
这个是查出来的相关功能唯一一个处在运行状态的线程。
三、问题压测及复现
1. 压测注意
既然是服务器端存在瓶颈,我们一般都是可以通过压测然后复现问题。
压测无非是模拟至少要保证:
1. 比如请求一致,/xxxx
2. jdk版本一致,JDK17
即尽可能的保证环境和产线一致。
本文前面贴的截图都是压测自己本地服务相关功能的压测线程日志的截图。
本次压测结果,50并发就已经复现问题了。
2. 压测结果
压测20并发截图:
压测50并发截图:
在50个并发的时候 90%的响应时间已经到达10s,问题可复现。
四、问题分析及解决
1. 详细分析
对比前面贴的两张图,我们发现锁相关的位置是 jdk17 的 KeepAliveCache.class。
我们看下jdk17的源码: KeepAliveCache.class
put() 和 get() 使用的是同一个锁 ,或者可以理解为 下图的 cacheLock 锁了该类的大部分方法。
2. 如何解决
OK,JDK的代码有锁,确实很难处理,我们再看这个地方为什么会阻塞?不慢是不是就不会阻塞了,是不是就这个地方蛮导致了阻塞。 假设加锁的地方运行时间是1ms,那么1s我们也可以执行1000次。速度也会很快。
我们再回头看堆栈:
这个地方在close connection,也就是关闭连接慢。关闭连接耗时会阻塞,不像采用池的方式,只用连接,而不用关注建立链接和关闭链接。 一次网络的开销或者运行是远远大于CPU时间的,所以这个地方一旦要关闭锁锁阻塞严重。
所以此处要关注为什么要关闭连接。
那突破口就是可以看如何调整MaxConnections。
KeepAliveCache.class
此处http.maxConnections是从系统环境变量取的。默认没有设置的话每个URL的maxConnections最大值为5。
3. 解决方案及验证
即解决方案可以设置比如-DmaxConnections=100解决。我们产线最终是20,因为有多个节点。
最终压测验证:200并发 效果明显变好。
五、总结及延伸
1. 总结
经上述分析,总结为google sdk使用的是jdk自带的HttpURLConnection来进行http request。 HttpURLConnection底层使用cache的方式,缓存URL,每个url设置的最大缓存数值是5,我们可以通过设置-DmaxConnections 来调整每个url的maxConnections即缓存的connection最大值。
2. 延伸
jdk8 KeepAliveCache.class
jdk8的情况下采用的是synchronized 来锁住方法,属于方法级别的锁。
jdk17
而jdk17是大部分方法采用的一个公共锁,可以理解为属于类级别的锁,从锁的效率来看jdk8的synchronized锁更加。
所以理论上同样的代码运行在jdk8的环境下,效率要明显高于jdk17.以下是jdk8的压测情况。