使用Python简单分析JSON日志

发表于 | 分类于 | | 浏览 次

问题起因

最近工作中遇到个问题，开始是凌晨的一段时间，线上业务频繁报警，后来查询CAT和日志，发现是由于一个名为selectByOrderId的慢查询导致的。

遇到这种情况，通常会想到加索引。但是查看数据了解业务之后，发现这张300W数据表中只有几十条该字段非空，且会较频繁更新。于是想进一步分析，看看有什么其他的解决方案。
再看long-url，有一个用于客户端上报支付结果的report接口占比非常大。

数量上差不多，会不会有什么联系呢？翻了翻代码，发现report接口的处理逻辑确实有调用selectByOrderId相关rpc的代码，从这两张图来看，selectByOrderId慢查询仿佛大部分是由report接口导致的，但是什么样的参数会导致慢查询还需要进一步分析。
正好最近有点迷机器学习，学了点Python数据分析的皮毛，就用这个练练手吧。

着手调查

目标

找到report接口响应时间过长的共性

数据准备

在服务器上拉取了包含report接口的api日志，日志格式为”$requestId $json”，在json格式中存储了接口名称、输入参数、输出参数、状态码、发起时间、耗时、用户设备等40多项信息，并且有多层嵌套。
使用awk、sed将数据提取成json数组的形式：

1
2
# 删除requestId并使用在行尾添加,分割json串。由于json中可能有空格，所以使用截取字符串进行提取。
grep report api.log | awk '{print substr($0,27)}' | sed 's/$/,/' > report.json

之后使用vim在文本开头添加”[“结尾添加”]”。（如果您有更好的方式可以告诉我哈）
至此json数组文件构造完毕。
将文件通过sz或scp下载到待分析的机器上。

数据处理与分析

我使用备受推荐的Anaconda作为Python数据分析平台。Anaconda的依赖管理（包括python的版本）、已集成的常用库、集成Jupyter Notebook等常用数据分析工具，用起来都非常方便。当然Anaconda也不是必须的，直接使用conda或pip、easy_install安装管理依赖也是没问题的。
先简单介绍下使用到的Python库。

  • pandas
    高性能、简单易用的数据结构和数据分析工具。10 minutes to Pandas
  • numpy
    虽然没有直接用到，但它是pandas的基础，由C语言开发。

打开Jupyter Notebook，开始工作。
首先读取json数据，获得DataFrame。注意打开带有utf-8编码的文件用codecs.open代替open；因为数据时带有嵌套结构的json，所以使用pd.io.json.json_normalize对数据标准化，类似{“p”:{“id”:5}}的节点会被解析为p.id=5，否则会解析成p=”{“id”:5}”。如果json中不含嵌套结构，或者不使用嵌套数据，可以直接使用df = pd.read_json(path)得到DataFrame。

1
2
3
4
5
6
7
8
9
10
11
import pandas as pd
import codecs
import json
path = 'report.json'
with codecs.open(path, 'r', 'utf-8') as json_data:
    json_dicts = json.load(json_data) # 读取json数据为list[dict]结构
    json_df = pd.io.json.json_normalize(json_dicts)  # 处理嵌套json
    df = pd.DataFrame(json_df)
df.head()

通常原始数据需要进行处理后才能使用，比如去掉无关列、处理空值、转换列值、新增列等。
通过df.columns获取列名后，可以通过easy_df = df.drop(['col1','col2'], axis=1, inplace=False)删除某几列，axis表示删除的是列，inplace表示是否在原df中删除。
下面针对ct列也就是接口耗时做统计汇总：
easy_df.describe(percentiles=[.50,.75,.90,.95])[['ct']]
describe()进行快速统计汇总，percentiles可以添加多个百分位数进行统计，后面的[[‘ct’]]表示只取ct列的汇总。

优化前快速统计.png
可以发现，90%以上的请求耗时都很短，在80毫秒内。但是由于小于10%的请求导致平均响应时间(mean)接近一秒。那什么样的请求耗时那么长呢？没有什么头绪，那就先比较下慢请求的部分和总体请求统计上有什么差别吧。

1
2
# 删选耗时大于1秒的值
slow_df = easy_df[( easy_df.ct > 1000 )]

进行比较：

image.png
可以发现慢请求的一个共性就是参数值都是1.0。

得出结论

再翻代码，1代表着用户的支付成功，当上报接口的参数为1时，会进行订单查询操作，会通过订单号查询代金券信息，也就是调用包含上面selectByOrderId的RPC。但是由于没有判断该笔订单是否有代金券支付，导致了很多不必要的查询，而应该查询的那部分仅是一小部分，且有缓存命中会直接返回。程序上的修改只需增加判断，当该笔订单有代金券支付，才调用RPC查询即可。

小结

通过分析数据，推测数据之间的关联性并验证，还是很有意思的。
学习机器学习的路还很漫长，要求的学科知识都是我非常欠缺的，尤其是数据处理，以及背后的数学逻辑。能把学到的一点皮毛用到工作和生活中来学以致用，一直是我希望的。