使用Python简单分析JSON日志

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列的汇总。

优化前快速统计.png

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


最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 205,236评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 87,867评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,715评论 0 340
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,899评论 1 278
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,895评论 5 368
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,733评论 1 283
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,085评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,722评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,025评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,696评论 2 323
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,816评论 1 333
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,447评论 4 322
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,057评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,009评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,254评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,204评论 2 352
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,561评论 2 343

推荐阅读更多精彩内容