Categories
程式開發

日誌收集系統在大搜車的探索和實踐


引言

大搜車日誌分為兩種:業務日誌和鏈路日誌。

業務日誌是業務開發人員在代碼裡面自己打印的日誌,為方便開發人員快速查閱分佈在多台機器上的日誌,我們提供了業務日至平台,供開發自助接入。目前接入的系統400+,每天產生的日誌量7億+,高峰時期每秒要處理5W+的日誌。

鏈路日誌對應的則是鏈路追踪平台(trace),通過traceID把跨系統調用的所有下游系統串聯起來,想要了解詳細的話可以參考開源的pinpoint。鏈路日誌每天日誌量30億+,高峰每秒要處理8W+的日誌。我們只保留七天的數據,大概45T。

開源社區有很多優秀的日誌收集組件,如logkit,logstack,flume等。我們公司因為早前就在其它場景下使用過flume,運維同學也積累了豐富的運維經驗,所以採集組件直接使用的flume。個人感覺而已,logkit和logstack更輕量,作為採集端更合適~

下面開始進入正題,介紹下我們的整體架構以及遇到的坑,還有就是根據自身的業務特點做的特殊優化~

整體架構圖

日誌收集系統在大搜車的探索和實踐 1

詳細說明

如上圖所示,整體上分為四個模塊:日誌採集,日誌處理,日誌存儲以及展示和應用,下面開始詳細介紹每個模塊。

日誌採集

日誌採集最大的難題就是業務日誌在機器山存放的路徑以及文件名稱並不統一(運維最開始沒有製定標準),而且日誌格式和滾動策略等都是業務開發人員自己配置的。所以接入我們的系統需要使用方自己錄入日誌存放目錄以及通過 正則表達式 指定日誌格式(如下圖)。配置好日誌目錄和格式,系統會把這些配置推送給flume(開源版本不支持該推送配置的功能,我們修改了開源版本使其支持),日誌採集就開始了。

日誌收集系統在大搜車的探索和實踐 2

第一步我就遇到了一個大坑,先說現象:有的應用莫名其妙的最新日誌就收集不上來了,登錄到機器上查看,發現採集進程還在,用top命令查看,發現日誌採集進程佔用cpu達到100%

cpu100%問題排查我就不詳訴了,可以點超鏈接自行查看。通過線程堆棧,可以看到是正則表達式在搞鬼。這裡需要引入正則表達式的執行原理:

傳統的NFA引擎運行所謂的“貪婪的”匹配回溯算法(longest-leftmost),以指定順序測試正則表達式的所有可能的擴展並接受第一個匹配項。傳統的NFA回溯可以訪問完全相同的狀態多次,在最壞情況下,它的執行速度可能 非常慢,但它 支持子匹配。代表性有:GNU Emacs,Java,ergp,less,more,.NET語言, PCRE library,Perl,PHP,Python,Ruby,sed,vi等,一般高級語言都採用該模式。

在通過下面這個實例理解下:

源字符DEF,匹配正則表達式是:/Dw+F/
匹配開始:
第一步,/D 正確匹配到D,而w+會貪婪的匹配最長的字符串,也就是 EF。然後F因為匹配不到任何字符,導致匹配失敗。
第二步,因為上面的匹配失敗了,回溯算法往後退一位, /D 正確匹配到D,而w+ 匹配到 E,F匹配到 F,匹配成功。

上面的例子因為源字符串比較短,正則表達式也不復雜,所以只回溯了一次。但是我們的真實場景一條業務日誌長度幾百設置上千,而用戶寫的正則可能不止 有w+,還會有.+ 等等。所以這也就造成了上面的問題,最新日誌收集不上來(解析日誌耗費的時間太長了),而且CPU100%(因為一直在運算,並不是卡住)。

明確了問題直接上解決方案吧,不想鋪墊了。 。 。

第一步就是要快速失敗,如果解析一條日誌超過100ms,就應該把它歸類為解析失敗,繼續後面的日誌處理。所以可以把日誌解析丟到異步線程池中,主線程通過拿到的Future控制超時時間。

第二步就是如果超時了,要能夠中斷正在匹配的正則表達式。這個時候遇到的問題是正則表達式本身是不響應中斷,不過好在天無絕人之路,觀察發現正則表達式源字符串要求傳入的類型是 CharSequence,而每次回溯時,都會調用charAt方法,所以可以通過創建一個新的類,實現 CharSequence,並且在charAt中判斷是否被中斷。這樣的話,就可以讓正則表達式的解析過程響應中斷了~~,CharSequence 實現類代碼如下

public class InterruptibleCharSequence implements CharSequence {

    CharSequence inner;

    public InterruptibleCharSequence(CharSequence inner) {
        super();
        this.inner = inner;
    }

    @Override
    public char charAt(int index) {
        if (Thread.currentThread().isInterrupted()) {
            throw new RuntimeException("Interrupted!");
        }
        return inner.charAt(index);
    }

    @Override
    public int length() {
        return inner.length();
    }

    @Override
    public CharSequence subSequence(int start, int end) {
        return new InterruptibleCharSequence(inner.subSequence(start, end));
    }

    @Override
    public String toString() {
        return inner.toString();
    }
}

日誌處理

所有機器上的flume採集程序,收集到的日誌會先上報給單獨搭建的flume代理層集群,這是因為運維不希望太多的機器直連kaka。代理層沒有做任何處理,直接把日誌丟到kafka。

