最近在优化一个Python项目,里面包含很多set,list,dict等操作,代码行数2000多行,每次运行耗时都在30-50ms,本以为是Python语言的动态解析特性导致运行性能太低,便尝试使用JIT工具进行优化,折腾一番之后,性能只提升20%,远没有官方介绍的6倍之多,反复查看代码,想到了IO耗时的问题,而是怀疑log输出到控制台耗时是否是罪魁祸首,实验下来发现的确如此。
实验内容:
分别对比,运行下面代码,记录耗时情况,结果:
- 运行1000次 加法: 0.5578994750976562 ms
- 运行1000次 空logging: 3.5049915313720703 ms
- 运行1000次 控制台输出logging: 50.84490776062012 ms
- 运行1000次 控制台输出loguru: 135.09225845336914 ms
- 运行1000次 空loguru: 1.0859966278076172 ms
- 运行1000次 控制台print: 3.3588409423828125 ms
- 运行1次 控制台1000倍字符长度print: 0.051975250244140625 ms
- 运行1次 控制台1000倍字符长度logging: 0.25582313537597656 ms
- 运行1次 控制台1000倍字符长度logger: 0.0059604644775390625 ms
- 运行1次 加法: 0.0030994415283203125 ms
- 运行1000次 控制台print: 3.3588409423828125 ms
- 运行1000次 python文件流方式输出到stdout: 0.9961128234863281 ms
- 运行1000次 python文件流方式输出到文件: 1.2679100036621094 ms
- 运行1000次 loguru文件流方式输出到文件: 192.5220489501953 ms
结论:
1.log写入文件效率高于stdout,优先选择写文件
2.log输出到控制台,直接print和定向到stdout的效率都低于以文件流的方式写入/dev/stdout,优先选择文件流写入
3.loguru写文件效率都较低,准备自己实现log简易功能
代码
import logging
from loguru import logger
import time
s1 = time.time()
for i in range(1000):
i = i + float("0.0000009998980")
s2 = time.time()
for i in range(1000):
logging.info(f"我是第{i}次记录log")
s3 = time.time()
for i in range(1000):
logging.error(f"我是第{i}次记录log")
s4 = time.time()
for i in range(1000):
logger.error(f"我是第{i}次记录log")
logger.remove(handler_id=None)
s5 = time.time()
for i in range(1000):
logger.error(f"我是第{i}次记录log")
s6 = time.time()
for i in range(1000):
print(f"我是第{i}次记录log")
s7 = time.time()
s8 = time.time()
print(f"我是第8次记录log" * 1000)
s9 = time.time()
logging.error(f"我是第8次记录log" * 1000)
s10 = time.time()
logger.error(f"我是第8次记录log" * 1000)
s11 = time.time()
i = 8 + float("0.0000009998980")
s12 = time.time()
f1 = open("/dev/stdout","w")
s13 = time.time()
for i in range(1000):
f1.write(f"我是第{i}次记录log\n")
s14 = time.time()
f1.close()
f2 = open("./test.log","w")
s15 = time.time()
for i in range(1000):
f2.write(f"我是第{i}次记录log\n")
s16 = time.time()
f2.close()
logger.add("test.loguru")
s17 = time.time()
for i in range(1000):
logger.error(f"我是第{i}次记录log\n")
s18 = time.time()
print("运行1000次 加法:", (s2 - s1) * 1000, "ms")
print("运行1000次 空logging:", (s3 - s2) * 1000, "ms")
print("运行1000次 控制台输出logging:", (s4 - s3) * 1000, "ms")
print("运行1000次 控制台输出loguru:", (s5 - s4) * 1000, "ms")
print("运行1000次 空loguru:", (s6 - s5) * 1000, "ms")
print("运行1000次 控制台print:", (s7 - s6) * 1000, "ms")
print("运行1次 控制台1000倍字符长度print:", (s9 - s8) * 1000, "ms")
print("运行1次 控制台1000倍字符长度logging:", (s10 - s9) * 1000, "ms")
print("运行1次 控制台1000倍字符长度logger:", (s11 - s10) * 1000, "ms")
print("运行1次 加法:", (s12 - s11) * 1000, "ms")
print("运行1000次 控制台print:", (s7 - s6) * 1000, "ms")
print("运行1000次 python文件流方式输出到stdout:", (s14 - s13) * 1000, "ms")
print("运行1000次 python文件流方式输出到文件:", (s16 - s15) * 1000, "ms")
print("运行1000次 loguru文件流方式输出到文件:", (s18 - s17) * 1000, "ms")
实验机器:
python常见的性能瓶颈:数据库慢查询SQL、日志打印、xml大报文解析和格式转换、复杂业务逻辑、锁竞争等。