nginx の時刻周りの処理について

openresty をいじっていてマニュアルをチラ見してると、時刻周りのAPIの説明にこんなことが書かれている。

ngx.time

syntax: secs = ngx.time()
context: init_worker_by_lua, set_by_lua*, rewrite_by_lua*, access_by_lua*, content_by_lua*, header_filter_by_lua*, body_filter_by_lua*, log_by_lua*, ngx.timer.**

Returns the elapsed seconds from the epoch for the current time stamp from the nginx cached time (no syscall involved unlike Lua's date library).

nginx がキャッシュしてる時間を返すよってことなんだけど、そういえば nginx って時刻の処理はどうやってるのか少し気になったのでソースコードを見てみるのだけれど、まずは openresty であるところの ngx_lua_module のコードから ngx.time APIのコードを探して、なにをやってるかを見てみる。

たぶん time なんちゃら的なファイルだろなと思ったので覗いてみると、
https://github.com/openresty/lua-nginx-module/blob/master/src/ngx_http_lua_time.c#L217 に登録してる箇所を発見。

lua_pushcfunction(L, ngx_http_lua_ngx_time);
lua_setfield(L, -2, "time");

そこから ngx_http_lua_ngx_time 関数を見てみると。

static int
ngx_http_lua_ngx_time(lua_State *L)
{
    lua_pushnumber(L, (lua_Number) ngx_time());

    return 1;
}

nginx のソースコード探訪

ngx_time() が nginx の API なわけだねってことで次は nginx のソース覗いてみたいので、とりあえず最新安定バージョンの 1.6.0 のソースを落として find ./src | xargs grep ngx_time でソースファイルのあるディレクトリの中を探索してみる・・・いっぱいでてくる。。

ざっくり結果を見てると ./src//core/ngx_times.h:#define ngx_time() ngx_cached_time->sec なんて箇所を発見。てことは、関数じゃなくてマクロでグローバル変数を参照してるんだね。

んじゃ、この ngx_cached_time の値を更新してる箇所はどこか探さなきゃいけないので find ./src/ | xargs grep ngx_cached_time で探してみると ./src//core/ngx_times.c: ngx_cached_time = tp; というそれっぽい箇所があったのでソースを覗いてみる。

void
ngx_time_update(void)
{
    u_char          *p0, *p1, *p2, *p3;
    ngx_tm_t         tm, gmt;
    time_t           sec;
    ngx_uint_t       msec;
    ngx_time_t      *tp;
    struct timeval   tv;

    if (!ngx_trylock(&ngx_time_lock)) {
        return;
    }

    ngx_gettimeofday(&tv);

    sec = tv.tv_sec;
    msec = tv.tv_usec / 1000;

    ngx_current_msec = (ngx_msec_t) sec * 1000 + msec;

    tp = &cached_time[slot];

// 長いので中略

    p3 = &cached_http_log_iso8601[slot][0];

    (void) ngx_sprintf(p3, "%4d-%02d-%02dT%02d:%02d:%02d%c%02d:%02d",
                       tm.ngx_tm_year, tm.ngx_tm_mon,
                       tm.ngx_tm_mday, tm.ngx_tm_hour,
                       tm.ngx_tm_min, tm.ngx_tm_sec,
                       tp->gmtoff < 0 ? '-' : '+',
                       ngx_abs(tp->gmtoff / 60), ngx_abs(tp->gmtoff % 60));


    ngx_memory_barrier();

    ngx_cached_time = tp;
    ngx_cached_http_time.data = p0;
    ngx_cached_err_log_time.data = p1;
    ngx_cached_http_log_time.data = p2;
    ngx_cached_http_log_iso8601.data = p3;

    ngx_unlock(&ngx_time_lock);
}

この ngx_time_update で時刻だけじゃなくてログ書き出し時の時刻フォーマット文字列もキャッシュしてるってことがわかった。ということは最終的にここを呼び出してる箇所が更新のロジックとなるので、またまた find ./src/ | xargs grep ngx_time_update てな感じで探してみる。

イベント処理周りのソースっぽいとこがずらずらいっぱい出て来たけど、わかりやすそうなので ./src//event/modules/ngx_kqueue_module.c: ngx_time_update(); を見てみると ngx_kqueue_process_events 関数の中に以下のコードを発見。

ngx_kqueue_process_events(ngx_cycle_t *cycle, ngx_msec_t timer,
    ngx_uint_t flags)
{

// 長いのでまたまた中略

    events = kevent(ngx_kqueue, change_list, n, event_list, (int) nevents, tp);

    err = (events == -1) ? ngx_errno : 0;

    if (flags & NGX_UPDATE_TIME || ngx_event_timer_alarm) {
        ngx_time_update();
    }

kevent から復帰した後にフラグチェックして ngx_time_update を呼んでる。flags は引数で渡されてて追うのがめんどくさそうなので ngx_event_timer_alarm というグローバル変数を find ./src/ | xargs grep ngx_event_timer_alarm 探してみる。

kqueue 以外の epoll や devpoll といった他のイベント処理コードでも同じように処理してるようでぞろぞろ出て来たけど ./src//event/ngx_event.c: ngx_event_timer_alarm = 1; という箇所で値をセットしてるのでこの中身を覗いてみる。

static void
ngx_timer_signal_handler(int signo)
{
    ngx_event_timer_alarm = 1;

#if 1
    ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ngx_cycle->log, 0, "timer signal");
#endif
}

名前と引数から察するとシグナルハンドラで呼んでるんだね。んじゃ、このハンドラを登録してる箇所を探す。

static ngx_int_t
ngx_event_process_init(ngx_cycle_t *cycle)
{
// ながーいのでry

    if (ngx_timer_resolution && !(ngx_event_flags & NGX_USE_TIMER_EVENT)) {
        struct sigaction  sa;
        struct itimerval  itv;

        ngx_memzero(&sa, sizeof(struct sigaction));
        sa.sa_handler = ngx_timer_signal_handler;
        sigemptyset(&sa.sa_mask);

        if (sigaction(SIGALRM, &sa, NULL) == -1) {
            ngx_log_error(NGX_LOG_ALERT, cycle->log, ngx_errno,
                          "sigaction(SIGALRM) failed");
            return NGX_ERROR;
        }

        itv.it_interval.tv_sec = ngx_timer_resolution / 1000;
        itv.it_interval.tv_usec = (ngx_timer_resolution % 1000) * 1000;
        itv.it_value.tv_sec = ngx_timer_resolution / 1000;
        itv.it_value.tv_usec = (ngx_timer_resolution % 1000 ) * 1000;

        if (setitimer(ITIMER_REAL, &itv, NULL) == -1) {
            ngx_log_error(NGX_LOG_ALERT, cycle->log, ngx_errno,
                          "setitimer() failed");
        }
    }

sigaction でハンドラを登録してるのはわかったけど、どこでシグナル送ってるんだろと思って怪しそうな setitimer を調べてみると Man page of GETITIMER に書いてあった。なるほどね。

気になる NGX_USE_TIMER_EVENT フラグ

てなわけで、シグナルでキャッシュの更新してることがわかったけど NGX_USE_TIMER_EVENT というフラグが立ってる時はどうなのさってことでこっちも調べてみる。ちょうど ngx_time_update の探した時に各イベント処理周りのソースに二カ所ずつくらい入り込んでたので、もう一度 ./src//event/modules/ngx_kqueue_module.c を見てみると以下の箇所を発見。

#if (NGX_HAVE_TIMER_EVENT)

        if (event_list[i].filter == EVFILT_TIMER) {
            ngx_time_update();
            continue;
        }

#endif

NGX_HAVE_TIMER_EVENT が定義されてる時は タイマーイベント で処理するようになってるんだね。じゃ、そこいらを調べてみれば NGX_USE_TIMER_EVENT というフラグを設定してるとこが見つかるかなってことで、そのままソースファイルの中を検索するとやっぱりあった。

static ngx_int_t
ngx_kqueue_init(ngx_cycle_t *cycle, ngx_msec_t timer)
{
// ながーいのry

#if (NGX_HAVE_TIMER_EVENT)

    if (timer) {
        kev.ident = 0;
        kev.filter = EVFILT_TIMER;
        kev.flags = EV_ADD|EV_ENABLE;
        kev.fflags = 0;
        kev.data = timer;
        kev.udata = 0;

        ts.tv_sec = 0;
        ts.tv_nsec = 0;

        if (kevent(ngx_kqueue, &kev, 1, NULL, 0, &ts) == -1) {
            ngx_log_error(NGX_LOG_ALERT, cycle->log, ngx_errno,
                          "kevent(EVFILT_TIMER) failed");
            return NGX_ERROR;
        }

        ngx_event_flags |= NGX_USE_TIMER_EVENT;
    }

#endif

そんなこんなで覗いてみた範囲内では、kqueue なら タイマーイベント が利用可能な場合にはイベントを利用するってことだね。

お腹すいたし、こんな事やってないでランチ食べよ。