背景

日志解析服务，需要将服务端上报的日志，解析并投递到对应的日志库中。投递时可以批量，但解析只能针对一条条日志，所以解析的性能至关重要。

日志原文:

[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 上也跑了一遍，结果如下

截屏2021-10-25 下午10.27.31.png

经过不严谨的对比，i9 大概是 M1 效率的 52%~62% 。大概因为 MacBook 上 i9 降频降的太离谱。

日志解析效率提高 8 倍过程

背景

旧函数

工作原理

新实现方式

序列化对象，而不是 HashMap

Benchmark

CPU 缓存优化

Benchmark

复用对象

Benchmark

高效日期转时间戳

Benchmark

Benchmark 总结