背景

有一天，群里收到小伙伴提的一個問題，為什么程序 sensitive-word 第一次執行這么慢?

sensitive-word-131

初步驗證

自己本地用 v0.27.1 驗證了一下，確實很奇怪，第一次明顯很慢。

為了排除一些干擾項，我們把一些配置先關閉。

最簡單的我們用 System.nanoTime 輸出一下耗時，用 mills 也行。

public static void main(String[] args) {final List<String> allWord = Arrays.asList("敏感","最強","定制", "81", "醫療器械");String demo1 = "產品尺寸參數§60mn§50mm§210枚/包§160枚/包§名稱A4銀色不干膠§規格60mm*40mm 送配套模板§規格70mm*50mm 送配套模板§數量每大張21枚一包10張總計210枚§數量每大張16枚一包10張總計160枚§適用激光打印機打印油性筆書寫§95mm§100mn§55mm§100枚/包§80枚/包§名稱 A4銀色不干膠§規格95mm*55mm 送配套模板§規格100mm*70mm 送配套模板§數量每大張10枚一包10張總計100枚§數量 每大張8枚一包10張 總計80枚§100mm§120枚/包§140枚/包§規格80mm*50mm 送配套模板§規格100mm*40mm 送配套模板§數量每大張12枚一包10張總計120枚§數量§每大張14枚包10張總計140枚§適用 激光打印機打印油性筆書寫§40mm§65mm§70mm§35mm§200枚/包§240枚/包§規格70mm*40mm送配套模板§規格§65mm*35mm 送配套模板§數量 每大張20枚一包10張總計200枚§每大張24枚包10張總計240枚§適 激光打印機打印油性筆書寫§適用§激光打印機打印油性筆書寫§40mn§280枚/包§360枚/包§規格50mm*40mm 送配套模板§規格40mm*30mm 送配套模板§數量每大張28枚一包10張總計280枚§數量每大張36枚一包10張總計360枚§45.7mm§38.1mm§400枚/包§650枚/包§45.7mm*25.4mm送配套模板§38.1mm*21.2mm 送配套模板§每大張40枚一包10張總計400枚§數量每大張65枚一包10張總計650枚§30mm§25mr§20mm§840枚/包§1260枚/包§規格 30mm*20mm 送配套模板§規格25mm*13mm 送配套模板§數量每張84枚包10張總計840枚§數量每大張126枚一包10張總計1260枚§46mm§意制§任§1000枚/包§定§名稱定制A4內割銀不膠§規格46mm*11.1mm送配套模板§任意規格定制§每大張100枚包10張總計1000枚§包10張滿5包送專屬模板§適激光打印機打印油性筆書寫§產品實拍§8格打印實拍展示(100mm*70mm)§上海薺騫文化用品固定資產標識卡§資產編號：§規格型號：§資產名稱：§使用狀態：§資產類別：§資產原值§存放地點§生產廠家：§使用人§備§注：§*請愛護公司財產，不要隨意撕毀此標簽§16格全內容打印實拍展示§固定資產標識卡§資產名稱§四層貨架（平板）§資產編號§3F跑菜區§規格型號§1800×500×1500§使用部門§財務部§使用時間§2019-04-26§李強§21格手寫款打印展示 (60mm*40mm)§固定資標識卡§36格打印實拍展示(40mm*30mm)§固定資產標簽§名稱:§編號:§部門:§40格打印實拍展示(45.7mm*25.4mm)§固定資§名稱：電腦§編號：20210§部門：財務部§20210201§使用人：我最強§八：找最強§編號：20210201§65格打印實拍展示(38mm*21mm)§名稱：§編號：§數量：§數量:§100格打印實拍展示(46mm*11.1mm)§客服電話：159 9569 3815§: 159 9569 3815§.§客服電話：159 9569§客服電話：1599§客服電話§服電話：159 9569 3815§話：159 9569 3815§客服電話：1599569 3815§電話：159 9569 3815§9569 3815§159 9569 3815§客服電話：§低值易耗品標識牌(70mm*50mm)§購買日期§保管部門§責任人§生產廠家§不要隨意撕毀此標牌*§*請愛護公司財產，不要隨意撕導§品標識牌§低值易耗品標識牌§隨意撕毀此標牌*§*請愛護公司財產，不要隨意撕毀此標牌*§三人沙發§行政酒廊§2200*860*900§2018-07-23§應用范圍§多用于產品信息固有資產登記航空倉庫管理 醫療政府機構等§Mainly used for product information inherent assets registration, aviation warehouse management, medi§cal government institutions, etc§政府單位§企業辦公§倉儲行業§醫療器械§教育單位§耐用品§電子產品包裝§商城賣場";// 初始化敏感詞庫SensitiveWordBs sensitiveWordBs = SensitiveWordBs.newInstance().wordFailFast(true).wordAllow(WordAllows.empty()).wordDeny(new IWordDeny() {@Overridepublic List<String> deny() {return allWord;}}).ignoreChineseStyle(false).ignoreCase(false).ignoreEnglishStyle(false).ignoreNumStyle(false).ignoreRepeat(false).ignoreWidth(false).wordTag(WordTags.none()).init();costTimeTest(sensitiveWordBs, demo1);}private static void costTimeTest(SensitiveWordBs sensitiveWordBs, String demo1) {int count = 5;for (int i = 0; i < count; i++) {long startTime = System.nanoTime();List<String> emitWord1 = sensitiveWordBs.findAll(demo1);long costTime = System.nanoTime() - startTime;System.out.println("cost=" + costTime);}}

輸出：

cost=27687800
cost=3623000
cost=2764000
cost=4456500
cost=6652700

這里是納秒，看比例也看得出第一次比較慢。

long ns = 1_000_000_000L;  // 1 秒 = 1e9 納秒
long us = 1_000_000L;      // 1 秒 = 1e6 微秒
long ms = 1_000L;          // 1 秒 = 1e3 毫秒

排除問題

確認了問題之后，就要找到到底慢在哪里。

有一些方法：

1）每個方法加耗時日志，適用性廣，但是比較麻煩。如果沒有源代碼的話，也無法直接修改。

2） 用 Profiling 工具更方便一些。

Java Flight Recorder (JFR)（JDK 自帶，jcmd 或 jfr 啟動）

VisualVM（免費 GUI，適合初步分析）

Async Profiler + 火焰圖（性能瓶頸定位神器）

YourKit / JProfiler（商業工具，功能更全）

初步猜想

一些初步的猜想：

1. 第一次執行，初始化加載了一些信息比較慢。

2. 后續執行被 jvm 編譯優化了，性能提升。

3. 因為后續執行耗時明顯下降，一些場景的比如 IO、鎖之類的可以暫時排除。

idea 中使用 profile

說明

本地使用的是 idea 免費社區版本。

IDEA Ultimate

IDEA Ultimate 自帶了對 Java Flight Recorder (JFR) 的支持。啟動應用時，點 Run → Profile…，選擇 Java Flight Recorder。

IDEA + Async Profiler 插件

IDEA 提供了 Async Profiler 集成（從 2020.3 開始支持）。

用法：右鍵 Run 旁邊選擇 Profile with Async Profiler。

輸出直接是 火焰圖，更直觀地看哪一層方法耗時最多。

當然，這兩個方法直接用用一個不足，那就是前面的初始化信息也會被記錄，有一定的干擾性。

所以需要次數多一些，比如1W次

編碼 profile

JDK 11+ 提供了 jdk.jfr API，可以在代碼里手動控制錄制

import jdk.jfr.Recording;
import java.nio.file.Path;public class JFRDemo {public static void main(String[] args) throws Exception {try (Recording recording = new Recording()) {recording.start();// 運行你要分析的代碼MyUtil.someMethod();recording.stop();recording.dump(Path.of("app.jfr")); // 保存到文件}}
}

我們略微調整

   private static void costTimeTest(SensitiveWordBs sensitiveWordBs, String demo1) throws IOException {int count = 5;try (Recording recording = new Recording()) {recording.start();for (int i = 0; i < count; i++) {long startTime = System.nanoTime();List<String> emitWord1 = sensitiveWordBs.findAll(demo1);long costTime = System.nanoTime() - startTime;System.out.println("cost=" + costTime);}recording.stop();recording.dump(Path.of("app.jfr")); // 保存到文件}}

執行后可以看到根目錄下 app.jfr，發現這個生成 jfr 有問題。

jfr 文件如何文件如何打開分析呢？

jmc

JDK 11+ 一般自帶 JMC（或者單獨下載安裝 JMC）

jmc 然后選擇打開，發現自己的 jdk11 并沒有，應該和 jvisual 一樣，后續被單獨拆開了。

官網下載： https://www.oracle.com/java/technologies/jdk-mission-control.html

或者 OpenJDK 社區版的 JMC： https://github.com/openjdk/jmc

下載后直接運行 JMC GUI，然后打開 .jfr 文件進行分析。

下載

可以在 https://www.oracle.com/java/technologies/javase/products-jmc9-downloads.html 頁面選擇合適自己的安裝包。

firefox profiler

看了一下 Async Profiler 用的應該就是 https://profiler.firefox.com/ 這個頁面分析文件的。

如果可以的話，你也可以直接用這個網頁。

可以選擇本地的 JFR 文件，或者是 URL。

整體耗時優化

1萬次

這是一個循環調用 1W 次的例子，可以看到整體的耗時：

可以直接打開這個鏈接查看： https://share.firefox.dev/4lZljPd

整體耗時：7890ms

        long time = System.currentTimeMillis();costTimeTest(sensitiveWordBs, demo1);long cTime = System.currentTimeMillis() - time;System.out.println("---DONE"+cTime);

慢的點

可以看到比較慢的2個點

1. String.toCharArray(): char[] 54%

2. InnerWordFormatUtils.formatCharsMapping(String, IWordContext): Map 11%

優化方案

針對1，我們嘗試優化一下，toCharArray 看 String 源碼會重新創建 chars，占用內存，我們盡可能的避免。

    /*** Converts this string to a new character array.** @return  a newly allocated character array whose length is the length*          of this string and whose contents are initialized to contain*          the character sequence represented by this string.*/public char[] toCharArray() {return isLatin1() ? StringLatin1.toChars(value): StringUTF16.toChars(value);}

針對2，用 char[] 數組替代肯定是最好的，但是字符比較復雜，暫時還是 map 適用性更強。

如果不指定格式轉換，可以考慮 map 為空，取不到用原始值，減少這一份消耗。

InnerWordFormatUtils.formatCharsMapping(String, IWordContext): Map 優化

優化方案：新增一個針對整體字符串 format 的處理類 IWordFormatText，如果 IWordFormat 是系統默認的 none，直接返回 emptyMap

限制場景：僅針對不做任何優化的場景有作用。

內存優化：只有映射 c 和 mc 不同，才放入映射 map

實現:

/*** 默認實現** @author d* @since 0.28.0*/
public class WordFormatTextDefault extends AbstractWordFormatText {@Overrideprotected Map<Character, Character> doFormat(String text, IWordContext context) {// 單個字符串里信息final IWordFormat wordFormat = context.wordFormat();// 不需要處理的場景if(wordFormat.getClass().getName().equals(WordFormatNone.class.getName())) {return Collections.emptyMap();}Map<Character, Character> map = new HashMap<>();for(int i = 0; i < text.length(); i++) {char c = text.charAt(i);char mc = wordFormat.format(c, context);if(c != mc) {map.put(c, mc);}}return map;}}

JFR 對比效果：JFR 為 7571

嚴謹起見，我們加一下額外項目的測試對比，對比5次

v0.27.1 直接運行1W次，5 次均值：7255 ，明細如下：

7613
7166
7156
7176
7164

新代碼直接運行1W次，均值 7139.4，明細如下：

7650
7074
7002
6979
6992

看來這個 cpu 火焰圖和時間耗時不是嚴格等價。

這里只提升了 1% 左右的性能。

罷了，看在內存的面子上，我們先發布一個版本。

發布

此代碼發布，放在 v0.28.0 版本。

針對 toCharArray 的改進

思路

我們盡量避免 toCharArray，使用原始的字符串 string.charAt 替代。

不過這個 charAt 有一點不太好：

public char charAt(int index) {if ((index < 0) || (index >= value.length)) {throw new StringIndexOutOfBoundsException(index);}return value[index];
}

如果 jdk 能提供一個直接訪問的方法將完美，可惜去不得。

好處

帶來的好處就是節省了 toCharArray 帶來的方法+內存消耗。

修改點

修改點比較多，涉及到的地方夠改掉了。

遺憾的是破壞了兩個帶 chars 的接口，接口本身設計的不夠好。

ISensitiveWordCharIgnore 和 IWordReplace

從原始的 chars->text

效果

新代碼，同樣1w次循環，耗時 508.8ms，明細：

792
456
449
410
437

和 v0.28.0 對比提升了多少倍呢？大概 14 倍

7139.4 ÷ 508.8 ≈ 14.03

反思

這個大概率是每次 case 都一樣，導致 jvm 優化效果很不錯。

隨機測試

我們來用隨機，對比測試一下

測試 CASE

    public static void main(String[] args) {for(int k = 0; k < 5; k++) {// 1W 次long start = System.currentTimeMillis();for(int i = 0; i < 10000; i++) {String randomText = "產品尺寸參數§60mn§50mm§210枚/包§160枚/包§名稱A4銀色不干膠§規格60mm*40mm 送配套模板§規格70mm*50mm 送配套模板§數量每大張21枚一包10張總計210枚§數量每大張16枚一包10張總計160枚§適用激光打印機打印油性筆書寫§95mm§100mn§55mm§100枚/包§80枚/包§名稱 A4銀色不干膠§規格95mm*55mm 送配套模板§規格100mm*70mm 送配套模板§數量每大張10枚一包10張總計100枚§數量 每大張8枚一包10張 總計80枚§100mm§120枚/包§140枚/包§規格80mm*50mm 送配套模板§規格100mm*40mm 送配套模板§數量每大張12枚一包10張總計120枚§數量§每大張14枚包10張總計140枚§適用 激光打印機打印油性筆書寫§40mm§65mm§70mm§35mm§200枚/包§240枚/包§規格70mm*40mm送配套模板§規格§65mm*35mm 送配套模板§數量 每大張20枚一包10張總計200枚§每大張24枚包10張總計240枚§適 激光打印機打印油性筆書寫§適用§激光打印機打印油性筆書寫§40mn§280枚/包§360枚/包§規格50mm*40mm 送配套模板§規格40mm*30mm 送配套模板§數量每大張28枚一包10張總計280枚§數量每大張36枚一包10張總計360枚§45.7mm§38.1mm§400枚/包§650枚/包§45.7mm*25.4mm送配套模板§38.1mm*21.2mm 送配套模板§每大張40枚一包10張總計400枚§數量每大張65枚一包10張總計650枚§30mm§25mr§20mm§840枚/包§1260枚/包§規格 30mm*20mm 送配套模板§規格25mm*13mm 送配套模板§數量每張84枚包10張總計840枚§數量每大張126枚一包10張總計1260枚§46mm§意制§任§1000枚/包§定§名稱定制A4內割銀不膠§規格46mm*11.1mm送配套模板§任意規格定制§每大張100枚包10張總計1000枚§包10張滿5包送專屬模板§適激光打印機打印油性筆書寫§產品實拍§8格打印實拍展示(100mm*70mm)§上海薺騫文化用品固定資產標識卡§資產編號：§規格型號：§資產名稱：§使用狀態：§資產類別：§資產原值§存放地點§生產廠家：§使用人§備§注：§*請愛護公司財產，不要隨意撕毀此標簽§16格全內容打印實拍展示§固定資產標識卡§資產名稱§四層貨架（平板）§資產編號§3F跑菜區§規格型號§1800×500×1500§使用部門§財務部§使用時間§2019-04-26§李強§21格手寫款打印展示 (60mm*40mm)§固定資標識卡§36格打印實拍展示(40mm*30mm)§固定資產標簽§名稱:§編號:§部門:§40格打印實拍展示(45.7mm*25.4mm)§固定資§名稱：電腦§編號：20210§部門：財務部§20210201§使用人：我最強§八：找最強§編號：20210201§65格打印實拍展示(38mm*21mm)§名稱：§編號：§數量：§數量:§100格打印實拍展示(46mm*11.1mm)§客服電話：159 9569 3815§: 159 9569 3815§.§客服電話：159 9569§客服電話：1599§客服電話§服電話：159 9569 3815§話：159 9569 3815§客服電話：1599569 3815§電話：159 9569 3815§9569 3815§159 9569 3815§客服電話：§低值易耗品標識牌(70mm*50mm)§購買日期§保管部門§責任人§生產廠家§不要隨意撕毀此標牌*§*請愛護公司財產，不要隨意撕導§品標識牌§低值易耗品標識牌§隨意撕毀此標牌*§*請愛護公司財產，不要隨意撕毀此標牌*§三人沙發§行政酒廊§2200*860*900§2018-07-23§應用范圍§多用于產品信息固有資產登記航空倉庫管理 醫療政府機構等§"+ RandomUtil.randomString("1234567890bcdefghiJKLMNOPQRSTUVWXYZ", 100);SensitiveWordHelper.findAll(randomText);}long end = System.currentTimeMillis();System.out.println(end-start);}}

新代碼

實際測試發現這個在文本長的時候，效果更顯著。應該是 toCharArray 的代價更高

5次均值 1785.2：

2308
1621
1595
1664
1738

v0.28.0

5 次均值：7636.4

8438
7463
7404
7436
7441

總結

這個測試文本量，效果大概提升 4 倍

文本越長，效果越顯著。

查看一次耗時

說明

無論是整體跑，還是單個跑，都會發現第一次明顯比較慢。

多次跑應該是 jvm 優化，我們來看一下單詞的

我們回到問題的最開始，看的出來平均耗時優化了，但是初始化耗時還是這么慢。

跑5次

5 次效果如下：

21
1
1
1
1

單詞跑有個問題，前面的 wordBs 初始化干擾太大，我們暫時用加耗時的方法來處理下。

第二個問題：mills 不夠精確，可以用 nanoTime 替代。

我們改為 nanoTime 跑5次

看起來 ms 差不多，實際上還是差很多的。

13518800
2854600
1836900
1503900
925400

我們重點看一下第一次為什么這么慢。

子方法耗時拆分

演示一下，二分法：

public <R> List<R> findAll(final String target, final IWordResultHandler<R> handler) {
//        ArgUtil.notNull(handler, "handler");long s1 = System.nanoTime();List<IWordResult> wordResults = sensitiveWord.findAll(target, context);System.out.println(System.nanoTime()-s1);long s2 = System.nanoTime();List<R> res = CollectionUtil.toList(wordResults, new IHandler<IWordResult, R>() {@Overridepublic R handle(IWordResult wordResult) {return handler.handle(wordResult, context, target);}});System.out.println(System.nanoTime()-s2);return res;}

耗時：

17042800  #findAll2316800  #handle
22018600  #total

不過有一個問題，這個不太穩定。只能看比例。

很離譜的一個點：

中間只隔了下面的方法，耗時 3ms。

public List<String> findAll(final String target) {return findAll(target, WordResultHandlers.word());
}

原因

所以第一次請求，涉及到了

JVM 類和方法還沒加載：第一次調用 sensitiveWord.findAll 可能會觸發類加載、靜態初始化。

JIT（即時編譯）沒起作用：第一次運行是解釋執行，速度慢。

熱點優化沒完成：JIT 會把頻繁調用的方法編譯成本地代碼，但需要多次調用才會觸發。

解決方案

其實也不難，可以提前調預熱一下。

在 init() 的時候，指定預熱策略，簡單的觸發一下。

避免不太懂的性能測試的伙伴執著于第一次的問題。

策略支持用戶自定義。

效果

優化后的效果，還是會有一些，不過可以接受。

4520900
2804500
2493600
976000
1011100

和 v0.28.0 對比

20762000
3903400
3401200
8672000
7852000

第一次峰值從 20ms=>5ms 左右。

反思

jvm 的內置優化過于強求暫時意義不大，還是推薦性能壓測先做預熱。

小結

性能優化是一個支持以恒的過程，每次的改動都可能會導致性能有所影響。

這個系列后續更新了幾個版本，感興趣的小伙伴可以看一下：

v0.28.0+v0.29.0 敏感詞性能優化值本地方法調用為何這么慢?

v0.29.1 敏感詞性能優化-0.29.1-內部類+迭代器內部類

v0.29.2 基本類型拆箱、裝箱的進一步優化的嘗試

v0.29.3 依賴的繁簡體轉換 opencc4j 優化