從零開始搞監控系統(2)——存儲和分析

一、存儲

  在將數據傳送到後台之前,已經做了一輪清洗工作,如果有需要還可以再做一次清洗。

  日誌表如下所示,自增的 id 直接偷懶使用了 bigint,沒有採用分表等其他技術。

CREATE TABLE `web_monitor` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `project` varchar(45) COLLATE utf8mb4_bin NOT NULL COMMENT '項目名稱',
  `digit` int(11) NOT NULL DEFAULT '1' COMMENT '出現次數',
  `message` text COLLATE utf8mb4_bin NOT NULL COMMENT '聚合資訊',
  `ua` varchar(600) COLLATE utf8mb4_bin NOT NULL COMMENT '代理資訊',
  `key` varchar(45) COLLATE utf8mb4_bin NOT NULL COMMENT '去重用的標記',
  `category` varchar(45) COLLATE utf8mb4_bin NOT NULL COMMENT '日誌類型',
  `source` varchar(45) COLLATE utf8mb4_bin DEFAULT NULL COMMENT 'SourceMap映射文件的地址',
  `ctime` timestamp NULL DEFAULT CURRENT_TIMESTAMP,
  `identity` varchar(20) COLLATE utf8mb4_bin DEFAULT NULL COMMENT '身份,用於連貫日誌上下文',
  `day` int(11) DEFAULT NULL COMMENT '格式化的天(冗餘欄位),用於排序,20210322',
  `hour` tinyint(2) DEFAULT NULL COMMENT '格式化的小時(冗餘欄位),用於分組,11',
  `minute` tinyint(2) DEFAULT NULL COMMENT '格式化的分鐘(冗餘欄位),用於分組,20',
  `message_status` int(11) DEFAULT NULL COMMENT 'message中的通訊狀態碼',
  `message_path` varchar(45) COLLATE utf8mb4_bin DEFAULT NULL COMMENT 'message通訊中的 path',
  `message_type` varchar(20) COLLATE utf8mb4_bin DEFAULT NULL COMMENT 'message中的類別欄位',
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin COMMENT='前端監控日誌';

  在正式上線後,遇到了幾次慢查詢,阿里雲給出了相關索引建議,後面就直接加上了,效果立竿見影。

1)堆棧壓縮

  對於數據量很大的公司,像下面這樣的堆棧內容消耗的存儲空間是非常可觀的,因此有必要做一次壓縮。

  例如將重複的內容提取出來,用簡短的標識進行替代,把 URL 被替換成了 # 和數字組成的標識等。

