Go语言Redis操作耗时异常：管道耗时低但整体Get超10ms求助

看起来你遇到了一个典型的「表面耗时」和「实际总耗时」不匹配的问题，既然已经排除了反序列化的影响，那我们从代码细节、连接池配置、并发模型这几个角度来拆解可能的原因：

1. 先修正你的计时代码（最容易忽略的关键问题） #

看你提供的代码，发现timer变量的赋值不完整：

• t.pipeline 没有把 sinceStartPipeTime 赋值进去
• t.total 也没有设置为 endTime
• 完全漏掉了 cachedValue.Bytes() 这一步的计时

这会导致你日志里的时间数据不准确，甚至可能误导你对耗时分布的判断。先把计时补全，才能精准定位耗时点：

func Get(params...) <-chan CacheResult {
    start := time.Now()
    var res CacheResult
    resCh := make(chan CacheResult, 1) // 建议加缓冲避免阻塞
    defer func() {
        resCh <- res
    }()

    type timers struct {
        total           time.Duration
        getConn         time.Duration // 新增：连接池获取连接耗时
        pipelineExec    time.Duration
        getBytes        time.Duration // 新增：从Redis响应取字节数据耗时
        unmarshal       time.Duration
        sendChannel     time.Duration // 新增：通道发送耗时
        logTime         time.Duration // 新增：日志输出耗时
    }
    t := timers{}

    // 计时从创建Pipeline开始（Pipeline创建涉及从连接池拿连接）
    startConnTime := time.Now()
    pipe := c.client.Pipeline()
    t.getConn = time.Since(startConnTime)

    // Pipeline命令执行计时
    startPipeTime := time.Now()
    results, res.Err := pipe.Exec()
    if res.Err != nil && res.Err != redis.Nil {
        return resCh
    }
    t.pipelineExec = time.Since(startPipeTime)

    // 获取缓存值字节数据的计时
    startGetBytesTime := time.Now()
    cachedValue := results[0].(*redis.StringCmd) // 假设对应你的HGET结果
    val, res.Err := cachedValue.Bytes()
    if res.Err != nil {
        return resCh
    }
    t.getBytes = time.Since(startGetBytesTime)

    // 反序列化计时
    startUnmarshalTime := time.Now()
    var cv common.CacheValue
    if res.Err = json.Unmarshal(val, &cv); res.Err != nil {
        return resCh
    }
    t.unmarshal = time.Since(startUnmarshalTime)

    // 记录核心流程总耗时（排除后续日志和通道操作）
    t.total = time.Since(start)

    // 日志输出单独计时
    startLogTime := time.Now()
    xlog.Infof("Core Timings: total:%s, getConn:%s, pipelineExec:%s, getBytes:%s, unmarshaling(%vB):%s",
        t.total, t.getConn, t.pipelineExec, t.getBytes, len(val), t.unmarshal)
    t.logTime = time.Since(startLogTime)

    // 通道发送单独计时（如果阻塞会显著拉长总耗时）
    startSendTime := time.Now()
    resCh <- res
    t.sendChannel = time.Since(startSendTime)

    // 打印全链路细节耗时用于排查
    xlog.Debugf("Full Timings: totalWithAll:%s, log:%s, sendChannel:%s",
        time.Since(start), t.logTime, t.sendChannel)

    return resCh
}

2. 连接池等待是最可能的元凶 #

你的系统每台机器每秒处理100请求（3台总300QPS），但Redis客户端用了默认10个连接。理论上每个连接每秒处理10个请求刚好，但实际Redis命令有网络往返和处理开销，连接池很可能出现等待：

• 当所有连接都在忙时，新请求会阻塞在pipe := c.client.Pipeline()这一步（从连接池获取连接）
• 你之前的计时完全没覆盖这部分，所以会出现「Pipeline执行快，但总耗时高」的情况

排查/解决方法： #

• 监控客户端连接池指标：比如Go Redis客户端的PoolStats，查看Hits/Misses/Timeouts，如果Misses或Timeouts不为0，说明连接池不够用
• 调整连接池大小：把PoolSize（Go Redis v8+）或MaxActive（旧版本）提高到20-30，观察总耗时变化
• 检查连接泄漏：确保异常路径下连接能正常归还到池里，比如Pipeline是否正确关闭（Exec()会自动处理，但建议在异常时调用pipe.Close()）

3. 并发通道的阻塞风险 #

你的函数返回一个<-chan CacheResult，并且用defer发送结果到通道：

• 如果调用Get()的上游代码没有及时消费通道数据，resCh <- res会阻塞整个函数
• 这种阻塞的耗时会被算到Get操作的总耗时里，但完全和Redis无关

排查方法： #

• 看新增计时里的sendChannel耗时，如果这个值很大（几毫秒甚至几十毫秒），说明通道消费不及时
• 给通道增加缓冲（比如resCh := make(chan CacheResult, 100)），避免阻塞；或者优化上游的消费逻辑，确保及时处理通道数据

4. 其他潜在耗时点 #

• 修正拼写错误的命令：你代码里写了HEGT（应该是HGET？），虽然Redis会忽略错误命令，但解析错误命令会产生额外不必要的开销，建议修正
• 网络延迟抖动：测试Redis实例的PING耗时，看AWS实例和Redis之间的网络是否有偶尔的高延迟
• 日志输出开销：如果日志是同步写入磁盘或远程服务，高并发下日志操作会累积耗时，尝试关闭日志后看总耗时是否下降

内容的提问来源于stack exchange，提问作者Pramod Shashidhara