日志解析效率提高 8 倍过程
背景
日志解析服务，需要将服务端上报的日志，解析并投递到对应的日志库中。投递时可以批量，但解析只能针对一条条日志，所以解析的性能至关重要。
日志原文:
[INFO][2021-10-21 17:47:15.074][xxl-job][a57260920d9140cd91ae4f3e5bab0922.293.16348096350130313][][Thread-29][xxx.server.service.PrometheusService][10.2.6.166][172.17.0.239][xxx-server-859bb57fd-lqgjh] prometheus spent: 54 ms, request:{query=[sum(increase(logback_events_total{level=~"error|warn" }[1d] @1634809560 )) by (k8s_app,level) > 0], step=[60]} 复制代码需要转换成：
{ "container_ip": "172.17.0.239", "date": "2021-10-21 17:47:15.074", "level": "INFO", "logger": "xxx.server.service.PrometheusService", "message": "prometheus spent: 54 ms, request:{query=[sum(increase(logback_events_total{level=~"error|warn" }[1d] @1634809560 )) by (k8s_app,level) > 0], step=[60]}", "node_ip": "10.2.6.166", "pod_name": "xxx-server-859bb57fd-lqgjh", "rawLog": "[INFO][2021-10-21 17:47:15.074][xxl-job][a57260920d9140cd91ae4f3e5bab0922.293.16348096350130313][][Thread-29][cn.jojo.infra.bs.monitor.api.server.service.PrometheusService][10.2.6.166][172.17.0.239][bs-monitor-api-server-859bb57fd-lqgjh] prometheus spent: 54 ms, request:{query=[sum(increase(logback_events_total{level=~"error|warn" }[1d] @1634809560 )) by (k8s_app,level) > 0], step=[60]}", "threadName": "Thread-29", "traceId": "a57260920d9140cd91ae4f3e5bab0922.293.16348096350130313", "traceType": "xxl-job" } 复制代码旧函数
旧函数实现如下（可以不用看）：
public void parseLog() { String rawLog = new String(contentByte); Map<String, Object> logMap = generateLogItem(rawLog); if (isReportRawLog) { logMap.put(LOG_FIELD_RAW_LOG, rawLog); } String date = String.valueOf(logMap.get(LOG_FIELD_DATE)); if (date != null) { try { Date logDate = DateUtils.parseDate(date, DATE_PATTERN); time = logDate.getTime(); } catch (Exception ignore) { time = System.currentTimeMillis(); } } else { time = System.currentTimeMillis(); } if (logMap.containsKey(LOG_FIELD_TRACE_EXT)) { logMap.put(LOG_FIELD_TRACE_EXT, JSON.parseObject(logMap.get(LOG_FIELD_TRACE_EXT).toString())); } logContent = JSON.toJSONString(logMap); contentByte = null; } private Map<String, Object> generateLogItem(String message) { Map<String, Object> logItem = new HashMap<>(20); try { int start = 0; int end = 0; int matchCount = 0; int maxCount = LOG_FIELD_PATTERNS.length; for (int i = 0; i < message.length() && matchCount < maxCount; i++) { if ('[' == message.charAt(i)) { start = i; } if (']' == message.charAt(i)) { end = i; // subString start = start + 1; if (end > start) { logItem.put(LOG_FIELD_PATTERNS[matchCount], message.substring(start, end)); } start = end + 1; matchCount++; } } // trim content int trimStart = end + 1; int trimEnd = message.length(); for (int i = 0; i < message.length(); i++) { while ((trimStart < trimEnd) && (message.charAt(trimStart) <= ' ')) { trimStart++; } while ((trimStart < trimEnd) && (message.charAt(trimEnd - 1) <= ' ')) { trimEnd--; } } logItem.put(LOG_FIELD_MESSAGE, message.substring(trimStart, trimEnd)); } catch (Exception e) { logItem = new HashMap<>(); logItem.put(LOG_FIELD_MESSAGE, message); log.warn("解析华为云日志异常 error:{}", e.getMessage(), e); } return logItem; } 复制代码分别跑两个方法，区别是否上报原文，结果如下（使用 JMH 做吞吐测试）：
HuaWeiLogItemTest.parseLog thrpt 424734.273 ops/s HuaWeiLogItemTest.parseLogReportRaw thrpt 350891.566 ops/s 复制代码
工作原理
函数的工作原理是，通过对日志原文字符串的遍历，识别中括号 [] 并提取下标，将下标范围内的字符串放入到 HashMap 中。最后用 JSONObject.toJSONString() 输出。
有可能的性能开销点有以下几个：
每次都需要新建一个 HuaweiLogItem 对象
每次都需要新建一个 HashMap 对象
最后对 message 处理时，误用了外层的 for 循环，实际上是不需要的。
int trimStart = end + 1; int trimEnd = message.length(); // 这段代码意思是从字符串左侧判断是否有换行符，等价于 string.trim() 方法，事实上这个就是从里边抄的。 // 这个 for 循环是不需要的 for (int i = 0; i < message.length(); i++) { while ((trimStart < trimEnd) && (message.charAt(trimStart) <= ' ')) { trimStart++; } while ((trimStart < trimEnd) && (message.charAt(trimEnd - 1) <= ' ')) { trimEnd--; } } logItem.put(LOG_FIELD_MESSAGE, message.substring(trimStart, trimEnd)); 复制代码新实现方式
序列化对象，而不是 HashMap
有以下几点原因：
HashMap 的计算开销较大，存储浪费。
HashMap 做不到对象复用，但是类的字段可以。
Benchmark
# parseLog 指旧函数。newParseLog 指新函数 # ReportRaw 指包含日志原文字段 HuaWeiLogItemTest.parseLog thrpt 432612.603 ops/s HuaWeiLogItemTest.parseLogReportRaw thrpt 361318.931 ops/s HuaWeiLogItemTest.newParseLog thrpt 1059580.230 ops/s HuaWeiLogItemTest.newParseLogReportRaw thrpt 1059339.806 ops/s 复制代码
可以看到有大约 144% ~ 190% 的提升。
CPU 缓存优化
在遍历字符串时，之前的做法是使用 string.charAt(i) 的方式：
for (int i = 0; i < message.length() && matchCount < maxCount; i++) { // 这里 if ('[' == message.charAt(i)) { // ... } // 还有这里 if (']' == message.charAt(i)) { // ... } } 复制代码使用 charAt很可能会使 CPU 缓存刷新，于是改为 toCharArray() 的方式遍历（toCharArray()会再创建一份字符串，所以之前没用） :
char[] chars = rawLog.toCharArray(); int rawLogLength = rawLog.length(); for (int i = 0; i < rawLogLength && matchCount < maxCount; i++) { if ('[' == chars[i]) { // ... } if (']' == chars[i]) { // ... } } 复制代码Benchmark
# 缓存行优化。改用 toCharArray 遍历， # before HuaWeiLogItemTest.newParseLog thrpt 1059580.230 ops/s HuaWeiLogItemTest.newParseLogReportRaw thrpt 1059339.806 ops/s # after HuaWeiLogItemTest.newParseLog thrpt 1156832.681 ops/s HuaWeiLogItemTest.newParseLogReportRaw thrpt 1164270.861 ops/s 复制代码
比上一步有大概有 15% 的提升。
复用对象
之前是每条日志都会对应到一个 HuaweiLogItem 对象，修改成只将该对象作为媒介，转换日志原文与 JSON 用，将对象存储在 ThreadLocal 中
// 放在 threadLocal HuaWeiLogItemNew huaWeiLogItemNew = HUAWEI_LOG_ITEM_THREAD_LOCAL.get(); if (huaWeiLogItemNew == null) { synchronized (HuaweiLogProducer.class) { huaWeiLogItemNew = new HuaWeiLogItemNew(); HUAWEI_LOG_ITEM_THREAD_LOCAL.set(huaWeiLogItemNew); } } // 每次使用前存入数据并转换 for (String rawLog : rawLogs) { huaWeiLogItemNew.setData(rawLog, clientConfig.isReportRawLog()); huaWeiLogItemNew.parseLog(); contents.add(ImmutableMap.of("log_time_ns", huaWeiLogItemNew.getTime() * 1000L * 1000L, "log", JSON.toJSONString(huaWeiLogItemNew))); } 复制代码Benchmark
# 复用对象优化 # before HuaWeiLogItemTest.newParseLog thrpt 1156832.681 ops/s HuaWeiLogItemTest.newParseLogReportRaw thrpt 1164270.861 ops/s # after HuaWeiLogItemTest.newParseLogSharedObject thrpt 1365381.574 ops/s HuaWeiLogItemTest.newParseLogReportRawSharedObject thrpt 1374768.509 ops/s 复制代码
比上一步有 17% ~ 19% 的优化。
高效日期转时间戳
之前直接用了DateUtils.parseDate()，该方法中会使用 FastDateFormat 并返回一个 Date 对象，我们再从 Date 对象中取得时间戳。在这个过程中会创建对象，计算过程也相当复杂。单独对这个方法进行了 Benchmark 吞吐测试，得到的结果是在 130w/s 左右，看起来瓶颈很可能是在这里。
我们需要的仅仅是一个从 2021-10-22 17:47:15.074 转成 1634896035074 的工具，有没有更简单的办法？比如说直接从字符串中，解析对应的时分秒加起来：
public static long fastStrToTimestamp(String date) { // 仅支持 yyyy-MM-dd HH:mm:ss.SSS 格式 if (date.length() != 23) { return 0; } // 寻找当前天数对应的时间戳，如 2021-10-20 对应了 1634659200000 long todayTimestamp = -1; for (Tuple2<String, Long> tuple2 : fastConvertCache) { if (date.startsWith(tuple2.getFirst())) { todayTimestamp = tuple2.getSecond(); break; } } if (todayTimestamp == -1) { return DateUtils.parseDate(date, YYYY_MM_DD_HH_MM_SS_SSS).getTime(); } // 截取字符串的时分秒毫秒，与天数时间戳相加 int hour = Integer.parseInt(date.substring(11, 13)); int minute = Integer.parseInt(date.substring(14, 16)); int second = Integer.parseInt(date.substring(17, 19)); int mills = Integer.parseInt(date.substring(20, 23)); return todayTimestamp + hour * DateUtils.MILLIS_PER_HOUR + minute * DateUtils.MILLIS_PER_MINUTE + second * DateUtils.MILLIS_PER_SECOND + mills; } 复制代码还需要一个缓存，保存天数对应的时间戳，启动时生成并每天定时更新。 经过 Benchmark 测试，这个函数可以达到 2000w 左右的 QPS。
Benchmark
# 使用快速时间戳转换 # before HuaWeiLogItemTest.newParseLog thrpt 1156832.681 ops/s HuaWeiLogItemTest.newParseLogReportRaw thrpt 1164270.861 ops/s HuaWeiLogItemTest.newParseLogSharedObject thrpt 1365381.574 ops/s HuaWeiLogItemTest.newParseLogReportRawSharedObject thrpt 1374768.509 ops/s # after HuaWeiLogItemTest.newParseLog thrpt 2326123.191 ops/s HuaWeiLogItemTest.newParseLogReportRaw thrpt 2314395.548 ops/s HuaWeiLogItemTest.newParseLogSharedObject thrpt 3275743.575 ops/s HuaWeiLogItemTest.newParseLogReportRawSharedObject thrpt 3326434.899 ops/s 复制代码
比上一步大约有 100%~ 142% 的提升，效果可以说非常拔群了。QPS 也终于挺近了 300w 大关。
Benchmark 总结
# 新旧综合测试。 # parseLog 指旧函数。newParseLog 指新函数 # ReportRaw 指包含日志原文字段 # SharedObject 指复用对象 # 原解析方式 HuaWeiLogItemTest.parseLog thrpt 432612.603 ops/s HuaWeiLogItemTest.parseLogReportRaw thrpt 361318.931 ops/s HuaWeiLogItemTest.parseLogReportRawSharedObject thrpt 362798.892 ops/s HuaWeiLogItemTest.parseLogSharedObject thrpt 434279.601 ops/s # 改为字段后 HuaWeiLogItemTest.newParseLog thrpt 1059580.230 ops/s HuaWeiLogItemTest.newParseLogReportRaw thrpt 1059339.806 ops/s HuaWeiLogItemTest.newParseLogReportRawSharedObject thrpt 1200556.455 ops/s HuaWeiLogItemTest.newParseLogSharedObject thrpt 1191434.370 ops/s # 缓存行优化。改用 charsArrays 遍历。 HuaWeiLogItemTest.newParseLog thrpt 1156832.681 ops/s HuaWeiLogItemTest.newParseLogReportRaw thrpt 1164270.861 ops/s HuaWeiLogItemTest.newParseLogReportRawSharedObject thrpt 1374768.509 ops/s HuaWeiLogItemTest.newParseLogSharedObject thrpt 1365381.574 ops/s # 改为快速时间戳转换 HuaWeiLogItemTest.newParseLog thrpt 2326123.191 ops/s HuaWeiLogItemTest.newParseLogReportRaw thrpt 2314395.548 ops/s HuaWeiLogItemTest.newParseLogReportRawSharedObject thrpt 3326434.899 ops/s HuaWeiLogItemTest.newParseLogSharedObject thrpt 3275743.575 ops/s 复制代码
这一套打下来，对比旧解析方式，最高有 817% 的提升：
HuaWeiLogItemTest.parseLogReportRawSharedObject thrpt 362798.892 ops/s HuaWeiLogItemTest.newParseLogReportRawSharedObject thrpt 3326434.899 ops/s 复制代码
顺便一提，上边的测试全程在 Mac mini M1 芯片上进行，在 Macbook i9 CPU 上也跑了一遍，结果如下
经过不严谨的对比，i9 大概是 M1 效率的 52%~62% 。大概因为 MacBook 上 i9 降频降的太离谱。
作者：刘志国
链接：https://juejin.cn/post/7023017197253427230