{
  "type": "runtime",
  "lineno": 1,
  "colno": 100,
  "desc": "Uncaught Error: Cannot find module \"./paramPathMap\" at //localhost:8000/umi.js:248565:7",
  "stack": "Error: Cannot find module \"./paramPathMap\"
    at Object.<anonymous> (//localhost:8000/umi.js:248565:7)
    at __webpack_require__ (//localhost:8000/umi.js:679:30)
    at fn (//localhost:8000/umi.js:89:20)
    at Object.<anonymous> (//localhost:8000/umi.js:247749:77)
    at __webpack_require__ (//localhost:8000/umi.js:679:30)
    at fn (//localhost:8000/umi.js:89:20)
    at Object.<anonymous> (//localhost:8000/umi.js:60008:18)
    at __webpack_require__ (//localhost:8000/umi.js:679:30)
    at fn (//localhost:8000/umi.js:89:20)
    at render (//localhost:8000/umi.js:73018:200)
    at Object.<anonymous> (//localhost:8000/umi.js:73021:1)
    at __webpack_require__ (//localhost:8000/umi.js:679:30)
    at fn (//localhost:8000/umi.js:89:20)
    at Object.<anonymous> (//localhost:8000/umi.js:72970:18)
    at __webpack_require__ (//localhost:8000/umi.js:679:30)
    at //localhost:8000/umi.js:725:39
    at //localhost:8000/umi.js:728:10"
}

  考慮到我所在公司的數據量不會很大,人力資源也比較緊張,為了儘快上線,所以沒有使用壓縮,後期有時間了再來優化。

2)去除重複

  雖然沒有做壓縮,但是對於相同的日誌還是做了一次去重操作。

  去重規則也很簡單,就是將項目 token、日誌類別和日誌內容拼接成一段字元串,再用MD5加密,下面是 Node.js 程式碼。

const key = crypto.createHash("md5").update(token + category + message).digest("hex");

  將 key 作為條件判斷資料庫中是否存在這條記錄,若存在就給 digit 欄位加一。

  

  在正式上線後,每次在添加日誌時都要做這層判斷,一度將資料庫阻塞掉。因為每次在做 key 判斷時要全表查詢一次,舊的查詢還沒執行完,新的就來了。

  為了解決此問題,就加上了一個基於 Redis 的隊列:Kue,將判斷、更新和插入的邏輯封裝到一個任務中,非同步執行。注意,目前此庫已經不維護了,首頁上推薦了替代品:Bull

  再加上索引,雙重保障後,現在接收日誌時未出現問題。

二、分析

  目前的分析部分也比較簡單,只包括一個監控看板、趨勢分析、日誌列表和定時任務等。

1)監控看板

  在監控看板中包含今日數據和往期趨勢折線圖,本來想用 EChart.js 作圖,不過後面集成時出了點問題,並且該庫比較大,要500KB以上,於是換了另一個更小的庫:Chart.js,只有60KB。

  今日數據有今日和昨日的日誌總數、錯誤總數和影響人數,通訊、事件、列印和跳轉等總數。

  

  其中錯誤總數會按照 category:”error” 的 sum(digit) 來求和,而影響人數只會按照記錄的個數來計算。

  今日的數量是實時計算的,在使用中發現查詢特別慢,要好幾分鐘才能得到結果,於是為幾個判斷條件中的欄位加了個二級索引後(例如為 ctime 和 category 加索引),就能縮短到幾秒鐘響應。

ALTER TABLE `web_monitor` ADD INDEX `idx_category_ctime` (`category`, `ctime`);

SELECT count(*) AS `count` FROM `web_monitor` 
WHERE (`ctime` >= '2021-03-25 16:00:00' AND `ctime` < '2021-03-26 16:00:00') 
AND `category` = 'ajax';

  在往期趨勢中,會展示錯誤、500、502 和 504 錯誤、日誌總數折線圖,這些數據會被保存在一張額外的統計表中,這樣就不必每次實時計算了。折線的顏色值取自 AntDesign

  計算了一下出現 504 的通訊佔全部的 0.2%,接下來需要將這個比例再往下降。

 

  

  在看板中,展示的錯誤日誌每天在七八千左右,為了減少到幾百甚至更低的範圍,可採取的措施有:

  • 過濾掉無意義的錯誤,例如SyntaxError: Unexpected token ‘,’,該錯誤佔了 55%~60% 左右。
  • 優化頁面和介面邏輯,504通訊錯誤佔了25%~30% 左右。
  • 將這兩個大頭錯誤搞定,再針對性優化剩下的錯誤,就能將錯誤控制目標範圍內。

  從日誌中可以查看到具體的介面路徑,然後就能對其進行針對性的優化。

  例如有一張活動頁面,在進行一個操作時會請求兩個介面,並且每個介面各自發送 3 次通訊,這樣會很容易發生 504 錯誤(每天大約有1500個這樣的請求),因此需要改造該邏輯。

  首先是給其中一張表加索引,然後是將兩個介面合併成一個,並且每次返回 20 條以上的數據,這樣就不用頻繁的發起請求了。

  經過改造後,每日的 504 請求從 1500 個左右降低到 200 個左右,減少了整整 7.5 倍,效果立竿見影,大部分的 504 集中在 22 點到 0 點之間,這段時間的活躍度比較高。

  還有一個令人意外的發現,那就是監控日誌的量每天也減少了 50W 條。  

2)日誌列表

  在日誌列表中會包含幾個過濾條件:編號、關鍵字、日期範圍、項目、日誌類型和身份標識等。

  如果輸入了關鍵字,那麼會在監控日誌搜索結果列表中為其著色,這樣更便於查看,用正則加字元串的 replace() 方法配合實現的。

  在數據量上去後,當對內容(MYSQL 中的類型是 TEXT)進行模糊查詢時,查詢非常慢,用 EXPLAIN 分析SQL語句時,發現在做全表查詢。

  經過一番搜索後,發現了全文索引(match against 語法),在 5.7.6 之前的 MYSQL 不支援中文檢索,好在大部分情況要搜索的內容都是英文字元。

SELECT * FROM `web_monitor` WHERE MATCH(message) AGAINST('+*test*' IN BOOLEAN MODE)

  在建完這個索引後,表的容量增加了 3G 多,當前表中包含 1400W 條數據。

CREATE FULLTEXT INDEX ft_message ON web_monitor(message)

  有時候還是需要模糊匹配的,所以想了下加個下拉選項,來手動命令後台使用哪種方式的查詢,但如果是模糊匹配,必須選擇日期來縮小查找範圍。

  

  在實際使用時,又發現缺張能直觀展示峰值的圖表,例如我想知道在哪個時間段某個特定錯誤的數量最多,於是又加了個按鈕和柱狀圖,支援跨天計算。

  

  身份標識可以查詢到某個用戶的一系列操作,更容易鎖定錯誤發生時的情境。

  每次查詢列表時,在後台就會通過Source Map文件映射位置,注意,必須得有列號才能還原,並且需要安裝 source-map 庫。

const sourceMap = require("source-map");
/**
 * 讀取指定的Source-Map文件
 */
function readSourceMap(filePath) {
  let parsedData = null;
  try {
    parsedData = fs.readFileSync(filePath, "utf8");
    parsedData = JSON.parse(parsedData);
  } catch (e) {
    logger.info(`sourceMap:error`);
  }
  return parsedData;
}
/**
 * 處理映射邏輯
 */
async function getSourceMap(row) {
  // 拼接映射文件的地址
  const filePath = path.resolve(
    __dirname,
    config.get("sourceMapPath"),
    process.env.NODE_ENV + "-" + row.project + "/" + row.source
  );
  let { message } = row;
  message = JSON.parse(message);
  // 不存在行號或列號
  if (!message.lineno || !message.colno) {
    return row;
  }
  // 打包後的sourceMap文件
  const rawSourceMap = readSourceMap(filePath);
  if (!rawSourceMap) {
    return row;
  }
  const errorPos = {
    line: message.lineno,
    column: message.colno
  };
  // 過傳入打包後的程式碼位置來查詢源程式碼的位置
  const consumer = await new sourceMap.SourceMapConsumer(rawSourceMap);
  // 獲取出錯程式碼在哪一個源文件及其對應位置
  const originalPosition = consumer.originalPositionFor({
    line: errorPos.line,
    column: errorPos.column
  });
  // 根據源文件名尋找對應源文件
  const sourceIndex = consumer.sources.findIndex(
    (item) => item === originalPosition.source
  );
  const sourceCode = consumer.sourcesContent[sourceIndex];
  if (sourceCode) {
    row.sourceInfo = {
      code: sourceCode,
      lineno: originalPosition.line,
      path: originalPosition.source
    };
  }
  // 銷毀,否則會報記憶體訪問超出範圍
  consumer.destroy();
  return row;
}

  點擊詳情,就能在彈框中查看到程式碼具體位置了,編碼著色採用了 highlight.js

  而每行程式碼的行號使用了一個擴展的 highlight-line-numbers.js,柔和的淡紅色的色值是 #FFECEC。

  

  圖中還有個上下文的 tab,這是一個很有用的功能,可以查詢到當前這條記錄前面和後面的所有日誌。

  本以為萬事大吉,但是沒想到在檢索時用模糊查詢,直接將資料庫跑掛了。

  無奈,從伺服器上將日誌數據拉下來,導入本地資料庫中,在本地做查詢優化,2000W條數據倒了整整兩個小時。

  和大數據的同事溝通後,他們說可以引入 ElasticSearch 做檢索功能。當他們看到我的 message 欄位中的內容時,他們建議我先做關鍵字優化。

  就是將我比較關心的內容放到單獨的欄位中,提升命中率,而將一些可變的或不重要的數據再放到另一個欄位中,單純的做存儲。

  例如通訊內容中,我比較關心的是 url 和 status,那麼就將它們抽取出來,並且去除無關緊要的資訊(例如錯誤的 stack、通訊的 headers)給 message 欄位瘦身,最多的能減少三分之二以上。

{
  "type": "GET",
  "url": "/api/monitor/list?category=error&category=script&msg=",
  "status": 200,
  "endBytes": "0.15KB",
  "interval": "22.07ms",
  "network": {
    "bandwidth": 0,
    "type": "3G"
  },
}

  最後決定報表統計的邏輯仍然用 MySQL,而檢索改成 ElasticSearch,由大數據組的同事提供介面,我們這邊傳數據給他們。

  而之前的檢索方式也可以棄用了,MySQL中存儲的日誌數據也從 14 天減少到 7 天。

  在使用過程中遇到了幾個問題:

  • 沒有將所有的數據傳遞到ES庫中,丟失了將近33%的數據,後面排查發現有些數據傳遞到了預發環境,而預發環境中有個參數沒配置導致無法推送。
  • 在檢索時,返回的列表會漏幾條記錄,在一個可視化操作介面中輸入查詢條件可以得到連續的數據。經過排查發現,可能是在後台查詢時,由於非同步隊列的原因,那幾條數據還未推送,這樣的話就會得不到那幾條記錄,導致不連續。

3)定時任務

  每天的凌晨4點,統計昨天的日誌資訊,保存到 web_monitor_statis 表中。

CREATE TABLE `web_monitor_statis` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `date` int(11) NOT NULL COMMENT '日期,格式為20210318,一天只存一條記錄',
  `statis` text COLLATE utf8mb4_bin NOT NULL COMMENT '以JSON格式保存的統計資訊',
  PRIMARY KEY (`id`),
  UNIQUE KEY `date_UNIQUE` (`date`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin COMMENT='前端監控日誌統計資訊表';

  在 statis 欄位中,保存的是一段JSON數據,類似於下面這樣,key 值是項目的 token。

{
  "backend-app": {
allCount: 0, errorCount:
1, errorSum: 1, error500Count: 0, error502Count: 0, error504Count: 1, ajaxCount: 20, consoleCount: 0, eventCount: 0, redirectCount: 0 } }

  還有個定時任務會在每天的凌晨3點,將一周前的數據清除(web_monitor),並將三周前的 map 文件刪除。

  之所以有個時間差是為了避免一周內的數據中還有需要引用兩周前的 map 文件,當然這個時間差還可以更久。

  注意,MySQL中表的數據通過 delete 命令刪除,如果使用的是 InnoDB 存儲引擎,那麼是不會釋放磁碟空間的,需要執行 optimize 語句,例如:

optimize table `web_monitor`

  原先每日的數據量在180W左右,每條數據在 800B 左右,每天佔用空間 1.3G 左右。

  後面優化了請求量,過濾掉重複和無意義的請求後(例如後台每次都要發的身份驗證的請求、活動頁面的埋點請求等),每天的日誌量控制在 100W 左右。

  而在經過上述活動的504優化後,請求量降到了 50W 左右,優化效果很喜人。

  保存 map 文件的空間在100G,應該是妥妥夠的。

  在未來會將監控拓展到小程式,並且會加上告警機制,在合適的時候用郵件、飛書、微信或簡訊等方式通知相關人員,後面還有很多擴展可做。

  敘述的比較簡單,但過程還說蠻艱辛的,修修補補,加起來的程式碼大概有4、5千行的樣子。

 4)服務遷移

  在使用時發現監控日誌的服務比較佔用CPU和記憶體,於是將其單獨抽取做來,獨立部署。

  經過這波操作後,整體的504錯誤,從 800 多漸漸降到了 100 左右。其中有一半的請求是埋點通訊,業務請求降到了有史以來的最低點。

  但CPU和記憶體並沒有按預期下降,這部分涉及到了一次詳細的記憶體泄漏的摸查過程,在下文會詳細分析。

 

參考:

利用sourceMap定位錯誤實踐

螞蟻金服基於堆棧映射快速定位問題

貝貝集團多端錯誤監控平台

MySQL 全文索引實現簡單版搜索引擎