Carpe Diem

備忘録

go-redisのtimeoutで気をつけること

概要

Go言語でRedisを使う際に選択肢に挙がるのがgo-redisです。

今回はgo-redisでTimeoutを設定する際に注意すべきことをまとめました。

手前味噌ですがBlast Radius of Failureを最小にするためにTimeoutを短くすることを1つのテクニックとしても紹介しています。

W杯全64試合無料生中継で「落ちない」を実現。「小さく壊れる」ために行った負荷・障害・セキュリティ対策とは?【ABEMA DEVELOPER CONFERENCE 2023#3】 | レバテックラボ(レバテックLAB)

しかし短すぎるとそれはそれで問題が発生することになるので、その理由を説明します。

環境

  • redis/go-redis v9.0.5

go-redisのTimeoutの種類

go-redisではtimeoutとして以下があります。

種類 説明 デフォルト値
DialTimeout 新規コネクションを確立する際のtimeout 5s
ReadTimeout socket readのtimeout
0: デフォルト値
-1: timeoutなし
-2: net.Conn.SetReadDeadlineを無効に
3s
WriteTimeout socket writeのtimeout
0: デフォルト値
-1: timeoutなし
-2: net.Conn.SetWriteDeadlineを無効に
3s
ContextTimeout context.Contextを使ったtimeout
ContextTimeoutEnabled: trueで有効化
-
PoolTimeout PoolSizeで指定されたコネクションが全て使用中の際に待つ時間 ReadTimeout + 1s

ref: redis package - github.com/redis/go-redis/v9 - Go Packages

上記の中で読み取りや書き込み処理におけるtimeoutとしては

  1. ReadTimeout
  2. WriteTimeout
  3. ContextTimeout

の3つを主に扱い、クライアントを生成する際に指定できます。

cli := redis.NewClient(&redis.Options{
        Addr:                  "localhost:6379",
        ReadTimeout:           3 * time.Second,
        WriteTimeout:          3 * time.Second,
        ContextTimeoutEnabled: true,
})

ReadTimeout, WriteTimeoutのデフォルト値は3秒です。

気をつけること

1. 読み取り処理でもWriteTimeoutを使う

例えばGETは読み取り処理なのでReadTimeoutのみ使うと思えますが、そうではありません。

次のようなコードを用意すると

func main() {
        cli := redis.NewClient(&redis.Options{
                Addr:         "localhost:6379",
                ReadTimeout:  1 * time.Second,
                WriteTimeout: 1 * time.Nanosecond,
        })
        out, err := cli.Get(context.TODO(), "key").Result()
        if err != nil {
                fmt.Println(err)
        }
        cancel()
        fmt.Println(out)
}

このようにwrite timeoutになります。

$ go run main.go
write tcp [::1]:51732->[::1]:6379: i/o timeout

原因

Getコマンドを深ぼってみます。

func (c cmdable) Get(ctx context.Context, key string) *StringCmd {
    cmd := NewStringCmd(ctx, "get", key)
    _ = c(ctx, cmd)
    return cmd
}

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/commands.go#L977C9-L981

cmdableはClientにembedされています。

type Client struct {
    *baseClient
    cmdable
    hooksMixin
}

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/redis.go#L600C1-L604C2

これは初期化時にc.Processで設定されます。

func (c *Client) init() {
    c.cmdable = c.Process
    c.initHooks(hooks{
        dial:       c.baseClient.dial,
        process:    c.baseClient.process,
        pipeline:   c.baseClient.processPipeline,
        txPipeline: c.baseClient.processTxPipeline,
    })
}

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/redis.go#L621-L629

c.ProcessはClientにembedされているhooksMixinのメソッドであるc.processHookを使います。

func (c *Client) Process(ctx context.Context, cmd Cmder) error {
    err := c.processHook(ctx, cmd)
    cmd.SetErr(err)
    return err
}

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/redis.go#L649-L653

c.processHookはprocessを使います。

func (hs *hooksMixin) processHook(ctx context.Context, cmd Cmder) error {
    return hs.current.process(ctx, cmd)
}

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/redis.go#L171C1-L173

