復雜業務系統線上問題排查過程
背景
5月份,我接手了一個業務比較復雜的系統,原來負責這塊的是我的同事,離職了,這期間有問題或者開發任務,都是一個合作方同事在負責,我由于手里事情太多了,暫時沒時間管這套系統。
這套系統的客戶是股票投資者,股票投資者可以將一部分持倉的股票和資金授權交給我們代為操作,我們這邊也不是人工操作,而是由量化算法去買賣,而且是日內T+0的,也就是說,早上你把資金和股票交給我們,我們日內的量化算法,盡力去捕捉交易機會,比如高賣低買(反向T)或者低買高賣(正向T),當然,我們A股是T+1的,所以需要有歷史持倉才能這么玩。
每天T日交易完成后的第二天早上0點左右,會有批處理任務去計算用戶昨日的收益情況。
7月9日,業務反饋,有客戶反饋7月8日,量化算法是有成交的,但是查看收益的地方,顯示收益為0.
這個bug呢,是需要馬上介入處理的,不過也沒有那么緊急,畢竟收益還是有(沒注意是盈還是虧),只是看不到。
當日排查過程
相關流程介紹
用戶看到的,沒顯示昨日收益的地方,接口中是查詢了如下表(以下表皆為示意表):

我們這邊,負責這塊的合作方同事A在深圳,他最熟悉業務,這部分全是他寫的;我在成都,我leader在深圳,運維同事也是成都,我們三個人都不熟悉業務,運維在運維室里是臺式機,臺式機還不帶聲卡,溝通起來著實有點困難,勉強靠微信語音和騰訊會議溝通著。
在同事A的指導下,查了下上述的stock_total_profit表,這個表是存放總收益的,不過里面也有一個昨日收益字段。運維查了下,昨日收益字段為0. 接下來,開始溝通,這個字段怎么計算出來的。
溝通的結果,是說通過xxljob定時任務計算出來的,源表是stock_daily_profit,這個是存放用戶每天的收益情況。
接下來,同事A發了個sql過來查了下這個表,發現是昨日(20250708)日的profit字段不為0.

這下,源表沒問題,最終表有問題,同事A也懵了,懷疑起了代碼里別的方向,比如用戶是不是昨天用了量化策略2,也就是說,是量化策略類型沒匹配上導致的bug,把我們聽得也很懵。
總收益計算邏輯
只能讓他給我們把邏輯講一下,這塊的計算邏輯是這樣的:
對上面這個日收益表,先計算總收益:

然后,再弄個sql,查詢昨日的收益:

最后,把這兩個數據根據用戶名組合一下,然后寫入到總收益表:

邏輯就是這么個邏輯,為啥有問題還不知道。
xxljob日志
一方面,同事A在指導運維同事,對比最近幾天的數據啥的;我和leader這邊,則在查看xxljob的運行日志,發現這個job好像不是那么簡單。

實際的日志中,報什么和數據庫相關的問題,什么socket is not closed,什么urgent packet,這些報錯我之前確實沒咋遇到,還有沒截全的部分如下,還包含什么read time out啥的:
socket is not closed; Urgent packet sent to backend successfully; An I/O error occured while sending to the backend.detail:Read timed out;
問題是,同事A沒說job里要同步什么資金流水吧。由于這個job是從凌晨開始,每10分鐘執行一次,看了幾次調度執行的日志,發現日志還亂七八糟的。
看代碼
開始看這塊的代碼,發現job開始,要去調一個接口,然后對查詢回來的遍歷處理,后面逐步才溝通清楚這里是去另一個服務,查詢要執行哪些表相關的任務,如,每天凌晨第一次執行的時候,會執行下面的第一個紅框中的兩個表:資金交收流水表(可以理解為股票交易流水)、股票每日收益表。

為了避免大家理解困難,我先撥開些迷霧:

我們當時就看到,xxljob里,對于股票交易明細表的相關sql,報了錯,就是上面那一堆:
socket is not closed; Urgent packet sent to backend successfully; An I/O error occured while sending to the backend.detail:Read timed out;
但是后續還在繼續執行:股票日收益的計算,且:從日志來看,說股票日收益計算成功了??聪聢D,上面有股票明細相關的報錯,但是下面的日志看,日收益的計算沒問題。

