1.问题起因
最近工作中遇到个问题,开始是凌晨的一段时间,线上业务频繁报警,后来查询CAT和日志,发现是由于一个名为selectByOrderId的慢查询导致的。
遇到这种情况,通常会想到加索引。但是查看数据了解业务之后,发现这张300W数据表中只有几十条该字段非空,且会较频繁更新。于是想进一步分析,看看有什么其他的解决方案。
再看long-url,有一个用于客户端上报支付结果的report接口占比非常大。
数量上差不多,会不会有什么联系呢?翻了翻代码,发现report接口的处理逻辑确实有调用selectByOrderId相关rpc的代码,从这两张图来看,selectByOrderId慢查询仿佛大部分是由report接口导致的,但是什么样的参数会导致慢查询还需要进一步分析。
正好最近有点迷机器学习,学了点Python数据分析的皮毛,就用这个练练手吧。
2.着手调查
2.1 目标
找到report接口响应时间过长的共性
2.2 数据准备
在服务器上拉取了包含report接口的api日志,日志格式为"$requestId $json",在json格式中存储了接口名称、输入参数、输出参数、状态码、发起时间、耗时、用户设备等40多项信息,并且有多层嵌套。
使用awk、sed将数据提取成json数组的形式:
# 删除requestId并使用在行尾添加,分割json串。由于json中可能有空格,所以使用截取字符串进行提取。
grep report api.log | awk '{print substr($0,27)}' | sed 's/$/,/' > report.json```
之后使用vim在文本开头添加"["结尾添加"]"。(如果您有更好的方式可以告诉我哈)
至此json数组文件构造完毕。
将文件通过sz或scp下载到待分析的机器上。
### 2.3 数据处理与分析
我使用备受推荐的Anaconda作为Python数据分析平台。Anaconda的依赖管理(包括python的版本)、已集成的常用库、集成Jupyter Notebook等常用数据分析工具,用起来都非常方便。当然Anaconda也不是必须的,直接使用conda或pip、easy_install安装管理依赖也是没问题的。
先简单介绍下使用到的Python库。
- pandas
高性能、简单易用的数据结构和数据分析工具。[10 minutes to Pandas](http://pandas.pydata.org/pandas-docs/stable/10min.html)
- 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。
``` python
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列的汇总。
可以发现,90%以上的请求耗时都很短,在80毫秒内。但是由于小于10%的请求导致平均响应时间(mean)接近一秒。那什么样的请求耗时那么长呢?没有什么头绪,那就先比较下慢请求的部分和总体请求统计上有什么差别吧。
# 删选耗时大于1秒的值
slow_df = easy_df[( easy_df.ct > 1000 )]```
进行比较:
![image.png](http://upload-images.jianshu.io/upload_images/931112-18fe4690292ee286.png?imageMogr2/auto-orient/strip%7CimageView2/2/w/1240)
可以发现慢请求的一个共性就是参数值都是1.0。
## 3.得出结论
再翻代码,1代表着用户的支付成功,当上报接口的参数为1时,会进行订单查询操作,会通过订单号查询代金券信息,也就是调用包含上面selectByOrderId的RPC。但是由于没有判断该笔订单是否有代金券支付,导致了很多不必要的查询,而应该查询的那部分仅是一小部分,且有缓存命中会直接返回。程序上的修改只需增加判断,当该笔订单有代金券支付,才调用RPC查询即可。
## 4.小结
通过分析数据,推测数据之间的关联性并验证,还是很有意思的。
学习机器学习的路还很漫长,要求的学科知识都是我非常欠缺的,尤其是数据处理,以及背后的数学逻辑。能把学到的一点皮毛用到工作和生活中来学以致用,一直是我希望的。