一次线上redis慢的排查过程,发现redis根本不慢

缓存应用场景：

对话系统中，用redis来存储用户对话的上下文，用户每次说话将用户对话的上下文带给大模型进行推理，然后返回给用户回答

该对话系统用在电话场景,对响应速度要求较高。

代码中自己对redis的耗时进行了记录 超过50毫秒报警

start_time = time.time()
dialogueSession = dialogueStorage.get_dialogue_session(session_id, workspace_id)
end_time = time.time()
if ((end_time - start_time) * 1000) > 50:
这里发送报警信息 并且打印session_id

首先查看redis 没有任何慢日志，怀疑网络有问题

发现网络也没什么问题，决定在服务所在服务器上进行抓包，系统出现报警后停止抓包，日志记录如下：

开始 2024年2月28日 14点26分05秒818毫秒

结束 2024年2月28日 14点26分05秒924毫秒

日志可以看出来 耗时是 > 50ms的 定位到具体的包 但是抓包记录 redis是在1ms响应的

此时基本排除redis出现的问题 此时猜测 ，问题可能出现在操作系统 或者服务本身

查看读取redis代码 发现读取redis后有进行json解析操作

    def get_dialogue_llm(self, session_id, workspace_id):
        if session_id is None or workspace_id is None:
            return None
        session = None
        try:
            redisKey = self.get_redis_llm(session_id, workspace_id)
            llm_result = self.conn_redis.get(redisKey)
            if llm_result is None:
                return None
            session = json.loads(llm_result)
            log.info("[get_dialogue_llm] session_id:{}, workspace_id:{}".format(session_id, workspace_id))
        except Exception as e:
            log.error("[get_dialogue_llm] get dialogue llm result Error: %s" % str(e))
        return session

于是对实际读取redis 和 json解析 都进行记时 此时奇怪的问题发生了 整个方法依然超过50ms 但是 读取redis和解析json 都不耗时 1ms以内。剩下的就是打印日志了，发现这个项目是用的python自带的log包打印日志 默认配置。这个默认的配置是同步写的，并且每次都落盘才会返回。问题基本可以确定是在这里。接下来加上日志进行验证，验证结果如下。

可以看到总共耗时36毫秒 写日志用了35毫秒 ，接下来解决问题就是把写日志改成异步带缓存的写，避免阻塞和占用IO.