processは初期化時にbaseClient.processを渡しています。

   c.initHooks(hooks{
        dial:       c.baseClient.dial,
        process:    c.baseClient.process,
        pipeline:   c.baseClient.processPipeline,
        txPipeline: c.baseClient.processTxPipeline,
    })

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/redis.go#L623-L628

baseClient.processはc._processを使います。

func (c *baseClient) process(ctx context.Context, cmd Cmder) error {
    var lastErr error
    for attempt := 0; attempt <= c.opt.MaxRetries; attempt++ {
        attempt := attempt

        retry, err := c._process(ctx, cmd, attempt)
        if err == nil || !retry {
            return err
        }

        lastErr = err
    }
    return lastErr
}

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/redis.go#L370-L383

最後c._processは内部でcn.WithWritercn.WithReaderの両方を呼んでいます。

このためwriteのtimeoutも使われます。

func (c *baseClient) _process(ctx context.Context, cmd Cmder, attempt int) (bool, error) {
    if attempt > 0 {
        if err := internal.Sleep(ctx, c.retryBackoff(attempt)); err != nil {
            return false, err
        }
    }

    retryTimeout := uint32(0)
    if err := c.withConn(ctx, func(ctx context.Context, cn *pool.Conn) error {
        if err := cn.WithWriter(c.context(ctx), c.opt.WriteTimeout, func(wr *proto.Writer) error {
            return writeCmd(wr, cmd)
        }); err != nil {
            atomic.StoreUint32(&retryTimeout, 1)
            return err
        }

        if err := cn.WithReader(c.context(ctx), c.cmdTimeout(cmd), cmd.readReply); err != nil {
            if cmd.readTimeout() == nil {
                atomic.StoreUint32(&retryTimeout, 1)
            } else {
                atomic.StoreUint32(&retryTimeout, 0)
            }
            return err
        }

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/redis.go#L385-L408

ただしWriteTimeoutを極端に小さくしない限りは読み取り処理においては影響はないです。

2. 書き込み処理でもReadTimeoutを使う

注意なのは書き込み側のReadTimeoutです。

次のようなコードを用意します。

func main() {
        cli := redis.NewClient(&redis.Options{
                Addr:         "localhost:6379",
                ReadTimeout:  1 * time.Millisecond,
                WriteTimeout: 1 * time.Second,
        })
        out, err := cli.Set(context.TODO(), "key", "val", 0).Result()
        if err != nil {
                fmt.Println(err)
        }
        cancel()
        fmt.Println(out)
}

このようにread timeoutが出ました。

$ go run main.go
read tcp [::1]:51748->[::1]:6379: i/o timeout

原因

先程のコードが原因なわけですが、コードを見るにレスポンスを受け取る際にもこのRaedTimeoutを使っていると考えられます。

       if err := cn.WithReader(c.context(ctx), c.cmdTimeout(cmd), cmd.readReply); err != nil {
            if cmd.readTimeout() == nil {
                atomic.StoreUint32(&retryTimeout, 1)
            } else {
                atomic.StoreUint32(&retryTimeout, 0)
            }
            return err
        }

これはローカルtoローカル通信なのでまだ良いですが、クラウドなどの通信では小さいReadTimeoutを設定していると書き込み処理においてこのエラーが発生しやすくなります。

MSET, Pipelineへの影響

例えばローカルtoローカルの通信環境において、GETが ReadTimeout: 5 * time.Millisecond で問題ないのに対し、

MSET

10件程度でread timeout

PipelineでのSET

1200件程度でread timeout

といった結果になりました。

このことからMSETやPipelineの処理は、件数によってGETよりもReadTimeoutの影響が強く出る事が分かります。

テストコード

テストコードにおいてもPing処理でread/write両方のtimeoutでエラーを発生させているので、どちらも使われているのは仕様通りと言えます。

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/redis_test.go#L363-L442

3. Timeoutはコネクションをクローズさせる

以下の記事には、多くのDBではcontext cancelの場合はコネクションをクローズするとあります。

When context is cancelled, go-redis and most other database clients (including database/sql) must do the following:

  1. Close the connection, because it can't be safely reused.
  2. Open a new connection.
  3. Perform TLS handshake using the new connection.
  4. Optionally, pass some authentication checks, for example, using Redis AUTH command.

ref: Go Context timeouts can be harmful

そしてコネクションの再生成が必要となりオーバーヘッドが発生することで、よりTimeoutが発生しやすくなるという負のループに陥る可能性があります。

実際に検証してみました。

Timeoutしない場合

func main() {
        cli := redis.NewClient(&redis.Options{
                Addr:                  "localhost:6379",
                ReadTimeout:           3 * time.Second,
                WriteTimeout:          3 * time.Second,
        })
        for i := 0; i < 3; i++ {
                // KEYS *
                _, err := cli.Keys(context.TODO(), "*").Result()
                time.Sleep(1 * time.Second)
        }
        time.Sleep(3 * time.Second)
}

このように最後の処理が完了してからコネクションがクローズされます。
またコネクションはプールで再利用されます。

ContextTimeoutする場合

しかしcontext timeoutすると、

func main() {
        cli := redis.NewClient(&redis.Options{
                Addr:                  "localhost:6379",
                ReadTimeout:           3 * time.Second,
                WriteTimeout:          3 * time.Second,
                ContextTimeoutEnabled: true,
        })
        for i := 0; i < 3; i++ {
                ctx, _ := context.WithTimeout(context.TODO(), 5*time.Millisecond)
                // KEYS *
                _, err := cli.Keys(ctx, "*").Result()
                time.Sleep(1 * time.Second)
        }
        time.Sleep(3 * time.Second)
}

再利用するには適切な状態ではないと判断されコネクションは即座にクローズされます。

実コード

該当の処理はここにあたります。

func isBadConn(err error, allowTimeout bool, addr string) bool {
    switch err {
    case nil:
        return false
    case context.Canceled, context.DeadlineExceeded:
        return true
    }

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/error.go#L79-L85

func (c *baseClient) releaseConn(ctx context.Context, cn *pool.Conn, err error) {
    if c.opt.Limiter != nil {
        c.opt.Limiter.ReportResult(err)
    }

    if isBadConn(err, false, c.opt.Addr) {
        c.connPool.Remove(ctx, cn, err)
    } else {
        c.connPool.Put(ctx, cn)
    }
}

https://github.com/redis/go-redis/blob/c0ab7815ea66b036d0cb02e2902a7820551d948a/redis.go#L336C1-L346C2

ReadTimeoutする場合

じゃあReadTimeoutなどは大丈夫なのかというと、

func main() {
        cli := redis.NewClient(&redis.Options{
                Addr:                  "localhost:6379",
                ReadTimeout:           10 * time.Millisecond,
                WriteTimeout:          3 * time.Second,
        })
        for i := 0; i < 3; i++ {
                // KEYS *
                _, err := cli.Keys(context.TODO(), "*").Result()
                time.Sleep(1 * time.Second)
        }
        time.Sleep(3 * time.Second)
}

こちらもコネクションがクローズされました。

ただしcontext timeoutが全処理の合計としてのtimeoutとして扱われがちのに対し、ReadTimeoutやWriteTimeoutはコマンドは都度の通信で設定されるのでハンドリングしやすいと言えます。

対応

これまでの内容から以下のことを念頭に置く必要があります。

  1. 読み取り処理、書き込み処理それぞれにおいてReadTimeout, WriteTimeoutが影響する
  2. 特にReadTimeoutはレスポンスの取得に使われるので注意
  3. Timeoutが発生するとコネクションがクローズされ再利用されなくなるため、よりレイテンシが悪化しTimeoutが起きやすくなるので負のループに陥る
  4. Context TimeoutよりはReadTimeout, WriteTimeoutの方がオススメ

まとめ

go-redisを使う上でのTimeoutの扱い方の注意を説明しました。

参考