kafka的性能和穩定性是經過歷史驗證的,所以選它作為中間緩存層沒什麼爭議。當然,其它的mq也更有優勢,可以根據公司技術棧靈活選擇。像號稱下一代的mq:pulsar我們也打算調研試用下~

為什麼不直接寫後端的ES呢?這是因為需要緩衝層來削峰填谷,可能有點抽象,舉個實際的例子,我們的業務高峰期,日誌的產生速度高於ES的寫入速度。業務系統那邊基本都會配置了日誌文件翻滾,這樣就有可能造成還沒來得及收上來的日誌被沖掉了。

kafka後面掛的是flink集群,上面跑了四個job:

業務日誌Job:負責存儲業務日誌

鏈路日誌的Job:負責存儲鏈路日誌

監控報表的Job: 主要是統計一些指標,如qps,錯誤率等等,利用到了flink的窗口

報警中心的Job​​:業務日誌可以根據用戶自定義的報警規則報警,而鏈路日誌則可以對框架層面的超時,錯誤報警,如dubbo調用超時~

日誌存儲

日誌存儲主要是把數據寫入ES,單獨來講是因為不同的產品存儲方式不同。這塊也是整個系統最大的短板,為了優化寫入做了很多工作。

業務日誌存儲

首先分析下業務日誌的場景,大家基本上只查看自己應用的日誌,痛點是可能分佈在不同的機器上,經常使用的姿勢是根據關鍵字全文匹配。而且以前使用kibana的時候,因為分詞導致查詢出來的結果不精確很不爽。

針對這個特點,我們設計的後端存儲方式是:每個應用每天一個索引,同時創建索引的時候通過MappingTemplate禁用掉分詞。

優缺點: 這是設計方式是面向單應用查詢的,所以查詢速度比較快,而且是全文匹配的暴力查詢,用戶體驗比較好。但是也導致了ES集群中索引的數量過多,會多佔用一些內存。

還有一個小坑,是關於限流功能的。我們想實現的功能是,針對打日誌特別多的應用,比如說一天打幾千萬條的日誌,超過閾值就自動限流該應用,後面的日誌就不採集了。統計應用每天的日誌量,是放在flink集群做的,但是實際應用中發現,當flink統計到某個應用採集量已經達到上限,比如說1000W,想要限流已經為時已晚,因為這時候這個應用可能已經有5000W日誌堆在kafka了。  也就是說,在flink集群統計有嚴重的滯後性,後來我們又在flume採集的時候增加了單機限流。

鏈路日誌存儲

鏈路日誌的數據量特別龐大,同時因為經常需要跨系統查詢,所以不能按照系統的維度建索引。不過相對於業務日誌,因為都是框架層面打印的,所以格式是統一的。針對這種特點,按照每小時建一個索引,保證索引數據量不會太大。 Mapping策略上,也是禁用分詞,提前解析出(應用,路徑,環境,線程)字段,讓ES索引起來。這樣用戶在界面上根據這些字段過濾就會有比較好的性能表現。

其它的寫入性能優化

在接入量快速增長的階段,ES首先扛不住了,寫入性能無法滿足快速增長的日誌量。雖然可能通過加機器緩解問題,但成本也要控制,所以優化ES寫入性能迫在眉睫,下面列出的是實踐過程中最有效的方式,其它的可以自行百度~

  • 增大刷盤時間(refresh_interval):默認是1s,我們時間過程中調到了5s。調大之後寫入性能上升還是比較明顯的,帶來的問題是日誌寫入5s之後才能被查詢到,不過5s延遲延遲業務上是完全可以接受的。
  • 0備份並且關掉事務日誌(“durability”: “async”):這個對寫入性能的提高是大幅度的,幾乎是兩倍的提升,我們的集群最高可以寫到15W+。但是問題是無法保證可靠性,萬一掛了怎麼辦?  我們的解決方式是kafka保存12小時的數據+低峰期(晚上)備份。  首先kafka保存12小時的數據保證了即使flink掛了或者ES掛了,都可以通過重置消費位點把數據找回來。晚上備份的話,保證了十二小時之前的數據就不會丟了
  • 提前創建索引:業務日誌每到晚上零點的時候,都會堆積數據。這是因為這個時候在大量的創建索引,寫入速度自然受影響。解決思路就是提前把索引創建好
  • 第三方冪等:首先說明這個我還沒嘗試過,因為現在寫入性能夠了,就沒怎麼在折騰,思路寫出來供大家參考。  我們為了防止ES數據重複寫入,是通過指定id的方式實現了冪等。這個對ES性能消耗還是比較大的(大概15%)。並且index的數據規模越大,性能越低,因為它要判斷這個id是否已經存在。  如果把這個冪等控制拿到外面去做,讓ES直接存就好了,性能肯定有進一步提升

日誌應用

日誌展示

可以根據關鍵字或者過濾條件快速搜索日誌,免去了登錄多台機器的麻煩

日誌收集系統在大搜車的探索和實踐 3

日誌報警

把查詢條件設置為報警規則,如下圖,10分鐘類日誌中出現Exception關鍵字,次數大於1次,將觸發報警。技術實現是通過flink,擴展窗口機制,實現了動態窗口(有時間這塊可以詳細寫下)。

日誌收集系統在大搜車的探索和實踐 4

數據大盤

基於trace日誌形成的數據大盤,QPS、耗時百分位圖等信息,詳細可以看另一片文章。