Missing milliseconds in the Go code performing redis operation

Question

Below is the sample snippet for getting value from Redis. I'm pipeling 3 redis commands and getting the values. The problem here is "missing milliseconds". The time taken by redis pipeline is significantly lower ( less than 5ms) but the overall time taken to perform a Get Operation is more than 10ms. Not sure which operation is taking time, unmarshal is not the issue, as I measured the len(bytes) and timing. Any help is much appreciated.

Request/Second = 300, running on 3 AWS large instances with a powerful 25GB redis instance. Using 10 default connections.

func Get(params...) <-chan CacheResult {
    start := time.Now()
    var res CacheResult
    defer func() {
            resCh <- res
    }()

    type timers struct {
        total     time.Duration
        pipeline  time.Duration
        unmarshal time.Duration
    }
t := timers{}

    startPipeTime := time.Now()
    // pipe line commands
    pipe := c.client.Pipeline()
    // 3 commands pipelined (HGET, HEGT, GET)
    if _, res.Err = pipe.Exec(); res.Err != nil && res.Err != redis.Nil {
                    return resCh
    }
    sinceStartPipeTime := time.Since(startPipeTime)

// get query values like below for HGET & GET
if val, res.Err = cachedValue.Bytes(); res.Err != nil {
    return resCh
}

// Unmarshal the query value
startUnmarshalTime := time.Now()
var cv common.CacheValue
if res.Err = json.Unmarshal(val, &cv); res.Err != nil {
    return resCh
}
sinceStartUnmarshalTime := time.Since(startUnmarshalTime)
t.unmarshal = sinceStartUnmarshalTime

endTime := time.Since(start)
xlog.Infof("Timings total:%s, "+
        "pipeline(redis):%s, unmarshaling(%vB):%s", t.total, t.pipeline, len(val), t.unmarshal)
return resCh

}

Answer 1

Time to execute a redis command include:

1. App server pre-processing
2. Round trip time between app server and redis server
3. Redis server processing time

In normal operation, (2) takes the most significant time.