缘起
最近发生了一个服务故障，在一个同事对日志服务做了改动后，服务的耗时就变大了很多，数据大量积压。
通过观察监控报表，我们发现从他的改动上线后，服务器的CPU使用率大幅增加，基本处于满载状态。
粗略审查代码并没有发现问题，我们只能紧急回滚了服务，日志消费也恢复到正常状态了。
但是根本问题还没有找到，所以我请出了line_profiler来分析程序的具体耗时情况。
line_profiler是个代码耗时分析器，可以逐行分析代码的耗时情况。
使用
line_profiler包含两个部分
- kernprof：代码执行和耗时记录
- line_profiler：耗时报告解析和展示
首先，安装：pip install line_profiler -U
给需要分析的代码加上@profile装饰器, @profile装饰器不需要被import，kernprof在运行时会注入依赖，kernprof会记录被装饰函数的耗时情况，有多个函数也可以都加上装饰器。
1
2
3
4
5
6
7
8
9
10
11
12
| @profile
def main(run_type):
with open('data.txt','r') as f:
data=f.readline()
input_data = json.loads(data)
source = input_data.get('source', '')
service = input_data.get('service', 0)
apply_no = input_data.get('applyNo', 0)
info = input_data.get('info', '')
cust_no = input_data.get('cust_no', 0)
job.run(source, service, apply_no, info, run_type)
|
复制
然后，运行代码：kernprof -l service.py, 统计耗时情况, 执行完成后生成耗时报告文件service.py.lprof
最后，耗时报告解析：python -m line_profiler service.py.lprof，会生成可阅读的耗时报告。
分析
耗时报告示例
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
| Timer unit: 1e-06 s
Total time: 4.18908 s
File: service.py
Function: main at line 38
Line
==============================================================
38 @profile
39 def main(run_type):
40 1 45.0 45.0 0.0 with open('data.txt','r') as f:
41 1 517.0 517.0 0.0 data=f.readline()
42 1 6564.0 6564.0 0.2 input_data = json.loads(data)
43 1 20.0 20.0 0.0 source = input_data.get('source', '')
44 1 6.0 6.0 0.0 service = input_data.get('service', 0
45 1 5.0 5.0 0.0 apply_no = input_data.get('applyNo',
46 1 5.0 5.0 0.0 info = input_data.get('info', '')
47
48 1 1.0 1.0 0.0 cust_no = input_data.get('cust_no', 0)
49
50 1 4181914.0 4181914.0 99.8 job.run(source, service, apply_no, info, run_type)
|
复制
耗时报告会逐行显示代码耗时和调用情况
- Timer unit: 耗时单位，这里是微秒
- Total time：总耗时
- Line #：行号
- Hits：函数被调用次数
- Time：函数总耗时
- Per Hit：函数每次调用耗时
- % Time：耗时占比
可以看到，总耗时4.18908秒，job.run占用了99.8%的时间。
接下来我们分析下job.run的耗时情况
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
| Timer unit: 1e-06 s
Total time: 4.16909 s
File: job.py
Function: inout at line 69
Line # Hits Time Per Hit % Time Line Contents
==============================================================
69 @profile
70 def run(self, apply_no, info, req_type, run_type):
... 省略部分逻辑
112 1 2.0 2.0 0.0 if req_type == 'credit':
113 1 3370673.0 3370673.0 80.8 sql = db_utils.generate_sql(info1, sql, val, columns)
114 else:
115 sql = db_utils.generate_sql(info1, sql, val, columns)
116 1 6948.0 6948.0 0.2 safe3_db.executor(sql)
|
复制
可以看到，113行的生成SQL语句占用了80%的时间，SQL反倒不怎么耗时，显然是不正常的。
再看下db_utils.generate_sql函数的具体代码
可以发现遍历字段列表(item_list)的时候，调用了get_json_value，该函数每次都会调用copy.deepcopy。
众所周知，对象的深拷贝是十分消耗cpu资源的，并且这里深拷贝的次数会随着字段数的增加而线性增长。
把深拷贝行为去除后，服务耗时和cpu占用都回归到了正常水准。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
| def generate_sql(info, sql, val, item_list):
index = 0
length = len(item_list)
for item in item_list:
index += 1
buf = get_json_value(info,item)
if index < length:
sql = sql + ', `' + str(item) + '`'
val = val + ', \'' + MySQLdb.escape_string(str(buf)) + '\''
else:
sql = sql + ', `' + str(item) + '`) '
val = val + ', \'' + MySQLdb.escape_string(str(buf)) + '\')'
return sql + val
def get_json_value(js,term):
tsplit=term.split('|')
result=''
buf=copy.deepcopy(js)
return value
|
复制
Gitalking ...