也就是說,同事A認為,下面的日收益表的數據是可信的:

我們另外幾個,也不懂這塊業務,既然這個日收益表的數據沒問題,那就重跑下計算總收益的那個xxljob,把總收益計算出來,應該就行了吧,至于為啥總收益之前沒計算出來,現在來說,不那么重要,修復問題更要緊。
重跑整個job
計算總收益,代碼邏輯其實是在包含在:股票每日收益表的邏輯。

這個日收益的job,在完成對日收益的計算后,會觸發月收益代碼:

月收益完成后,又觸發年收益:

年收益里,又觸發了總收益計算:

而上述那部分代碼,又是包含在更大的job中的,如下圖所示:

先是調接口,查詢要跑哪些任務,正常查詢到兩個:

然后由于股票交易流水的任務在前,所以先執行;執行時,就是從另外的原始股票明細表(會通過數倉傳到我們的數據庫里),轉存到我們自己的股票明細表,正常來說,轉存成功后的股票明細表如下(這個也代表,當天T+0策略,觸發了交易):

但問題是出現在,這里其實會失?。赡苁沁@個表數據量很大,存儲了兩年多的股票明細),報那個:
socket is not closed; Urgent packet sent to backend successfully; An I/O error occured while sending to the backend.detail:Read timed out;

但此時異常被捕獲了,接著開始執行日收益計算:這里必須要說的是,日收益計算這個task,其實是依賴股票交易流水這個任務的。你想啊,股票的交易明細如果沒成功,此時你去計算股票日收益,那能算出來嗎,很可能就是查不到相關的股票交易明細,導致算出來的日收益表中的收益為0。
其實,這里我真正的猜想是,在股票交易明細的任務這里,是sql執行時間太長了,但其實數據庫還在繼續執行;而我們的程序,等了一段時間后,就超時了(read time out),關閉了連接,然后開始執行日收益。此時相當于在并發操作數據庫的這個表:

但我們當時看的那個用戶的日收益(有幾個股票的日收益不是0了),貌似是對的,就沒注意這塊。
不管咋說吧,我們就是準備重跑xxljob。結果重跑卻沒有實際執行,因為,查詢任務的接口提示:這兩個任務已經是已執行狀態了。

所以沒法重跑。當然,其實我們可以把數據庫字段改一下就行了,不過同事A說,可以單獨跑另一個job。
只重跑計算總收益的job
只重新計算出現問題的總收益部分,這塊有個單獨的job,這個job平時是不運行,就是為了出現問題時,手動重跑:

這個job的邏輯呢,我們其實在最開始的相關流程介紹那里講了,就是把下面兩個sql的結果在內存里拼一下,再寫入stock_total_profit即可。
SELECT NAME,SUM(profit) FROM stock_daily_profit
GROUP BY NAME,profit
SELECT NAME,SUM(profit) FROM stock_daily_profit
WHERE trade_day ='20250708'
GROUP BY NAME,profit
結果,重跑這個job,發現失敗了,依然是前面遇到的:
socket is not closed; Urgent packet sent to backend successfully; An I/O error occured while sending to the backend.detail:Read timed out;
只是這次報錯的sql,是下面這個sql,這個表,整表聚合,表數據大概是300w左右,實際的sql比這個復雜(8個字段聚合,select里也有各種計算)
SELECT NAME,SUM(profit) FROM stock_daily_profit
GROUP BY NAME
這個sql,在xxljob中失敗,我們就拿到可視化工具里手動執行了下,發現要執行13秒左右。
然后當時沒別的辦法,又去xxljob中試了下,這次成功了。(當時大家猜:因為在可視化工具中執行,可能有緩存了,所以這次10s內就返回了,程序就沒超時)
由于成功了,這次的問題大體也就算修復了。但,這里的sql超時等問題,還是需要解決,這個就留待次日了。
次日排查過程
本地復現
這一天的核心,是解決sql超時問題。這天一早,運維同事就又說,這一天的xxljob又失敗了,還是超時,問題現象一樣。我們就靠手動重跑,暫時解決這個問題。
其實,我現在看來(寫文章的此刻),這一天的數據可能還是有問題:必須確保股票交易明細數據沒問題后,才能執行日收益計算。否則,就有并發的可能性,可能我在計算日收益的時候,還查不到股票交易明細。
至于為啥現在也沒人反饋這些,因為這塊應該是沒有對賬程序,嗐,我們這個草臺班子;用戶不反饋,我們也就不知道。
不管怎么說,這一天我們手動重跑,認為已經解決了問題。
然后開始研究sql超時問題。
需要先在本地模擬一下,本地數據庫的表里,只有幾十萬數據,查詢很快就返回了;我只能是建一個測試表出來:
然后下面的sql多執行幾遍,數據就翻到了300w,當然,我這么造數據是可以的(業務上可能不太對),畢竟模擬那個慢sql足夠了
insert
into
stock_daily_profit_test(trddate,
custid,
fundid,
xxx1,
xxx2)
select
trddate,
custid,
fundid,
xxx1,
xxx2
from
stock_daily_profit
在搞個接口來調用這個sql:

