何为高级查询

用过 DataDog 或者阿里云日志服务的，相信会对他们的高级查询印象深刻，日志原来还可以这样分析:

如上图中，我在 nginx-access 日志中按域名聚合，统计平均响应时间并排序输出。有这种功能的日志系统就不再是仅限于存储浏览的工具，还可以从系统产生的海量日志中快速分析出有价值的数据，对定位问题、分析系统会非常有帮助。

我们的实现效果

同样是 nginx-access 日志:

由于结构化日志都是 KV 形式存储在数据库，所以查询列会稍微复杂一些需要指定类型:

select http_host -> select string['http_host']
select upstream_response_time -> select number['upstream_response_time']

不过我们支持更加灵活的写法，如省略 Select 前缀直接写 order by 也可以接受:

还可以写多个分隔符，将前边的 SQL 作为子查询:

更多案例

下面分享几个内部文档中总结的案例

统计不存在的节点

首先准确筛选日志「工作节点不存在」，字符串截取到 workerId 后的数字，再进行 group by 统计:

工作节点不存在  | select sublen(message, 'workerId=', 10) as workerId, count() group by workerId 

结果如下:

查看错误活动配置影响的用户

由于业务方活动配置失误，导致很多用户无法进入活动页，现在希望统计受影响的结果，如下图中 message 中的 activityId、uid、inviteCode 和时间字段。日志内容如下:

通过高级查询则可以直接从日志中拆出对应的字段:

参与的活动不存在 and BIZ_ERROR 
| select dt, JSONExtractString(message, 'requestPayload') AS requestPayload 
| select dt, JSONExtractString(requestPayload, 'eventParam', 'uid') AS uid,
JSONExtractString(requestPayload, 'eventParam', 'activityId') AS activityId,
JSONExtractString(requestPayload, 'eventParam', 'inviteCode') AS inviteCode 

查询结果: 这时发现有 uid、activityId 重复的情况，希望进一步再去重一下。在 ClickHouse 中有 limit by语法可以很方便地实现，现在高级查询如下:

参与的活动不存在 and BIZ_ERROR 
| select dt, JSONExtractString(message, 'requestPayload') AS requestPayload 
| select dt, JSONExtractString(requestPayload, 'eventParam', 'uid') AS uid,
JSONExtractString(requestPayload, 'eventParam', 'activityId') AS activityId,
JSONExtractString(requestPayload, 'eventParam', 'inviteCode') AS inviteCode 
limit 1 by uid, activityId

查询结果中可见已经实现去重，结果数量也少了很多:

分组统计接口响应时间

业务方发现 Dubbo 线程池用尽，此时调用方在跑异步任务，大量调用该服务。从日志中的 Dubbo 接口响应时间看不出明显上升，因为总共有十几万条日志，没办法一一翻阅。 Dubbo 接口日志如下:

筛选日志后，在高级查询汇总取出接口响应时间进行统计:

trace_ext.endpoint_name:cn.jojo.mall.gravity.rpc.api.service.BuyCourseActionRpcService.queryActionCount(BuyCourseActionQueryReq)
| select toInt64(subend(message, 'timeUsed ', 'ms'))  as time 
| select max(time), quantile(0.99)(time) as p99, quantile(0.90)(time) as p90, avg(time) 

结果如下，可以看出最大响应时间 905ms，说明确实在某些时刻响应时间发生了波动:

但这时看不出来趋势，于是将时间加入进去进行分组统计，使用 toStartOfInterval(date, interval 5 second)并 group by 该时间:

trace_ext.endpoint_name:"cn.jojo.mall.gravity.rpc.api.service.BuyCourseActionRpcService.queryActionCount(BuyCourseActionQueryReq)"
| select date, toInt64(subend(message, 'timeUsed ', 'ms'))  as time 
| select max(time), quantile(0.99)(time) as p99, quantile(0.90)(time) as p90, avg(time), toStartOfInterval(date, interval 5 second) as fiveSecond, count() 
group by fiveSecond order by fiveSecond

结果如下，可以明显看出在 06:20 ~ 06:30 响应时间和调用量有明显上升，确定了具体时间点，同时确定了原因是并发量突增导致数据库波动。