# 背景日志解析服务，需要将服务端上报的日志，解析并投递到对应的日志库中。投递时可以批量，但解析只能针对一条条日志，所以解析的性能至关重要。日志原文: ``` [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" } ``` # 旧函数旧函数实现如下（可以不用看）： ```java public void parseLog() { String rawLog = new String(contentByte); Map 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 generateLogItem(String message) { Map 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() 输出。有可能的性能开销点有以下几个： 1. 每次都需要新建一个 HuaweiLogItem 对象 2. 每次都需要新建一个 HashMap 对象 3. 最后对 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 有以下几点原因： 1. HashMap 的计算开销较大，存储浪费。 2. 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 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 上也跑了一遍，结果如下 ![截屏2021-10-25 下午10.27.31.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/0618bec45f3f4bb3a6df4e5a1fbbb3c6~tplv-k3u1fbpfcp-watermark.image?) 经过不严谨的对比，i9 大概是 M1 效率的 52%~62% 。大概因为 MacBook 上 i9 降频降的太离谱。