sql就是我前面提到的:
SELECT NAME,SUM(profit) FROM stock_daily_profit
GROUP BY NAME
然后調下這個接口,果然就報了一模一樣的錯誤了。
debug&&修改配置
debug這部分就不在這里說了,我們用的數據庫是國產信創的庫,其實是基于pg改的,但是,廠商只有二進制的驅動jar包,沒有源碼,這部分只能靠debug了。
訪問數據庫的話,我們從上到下的組件,依次是:com.baomidou.mybatisplus --> mybatis --> 阿里druid--》 廠商給的類postgre驅動包。


這部分,慢慢去debug就行了,有空了可以單獨寫一下這部分。
我們程序在線上的表現是,超過10s,沒等到數據庫的響應報文,就會自己斷開tcp連接(沒在線上抓包確認,我其實命令發給運維了,當時時間趕,忘記執行了;但我本地復現出來現象一模一樣,而我在本地是抓了包的,本地就是自己主動斷開的)。至于為啥是10s,這個其實就是個默認設置。
我們同事說,我們配置文件里,配了超時時間的呀,好像沒生效:

嗯。。經過我一番debug,發現問題出現在,我們引入了動態數據源組件:
<dependency>
<groupId>com.baomidou</groupId>
<artifactId>dynamic-datasource-spring-boot-starter</artifactId>
</dependency>
這個組件呢,是去spring.datasource.dynamic下面找配置的,根本不會在上述的spring.datasource.druid里找配置:

最終就是要調整下配置的位置,把那一段全放到dynamic下:

另外,超時的配置就是這個:

最終,對我們來說,就是把配置挪下位置,然后超時時間改長一點,先臨時解決這個問題,后續再優化這里的sql。
這一天,走了個緊急流程,把這個變更上線了,就等第二天20250711看結果。
而第二天,果然就沒啥問題了,資金流水的任務也不超時了,各種sql都不超時了,壓力最終還是給到了數據庫,總算是臨時解決了
job存在的問題
就那個流程很長的job來說,問題真的不少。
日收益任務在執行前未檢查前置任務是否成功
這里都出錯了,怎么還能繼續往下走呢?得改。

日收益任務,在未完全執行完成時即報告任務執行成功
下圖這兩把叉這里,先就報告任務成功了;但后續還在執行月收益、年收益、總收益的計算。我覺得應該得放到最后才行,這塊在排查過程中就發現了,同事A知道這個bug。

月收益、年收益計算時,分頁查詢導致數據庫壓力大

那個sql和下面sql類似,計算月收益,實際sql也比這復雜很多:
SELECT NAME,SUM(profit) FROM stock_daily_profit
WHERE trade_day BETWEEN '20250708' AND '20250608'
GROUP BY NAME
這里這個sql這么復雜,每次執行都要很久,每次返回的結果也是一樣的,結果數量總數也并不算多;分頁查詢導致了這個sql被執行了幾十次。。。
年收益、總收益的地方也是類似的,難怪那個xxljob執行了二十多分鐘。
總結
問題的解決在最后看起來很簡單,但是在當時的層層迷霧情況下,還是比較頭疼。這塊的邏輯也比較復雜,甚至于在解決完問題后沒兩天,我就忘了代碼整體的流程了,這也是記錄下來的意義吧,在想辦法給大家講明白的過程中,我也更清晰了,也發現了一些潛在的問題。

浙公網安備 33010602011771號