地方エンジニアの学習日記

興味ある技術の雑なメモだったりを書いてくブログ。たまに日記とガジェット紹介。

【Nginx】proxy_cache_lockが思ってたのと違った件

背景

pkg.go.dev

ISUCONの過去問を眺めていたらキャッシュのThundering Herd問題を解決するのにsingleflightというライブラリを使った解決策があることを知ったので調べていたらNginxでも似たようなことをできそうと言うことを知ったので調べてみたメモ。

キャッシュのThundering Herd問題

キャッシュのThundering Herd問題とは

キャッシュアサイドパターンとか呼ばれるパターンのシステム構成があるとしてキャッシュに格納されるデータがそれぞれ単一の生存時間(TTL)を持つ場合にキャッシュデータがエクスパイアした際に発生に発生し得る問題。

例えばエクスパイアされるデータが大量アクセスを並列に受けている場合にオリジンへデータを取得する処理が大量に発生してしまう。この処理が軽いものなら問題は特に起きないが重い計算やクエリをDBへ投げるなどどいった場合にシステムが高負荷になってレスポンス遅延や最悪の場合サービスダウンにまでなってしまう恐れがある。これがThundering HerdやCache Stampedeと呼ばれる問題。

blog.nomadscafe.jp

解決方法

有名な解決方法はwikiにあるように3つある。singleflightは①の方法を使って対策をする実装となっている。(あくまでも1プロセスに限った絞り方なので厳密に1リクエストにするにはプロセス間やサーバ間で分散ロックの仕組みは別途必要となるREDIS による分散ロック)

  • ① ロックを取ってオリジンへのリクエストを絞る
  • ② 他のプロセスで事前にキャッシュを生成する
  • ③ 期限切れ前に一定の確率で期限を更新する

Wikipedia: Cache Stampede

ここで思ったのがNginxにはProxyCacheという機能があって「Nginx -> upstreamの段階でリクエスト絞れれば早いのでは?」と思いそれっぽいオプションないかなと調べ始めたのが記事を書き始めたきっかけ。

proxy_cache_lockというのがあった

proxy_cache_lockというのがあった

Syntax:  proxy_cache_lock on | off;
Default:    
proxy_cache_lock off;
Context:    http, server, location
This directive appeared in version 1.1.12.

When enabled, only one request at a time will be allowed to populate a new cache element identified according to the proxy_cache_key directive by passing a request to a proxied server. Other requests of the same cache element will either wait for a response to appear in the cache or the cache lock for this element to be released, up to the time set by the proxy_cache_lock_timeout directive.

Module ngx_http_proxy_module

プロキシサーバーにリクエストを渡すことで、proxy_cache_keyディレクティブに従って識別された新しいキャッシュ要素に一度に1つのリクエストのみを送れるようになるとのこと。これで要件を満たせそう!となったがそんなに甘くはなかった。

検証用環境を作る

環境は以下。

  • Webアプリ: Flask
  • Webサーバ: nginx-1.21.1

アプリ

threadedをtrueにすることで並行にリクエストを受けれるようになる。(gunicornとか入れれば良いが簡易的な検証なのでこれで)。sleepというエンドポイントを用意して重いリクエストを再現する。

#!/bin/env python

from flask import Flask
import time

app = Flask(__name__)

@app.route("/sleep")
def sleep():
    time.sleep(2)
    return "sleeping"


if __name__ == "__main__":
    app.run(host="0.0.0.0", threaded=True)

nginx.conf

proxy_cacheとproxy_cache_lockを設定してあればよい。

upstream app {
    server flask:5000;
}

proxy_cache_path /var/cache/nginx keys_zone=zone1:1m max_size=1g inactive=24h;

server {
    listen       80;
    server_name  localhost;

    location / {
        proxy_pass http://app;
        proxy_http_version 1.1;
        proxy_set_header Connection "";
        proxy_cache zone1;
        proxy_cache_valid 200 302 10s;
        proxy_cache_lock on;
        add_header X-Nginx-Cache $upstream_cache_status;
    }
}

いざ実験!

4プロセスで合計4リクエストを投げる。

seq 1 16 | xargs -I{} -P 4 curl http://localhost/sleep -o /dev/null -s

1回目

flask_1が1回であとはnginx_1だけが出力されている。成功している模様。完璧!

flask_1  | 192.168.80.4 - - [23/Aug/2021 15:33:30] "GET /sleep HTTP/1.1" 200 -
nginx_1  | 192.168.80.1 - - [23/Aug/2021:15:33:30 +0000] "GET /sleep HTTP/1.1" 200 8 "-" "curl/7.64.1" "-"
nginx_1  | 192.168.80.1 - - [23/Aug/2021:15:33:30 +0000] "GET /sleep HTTP/1.1" 200 8 "-" "curl/7.64.1" "-"
nginx_1  | 192.168.80.1 - - [23/Aug/2021:15:33:30 +0000] "GET /sleep HTTP/1.1" 200 8 "-" "curl/7.64.1" "-"
nginx_1  | 192.168.80.1 - - [23/Aug/2021:15:33:30 +0000] "GET /sleep HTTP/1.1" 200 8 "-" "curl/7.64.1" "-"

キャッシュのttl切れを待って2回目を実施

