前言
本篇主要講解的是前陣子的一個壓測問題.那么就直接開門見山
可能有的朋友不並不知道forceTransactionTemplate這個是干嘛的,首先這里先普及一下,在Java中,我們一般開啟事務就有三種方式
- XML中根據service及方法名配置切面,來開啟事務(前幾年用的頻率較高,現在基本很少用)
- @Transactional注解開啟事務(使用頻率最高)
- 采用spring的事務模板(截圖中的方式,幾乎沒什么人用)
我們先不糾結為什么使用第三種,后面在講事務傳播機制的時候我會專門介紹,我們聚焦一下主題,你現在只要知道,那個是開啟事務的意思就行了.我特意用紅色和藍色把日志代碼圈起來,意思就是,進入方法的時候打印日志,然后開啟事務后,再打印一個日志.一波壓測之后,發現接口頻繁超時,數據一致壓不上去.我們查看日志如下:
我們發現.這兩個日志輸出時間間隔,竟然用了接近5秒!開個事務為何用了5秒?事出反常必有妖!
如何切入解決問題
線上遇到高並發的問題,由於一般高並發問題重現難度比較大,所以一般肥朝都是采用眼神編譯,九淺一深靜態看源碼的方式來分析.具體可以參考本地可跑,上線就崩?慌了!.但是考慮到肥朝公眾號仍然有小部分新關注的粉絲尚未掌握分析問題的技巧,本篇就再講一些遇到此類問題的一些常見分析方式,不至於遇到問題時,慌得一比!
好在這個並發問題的難度並不大,本篇案例排查非常適合小白入門,我們可以通過本地模擬場景重現,將問題范圍縮小,從而逐步定位問題.
本地重現
首先我們可以准備一個並發工具類,通過這個工具類,可以在本地環境模擬並發場景.手機查看代碼並不友好,但是沒關系,以下代碼均是給你復制粘貼進項目重現問題用的,並不是給你手機上看的.至於這個工具類為什么能模擬並發場景,由於這個工具類的代碼全是JDK中的代碼,核心就是CountDownLatch類,這個原理你根據我提供的關鍵字對着你喜歡的搜索引擎搜索即可.
CountDownLatchUtil.java
1public class CountDownLatchUtil {
2
3 private CountDownLatch start;
4 private CountDownLatch end;
5 private int pollSize = 10;
6
7 public CountDownLatchUtil() {
8 this(10);
9 }
10
11 public CountDownLatchUtil(int pollSize) {
12 this.pollSize = pollSize;
13 start = new CountDownLatch(1);
14 end = new CountDownLatch(pollSize);
15 }
16
17 public void latch(MyFunctionalInterface functionalInterface) throws InterruptedException {
18 ExecutorService executorService = Executors.newFixedThreadPool(pollSize);
19 for (int i = 0; i < pollSize; i++) {
20 Runnable run = new Runnable() {
21 @Override
22 public void run() {
23 try {
24 start.await();
25 functionalInterface.run();
26 } catch (InterruptedException e) {
27 e.printStackTrace();
28 } finally {
29 end.countDown();
30 }
31 }
32 };
33 executorService.submit(run);
34 }
35
36 start.countDown();
37 end.await();
38 executorService.shutdown();
39 }
40
41 @FunctionalInterface
42 public interface MyFunctionalInterface {
43 void run();
44 }
45}
HelloService.java
1public interface HelloService {
2
3 void sayHello(long timeMillis);
4
5}
HelloServiceImpl.java
1@Service
2public class HelloServiceImpl implements HelloService {
3
4 private final Logger log = LoggerFactory.getLogger(HelloServiceImpl.class);
5
6 @Transactional
7 @Override
8 public void sayHello(long timeMillis) {
9 long time = System.currentTimeMillis() - timeMillis;
10 if (time > 5000) {
11 //超過5秒的打印日志輸出
12 log.warn("time : {}", time);
13 }
14 try {
15 //模擬業務執行時間為1s
16 Thread.sleep(1000);
17 } catch (Exception e) {
18 e.printStackTrace();
19 }
20 }
21}
HelloServiceTest.java
1@RunWith(SpringRunner.class)
2@SpringBootTest
3public class HelloServiceTest {
4
5 @Autowired
6 private HelloService helloService;
7
8 @Test
9 public void testSayHello() throws Exception {
10 long currentTimeMillis = System.currentTimeMillis();
11 //模擬1000個線程並發
12 CountDownLatchUtil countDownLatchUtil = new CountDownLatchUtil(1000);
13 countDownLatchUtil.latch(() -> {
14 helloService.sayHello(currentTimeMillis);
15 });
16 }
17
18}
我們從本地調試的日志中,發現了大量超過5s的接口,並且還有一些規律,肥朝特地用不同顏色的框框給大家框起來
為什么這些時間,都是5個為一組,且每組數據相差是1s左右呢?
真相大白
@Transactional的核心代碼如下(后續我會專門一個系列分析這部分源碼,關注肥朝以免錯過核心內容).這里簡單說就是retVal = invocation.proceedWithInvocation()方法會去獲取數據庫連接.
1if (txAttr == null || !(tm instanceof CallbackPreferringPlatformTransactionManager)) {
2 // Standard transaction demarcation with getTransaction and commit/rollback calls.
3 TransactionInfo txInfo = createTransactionIfNecessary(tm, txAttr, joinpointIdentification);
4 Object retVal = null;
5 try {
6 // This is an around advice: Invoke the next interceptor in the chain.
7 // This will normally result in a target object being invoked.
8 retVal = invocation.proceedWithInvocation();
9 }
10 catch (Throwable ex) {
11 // target invocation exception
12 completeTransactionAfterThrowing(txInfo, ex);
13 throw ex;
14 }
15 finally {
16 cleanupTransactionInfo(txInfo);
17 }
18 commitTransactionAfterReturning(txInfo);
19 return retVal;
20}
然后肥朝為了更好的演示這個問題,將數據庫連接池(本篇用的是Druid)的參數做了以下設置
1//初始連接數 2spring.datasource.initialSize=1 3//最大連接數 4spring.datasource.maxActive=5
由於最大連接數是5.所以當1000個線程並發進來的時候,你可以想象是一個隊伍有1000個人排隊,最前面的5個,拿到了連接,並且執行業務時間為1秒.那么隊伍中剩下的995個人,就在門外等候.等這5個執行完的時候.釋放了5個連接,依次向后的5個人又進來,又執行1秒的業務操作.通過簡單的小學數學,都可以計算出最后5個執行完,需要多長時間.通過這里分析,你就知道,為什么上面的日志輸出,是5秒為一組了,並且每組間隔為1s了.
怎么解決
看過肥朝源碼實戰的粉絲都知道,肥朝從來不耍流氓,凡是拋出問題,都會相應給出其中一種解決方案.當然方案沒有最優只有更優!
比如看到這里有的朋友可能會說,你最大連接數設置得就像平時贊賞肥朝的金額一樣小,如果設置大一點,自然就不會有問題了.當然這里為了方便向大家演示問題,設置了最大連接數是5.正常生產的連接數是要根據業務特點和不斷壓測才能得出合理的值,當然肥朝也了解到,部分同學公司機器的配置,竟然比不過市面上的千元手機!!!
但是其實當時壓測的時候,數據庫的最大連接數設置的是200,並且當時的壓測壓力並不大.那為什么還會有這個問題呢?那么仔細看前面的代碼
其中這個校驗的代碼是RPC調用,該接口的同事並沒有像肥朝一樣值得托付終身般的高度可靠,導致耗時時間較長,從而導致后續線程獲取數據庫連接等待的時間過長.你再根據前面說的小學數學來算一下就很容易明白該壓測問題出現的原因.
敲黑板划重點
之前肥朝就反復說過,遇到問題,要經過深度思考.比如這個問題,我們能得到什么拓展性的思考呢?我們來看一下之前一位粉絲的面試經歷
其實他面試遇到的這個問題,和我們這個壓測問題基本是同一個問題,只不過面試官的結論其實並不夠准確.我們來一起看一下阿里巴巴的開發手冊
那么什么樣叫做濫用呢?其實肥朝認為,即使這個方法經常調用,但是都是單表insert、update操作,執行時間非常短,那么承受較大並發問題也不大.關鍵是,這個事務中的所有方法調用,是否是有意義的,或者說,事務中的方法是否是真的要事務保證,才是關鍵.因為部分同學,在一些比較傳統的公司,做的多是能用就行的CRUD工作,很容易一個service方法,就直接打上事務注解開始事務,然后在一個事務中,進行大量和事務一毛錢關系都沒有的無關耗時操作,比如文件IO操作,比如查詢校驗操作等.例如本文中的業務校驗就完全沒必要放在事務中.平時工作中沒有相應的實戰場景,加上並沒有關注肥朝的公眾號,對原理源碼真實實戰場景一無所知.面試稍微一問原理就喊痛,面試官也只好換個方向再繼續深入!
通過這個經歷我們又有什么拓展性的思考呢?因為問題是永遠解決不完的,但是我們可以通過不斷的思考,把這個問題壓榨出更多的價值!我們再來看一下阿里規范手冊
用大白話概括就是,盡量減少鎖的粒度.並且盡量避免在鎖中調用RPC方法,因為RPC方法涉及網絡因素,他的調用時間存在很大的不可控,很容易就造成了占用鎖的時間過長.
其實這個和我們這個壓測問題是一樣的.首先你本地事務中調用RPC既不能起到事務作用(RPC需要分布式事務保證),但是又會因為RPC不可控因素導致數據庫連接占用時間過長.從而引起接口超時.當然我們也可以通過APM工具來梳理接口的耗時拓撲,將此類問題在壓測前就暴露.
寫在最后
更多專題系列式源碼解析、真實場景源碼原理實戰與你分享,掃描下方二維碼關注肥朝,讓天生就該造火箭的你,無須委屈擰螺絲！