問題與分析
某天領導report了一個問題:線上的CPU自從上一個版本迭代后就一直處於居高不下的狀況,領導看着這段時間的曲線圖判斷是有兩條線程在不停的死循環。
接到任務后去查看了AWS的CloudWatch,發現線上CPU確實一直居高不下,使用率基本是之前的兩倍;另外發現線程使用率以比之前頻繁很多。后來公司的大佬拿到dump后經過分析發現,是由正則表達式造成的CPU持續高使用率的問題。
堆棧信息如下:
at java.util.regex.Pattern$Loop.match(Pattern.java:4787)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4719)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4281)
at java.util.regex.Pattern$Curly.match(Pattern.java:4236)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4274)
at java.util.regex.Pattern$Curly.match(Pattern.java:4236)
at java.util.regex.Pattern$GroupCurly.match0(Pattern.java:4487)
at java.util.regex.Pattern$GroupCurly.match(Pattern.java:4407)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4274)
at java.util.regex.Pattern$Curly.match(Pattern.java:4236)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4660)
at java.util.regex.Pattern$Loop.match(Pattern.java:4787)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4719)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4281)
at java.util.regex.Pattern$Curly.match(Pattern.java:4236)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4274)
at java.util.regex.Pattern$Curly.match(Pattern.java:4236)
at java.util.regex.Pattern$GroupCurly.match0(Pattern.java:4487)
at java.util.regex.Pattern$GroupCurly.match(Pattern.java:4407)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4274)
at java.util.regex.Pattern$Curly.match(Pattern.java:4236)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4660)
at java.util.regex.Pattern$Loop.match(Pattern.java:4787)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4719)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4274)
at java.util.regex.Pattern$Curly.match(Pattern.java:4236)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4274)
at java.util.regex.Pattern$Curly.match(Pattern.java:4236)
at java.util.regex.Pattern$GroupCurly.match0(Pattern.java:4487)
at java.util.regex.Pattern$GroupCurly.match(Pattern.java:4407)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4274)
at java.util.regex.Pattern$Curly.match(Pattern.java:4236)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4660)
at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4803)
at java.util.regex.Pattern$Prolog.match(Pattern.java:4743)
at java.util.regex.Pattern$GroupCurly.match0(Pattern.java:4487)
at java.util.regex.Pattern$GroupCurly.match(Pattern.java:4407)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4719)
at java.util.regex.Pattern$BranchConn.match(Pattern.java:4570)
at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3800)
at java.util.regex.Pattern$Branch.match(Pattern.java:4606)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4660)
at java.util.regex.Pattern$Start.match(Pattern.java:3463)
at java.util.regex.Matcher.search(Matcher.java:1248)
at java.util.regex.Matcher.find(Matcher.java:637)
at com.core.cbx.mybatis.plugin.sql.TableAliasParseInjector.getTableAlias(TableAliasParseInjector.java:48)
還是第一次知道正則表達式也會引發這種問題,網上查了下資料,原來有不少人也遇到同樣的問題。而這個問題,是由正則表達式的災難性回溯(Catastrophic Backtracking),或者說回溯陷阱造成的。
另外,可以發現在jdk的JIRA里也有人提出了這個issue,不過目前依然還沒有解決這個bug,下面是官方的issue鏈接:StackOverflowError in java.util.regex.Pattern
引擎與回溯
這里引用下一位老哥的原文,簡單介紹下正則表達式的引擎和回溯機制。
正則引擎主要可以分為基本不同的兩大類:一種是DFA(確定型有窮自動機),另一種是NFA(不確定型有窮自動機)。簡單來講,NFA 對應的是正則表達式主導的匹配,而 DFA 對應的是文本主導的匹配。
DFA從匹配文本入手,從左到右,每個字符不會匹配兩次,它的時間復雜度是多項式的,所以通常情況下,它的速度更快,但支持的特性很少,不支持捕獲組、各種引用等等;而NFA則是從正則表達式入手,不斷讀入字符,嘗試是否匹配當前正則,不匹配則吐出字符重新嘗試,通常它的速度比較慢,最優時間復雜度為多項式的,最差情況為指數級的。但NFA支持更多的特性,因而絕大多數編程場景下(包括java,js),我們面對的是NFA。
Java的正則表達式引擎用的是NFA算法,在根據正則表達式來匹配文本時,擁有回溯機制。在遇到以下字符時就有可能發生回溯:
?+*{min, max}
以上四種默認是貪婪模式去匹配文本,也就是說,會盡可能多地去匹配更多的字符。在這個匹配的過程中,必然會一次次地匹配文本,一直到匹配不上時,才會回溯一次,重新用正則表達式的下一個字符去匹配回溯之前匹配不上的文本。
這里說的比較抽象,有興趣的可以自行搜索下正則表達式的回溯以及貪婪模式、懶惰模式(也叫勉強模式)和獨占模式(也叫侵占模式),下面附上一篇圖文並茂的文章:正則表達式三種模式:貪婪模式、懶惰模式、獨占模式
總之,簡單地說,由於正則表達式的回溯,如果我們的正則表達式寫得不夠好,並且被匹配的字符串文本又非常長,就有可能大量觸發回溯,導致CPU飆升,甚至是堆棧溢出。這也就是所謂的災難性回溯,或者說回溯陷阱。
這里還是拿上面文章里的例子來舉例:為了校驗馬來西亞的商店名字,寫了如下一條正則表達式:
^([A-Za-z0-9._()&'\\- ]|[aAàÀảẢãÃáÁạẠăĂằẰẳẲẵẴắẮặẶâÂầẦẩẨẫẪấẤậẬbBcCdDđĐeEèÈẻẺẽẼéÉẹẸêÊềỀểỂễỄếẾệỆfFgGhHiIìÌỉỈĩĨíÍịỊjJkKlLmMnNoOòÒỏỎõÕóÓọỌôÔồỒổỔỗỖốỐộỘơƠờỜởỞỡỠớỚợỢpPqQrRsStTuUùÙủỦũŨúÚụỤưƯừỪửỬữỮứỨựỰvVwWxXyYỳỲỷỶỹỸýÝỵỴzZ])+$
這就是一個很簡單的^()+$結構,由於校驗允許使用英文字母大小寫、數字、越南文和一些特殊字符如“&”,“-”,“_”等,於是直接把這些字符都塞到[]里,然后為了方便觀看把越南文特地抽出來塞到另一個[]里,最后把這兩個[]用|拼接起來。
看上去非常簡單的結構,但卻會在線上時不時引發CPU過高的問題,可以用下面的測試類簡單跑一下看看:
import java.util.regex.Matcher;
import java.util.regex.Pattern;
public class Test {
private static final String REGEX_TABLE_ALIAS = "^([A-Za-z0-9._()&'\\- ]|[aAàÀảẢãÃáÁạẠăĂằẰẳẲẵẴắẮặẶâÂầẦẩẨẫẪấẤậẬbBcCdDđĐeEèÈẻẺẽẼéÉẹẸêÊềỀểỂễỄếẾệỆfFgGhHiIìÌỉỈĩĨíÍịỊjJkKlLmMnNoOòÒỏỎõÕóÓọỌôÔồỒổỔỗỖốỐộỘơƠờỜởỞỡỠớỚợỢpPqQrRsStTuUùÙủỦũŨúÚụỤưƯừỪửỬữỮứỨựỰvVwWxXyYỳỲỷỶỹỸýÝỵỴzZ])+$";
public static void main(final String[] args) {
final String string = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!";
final Pattern pattern = Pattern.compile(REGEX_TABLE_ALIAS);
final Matcher matcher = pattern.matcher(string);
final boolean result = matcher.find();
System.out.println(result);
}
}
你會發現,當在校驗這個aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!字符串時,竟然無法立刻打印出校驗結果,需要等待相當長的一段時間。如果把這個字符串改成這個,!aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa,就可以秒出結果。
這兩個字符串是一樣長,區別僅僅是!在首位和末位而已,但在校驗時花費的時間卻完全不同,原因是!是非法字符,但在末位時,會觸發大量回溯,如果這個字符串文本有數百位,上千位,就很有可能會發生堆棧溢出。
原文作者的解決方法是把原來的正則表達式改為獨占模式,也就是在+后加上+,將^()+$結構變成^()++$結構。這種做法我認為其實不太好,獨占模式也是會盡可能地匹配更多的字符,但是卻不會發生回溯,如果正則表達式寫得不好,就可能會校驗漏。
其實有個更好的改法,就是單純把原來的表達式里的兩個[]合並成一個[],如下:
^([A-Za-z0-9._()&'\\- aAàÀảẢãÃáÁạẠăĂằẰẳẲẵẴắẮặẶâÂầẦẩẨẫẪấẤậẬbBcCdDđĐeEèÈẻẺẽẼéÉẹẸêÊềỀểỂễỄếẾệỆfFgGhHiIìÌỉỈĩĨíÍịỊjJkKlLmMnNoOòÒỏỎõÕóÓọỌôÔồỒổỔỗỖốỐộỘơƠờỜởỞỡỠớỚợỢpPqQrRsStTuUùÙủỦũŨúÚụỤưƯừỪửỬữỮứỨựỰvVwWxXyYỳỲỷỶỹỸýÝỵỴzZ])+$
這時候再去跑上面的測試類,你會發現在校驗上面的兩個字符串文本時,都可以秒出校驗結果。原因是新的表達式減少了回溯的機會,相當於把Java里連續多個if語句給合並成一個了,這樣就減少了分支,自然就降低了災難性回溯的可能性。
具體案例與解決方案
上面是其他人遇到的案例,這里說下博主遇到的case以及最終的解決方案。在系統中我們用的是自己魔改過的mybatis,其中有個正則表達式是用來獲取sql中的表別名的,如下:
(FROM|JOIN|,)(\\s)+([A-Z0-9_]+(\\s)+[A-Z0-9_]+(,| )*)+(\\s)+(JOIN|WHERE|INNER|LEFT|OUTER|ON|ORDER)
這個本來一直都沒有問題,直到前段時間系統迭代后,有客戶在頁面上搜索了一段比較長的字符串。這個搜索的操作其實就是向db發出一條sql,用來模糊查詢若干個字段是否含有用戶搜索的這段字符串。然后在組裝這條sql的時候,會使用到上述的正則表達式來獲取表別名,具體組裝邏輯這里就不說了。最后組裝成的sql比較長,大概一萬多個字符(已經簡化過了)。之所以這么長,是因為我們會拿用戶輸入的字符串去挨個模糊查詢數據表里的很多個字符類型的列,也就是說,會有大量的like '%xxxx%'的部分。
當這條很長的sql被上述的正則表達式匹配時,就會發生災難性回溯,導致系統長時間假死。這里就不貼出來具體的sql了,就簡單分析下上述正則表達式存在什么問題。
表達式分成了三塊部分,第一部分是(FROM|JOIN|,)(\\s)+,第二部分是([A-Z0-9_]+(\\s)+[A-Z0-9_]+(,| )*)+,第三部分是(JOIN|WHERE|INNER|LEFT|OUTER|ON|ORDER)。這個很好理解,就是簡單匹配下表別名,比如:from Table_A a, Table_B b where ...。
可以發現,表達式的第一部分和第二部分都有,,而第二部分的末尾使用了+限定必須至少匹配一次,導致當sql過長時並存在大量逗號空格時,會觸發大量回溯。為了避免這種情況,應當盡量把第二部分末尾的+去掉,如果可能的話,可以轉換成*。
最終的修改方案是分為了兩部分:
第一部分是簡化sql,因為原本是直接拿組裝后的sql去匹配,其實sql里大量的like '%xxxx%'部分毫無意義,因為目的只是拿到表別名而已。所以在匹配之前,把這些模糊匹配的部分直接去掉了。
第二部分是修改正則表達式,測試時直接拿簡化前的sql去匹配,如果不會發生災難性回溯就算過關了。最終修改后的樣子如下:
(FROM|JOIN)(\\s)+([A-Z0-9_]+(\\s)+[A-Z0-9_]+((\\s)*(,|JOIN)(\\s)*[A-Z0-9_]+(\\s)+[A-Z0-9_]+)*)(\\s)+(JOIN|WHERE|INNER|LEFT|OUTER|ON|ORDER)
這里推薦個在線檢查正則表達式匹配字符串文本的網站,可以用來發現是否會觸發災難性回溯:Online regex tester and debugger: PHP, PCRE, Python, Golang and JavaScript
關於這個網站的用法可以看看這篇文章的末尾部分:一個正則表達式引發的血案,讓線上CPU100%異常!
排查高CPU使用率的方法
- 使用
top命令查找在大量占用CPU的進程的PID - 使用
ps -mp pid -o THREAD,tid,time定位到大量占用CPU的線程TID;也可以用這個命令直接排序下,更方便找到大量占用CPU的線程:ps -mp pid -o THREAD,tid,time|uniq -c|sort -nr - 將上述找到的線程TID轉換成十六進制:
printf “%x\n” TID,比如原本的線程TID是28802,可以用上面的命令轉成十六進制數7082 - 使用PID以及剛剛轉成十六進制的TID來打印出該線程的堆棧信息:
jstack PID|grep TID -A 100。也可以把完整的堆棧信息輸入到一個log文件里,有兩種方法:- 方法一是用
kill -3 PID > threadDump.log 2>&1,這種方法不適用於JDK1.6以上的版本 - 方法二是用
jstack -l PID > threadDump.log 2>&1
- 方法一是用
- 接下來就是分析堆棧信息,定位到問題代碼的位置了。
下面簡單介紹下上述命令的幾個關鍵參數的含義:
ps命令:
-m 顯示所有的執行者。
-p 指定進程的PID,並列出該進程的狀況。
-o 用戶自定義輸出格式。
unic命令:
-c 檢查文件是否已經按照順序排序,排序過為真
sort命令:
-n 按照數值大小進行排序
-r 以相反的順序進行排序,即降序排序,從大排到小
jstack命令:
-l long listing. Prints additional information about locks,會打印出額外的鎖信息,可以在發生死鎖時用來觀察鎖持有情況
-m to print both java and native frames (mixed mode),不僅會輸出Java堆棧信息,還會輸出C/C++堆棧信息(比如Native方法)
kill命令:
-signal 指定發送的信號類型,比如:
-3是打印進程的線程信息,並不會終止進程;
-9是強制殺死進程,一般用於立即殺死無響應或者卡死的進程;
-15是柔和地終止進程,一般會在終止之前保存數據、關閉連接,需要經過一段時間后才會完全退出進程,效果等同於-TERM
參考鏈接
- 一個正則表達式引發的血案,讓線上CPU100%異常!
- 正則表達式的失控——回溯循環
- 正則表達式:java.util.regex.Pattern matcher 循環導致高CPU
- 正則表達式三種模式:貪婪模式、懶惰模式、獨占模式
- StackOverflowError in java.util.regex.Pattern
- linux系統中,kill -3查看java進程狀態無效的解決方法
- Win下,通過Jstack截取Java進程中的堆棧信息
- linux ps 命令參數詳解
- Linux下面ps -o是什么意思
- kill與kill -9的區別
- 使用 kill 命令殺死 java進程,你用對了嗎?
- sort、uniq命令對文本進行排序、單一和重復操作