flask_1  | 192.168.80.4 - - [23/Aug/2021 15:33:48] "GET /sleep HTTP/1.1" 200 -
flask_1  | 192.168.80.4 - - [23/Aug/2021 15:33:48] "GET /sleep HTTP/1.1" 200 -
flask_1  | 192.168.80.4 - - [23/Aug/2021 15:33:49] "GET /sleep HTTP/1.1" 200 -
nginx_1  | 192.168.80.1 - - [23/Aug/2021:15:33:49 +0000] "GET /sleep HTTP/1.1" 200 8 "-" "curl/7.64.1" "-"
flask_1  | 192.168.80.4 - - [23/Aug/2021 15:33:49] "GET /sleep HTTP/1.1" 200 -
nginx_1  | 192.168.80.1 - - [23/Aug/2021:15:33:49 +0000] "GET /sleep HTTP/1.1" 200 8 "-" "curl/7.64.1" "-"
nginx_1  | 192.168.80.1 - - [23/Aug/2021:15:33:49 +0000] "GET /sleep HTTP/1.1" 200 8 "-" "curl/7.64.1" "-"
nginx_1  | 192.168.80.1 - - [23/Aug/2021:15:33:49 +0000] "GET /sleep HTTP/1.1" 200 8 "-" "curl/7.64.1" "-"

!!??

1回目の結果と違って全てのリクエストがupstreamまで全てのリクエストが到達してしまっている。原因をググるもよくわからない。

ソースを眺める

gdbを使って関連しそうな処理を特定。

ngx_http_file_cache_lockという関数が具体的にキャッシュのロックを取って取得できたプロセスがupstreamへリクエストを流すと言った処理を行なっている。この関数を呼び前段の関数(ngx_http_file_cache_open)を見る。

ngx_int_t
ngx_http_file_cache_open(ngx_http_request_t *r)
{
    // キャッシュファイルを読み取る。NGX_OKならコンテンツをreadして返す
    if (ngx_open_cached_file(clcf->open_file_cache, &c->file.name, &of, r->pool)
        != NGX_OK)
    {
        switch (of.err) {

        case 0:
            return NGX_ERROR;

        // ファイル/ディレクトリが存在しないケース
        case NGX_ENOENT:
        case NGX_ENOTDIR:
            goto done;  // ここのgotoに入る必要がある
        }
    }

done:

    if (rv == NGX_DECLINED) {
        // ここでロックを取る処理を呼び出す。
        return ngx_http_file_cache_lock(r, c);
    }

    return rv;
}

// ロックを取るなどの処理はこっち。"ngx_shmtx_lock"とあるように共有メモリを使ったロック
static ngx_int_t
ngx_http_file_cache_lock(ngx_http_request_t *r, ngx_http_cache_t *c)
{
    ngx_shmtx_lock(&cache->shpool->mutex);

    timer = c->node->lock_time - now;

    // 最初のリクエストのみここに入る
    if (!c->node->updating || (ngx_msec_int_t) timer <= 0) {
        c->node->updating = 1;
        c->node->lock_time = now + c->lock_age;
        // ステータスを更新する
        c->updating = 1;
        c->lock_time = c->node->lock_time;
    }

    ngx_shmtx_unlock(&cache->shpool->mutex);

キャッシュファイル/ディレクトリが存在しないケースでなければ処理そのもの(ngx_http_file_cache_lock)が動かない仕様らしい。キャッシュがEXPIRED(ttl切れ)の場合はどうやら動かないらしい。やるならgoto ラベルするケースにcacheのttlを見るような処理が必要となる。(またはpurgeする仕組みを独自に実装する)

この件に関しては言及しているコメントはちらほら見つけることができた。概ね調べた内容と同じようなことが書かれていた。

stackoverflow.com

やりたいことをやるなら以下の機能を組み合わせることで実現できそうなので別記事で対応してみることにする。

* proxy_cache_background_update
* proxy_cache_use_stale

おまけ: ApacheBenchは最初に1リクエスト飛ばしている?

github.com

abコマンドでテストしようとしてたらうまくいかなかった。ab -c 3 -n 3 http://localhost/sleepみたいに実行したら1リクエストだけ先に飛ばしてそれを待って残りの2リクエストを処理するような流れになっているみたいでした(ソースは未確認)。この動きだと最初のリクエストがproxy_cacheに載ってしまって都合が良くないと言った現象が起きてました。

以下はtcpdumpの結果。理由はよくわからないですがテスト結果に必要な情報を初回リクエストで取得してるとかですかね〜。

#### 1リクエスト目
01:04:39.878390 IP6 ::1.50763 > ::1.80: Flags [S], seq 1933344289, win 65535, options [mss 16324,nop,wscale 6,nop,nop,TS val 3092785126 ecr 0,sackOK,eol], length 0
01:04:39.878502 IP6 ::1.50763 > ::1.80: Flags [.], ack 2113740241, win 6371, options [nop,nop,TS val 3092785126 ecr 4235194127], length 0
01:04:39.878525 IP6 ::1.50763 > ::1.80: Flags [P.], seq 0:82, ack 1, win 6371, options [nop,nop,TS val 3092785126 ecr 4235194127], length 82: HTTP: GET /sleep HTTP/1.0
01:04:42.884627 IP6 ::1.50763 > ::1.80: Flags [.], ack 165, win 6369, options [nop,nop,TS val 3092788128 ecr 4235197129], length 0
01:04:42.884711 IP6 ::1.50763 > ::1.80: Flags [.], ack 166, win 6369, options [nop,nop,TS val 3092788128 ecr 4235197129], length 0

#### 2以降。sleepで指定した時間を待ってリクエストしている。
01:04:42.885305 IP6 ::1.50764 > ::1.80: Flags [P.], seq 0:82, ack 1, win 6371, options [nop,nop,TS val 1632426051 ecr 2438025469], length 82: HTTP: GET /sleep HTTP/1.0
01:04:42.885321 IP6 ::1.50765 > ::1.80: Flags [P.], seq 0:82, ack 1, win 6371, options [nop,nop,TS val 3660829198 ecr 1860469325], length 82: HTTP: GET /sleep HTTP/1.0