[입 개발] Redis 의 slowlog는 어떻게 측정되는가?

Redis 를 쓰면서 많이 참고하게 되는 명령들 중에 slowlog 가 있습니다. 그런데 이 slowlog가 정확하게 뭘 보여주는지에 대해서는 잘 정리가 되어있지 않아서…(너만 몰라… 컥… 퍽퍽퍽) 공부를 해봤습니다.

slowlog 는 뭘까요? 사실 DBMS등에도 보면 해당 쿼리가 얼마나 오래 실행되었는지 보여주는 기능들이 있습니다. 수행 시간(duration)이 얼마이상이면 로그를 남겨주기도 합니다. 어플리케이션에서도 보통 마지막에 수행시간이 얼마 이상이면 따로 로그를 남기지요. nginx 도 호출이 들어가고 나서 응답이 나올 때 까지의 시간을 재서 보여주는 기능이 있습니다.

showlog는 수행 시간이 느린 요청(쿼리)를 보여주는 기능입니다. 그럼 그 수행 시간을 어떻게 정의하는 가에 따라서 천차만별이라고 할 수 있습니다.

일반적으로 생각하는 것은 쿼리를 Redis 가 받아들인 시간 부터 결과가 나오는 시간이라고 생각할 것입니다. 이게 사실 거의 맞긴 합니다. 먼저 Redis에서 시간을 측정하는 코드를 보시죠.

void call(client *c, int flags) {
    long long dirty, start, duration;
    
    ......
    start = ustime();
    c->cmd->proc(c);
    duration = ustime()-start;
    ......
    if (flags & CMD_CALL_SLOWLOG && c->cmd->proc != execCommand) {
        char *latency_event = (c->cmd->flags & CMD_FAST) ?
                              "fast-command" : "command";
        latencyAddSampleIfNeeded(latency_event,duration/1000);
        slowlogPushEntryIfNeeded(c->argv,c->argc,duration);
    }    ......
}

위의 코드를 보면 Redis 에서의 수행 시간을 재는 범위는 명확합니다. 패킷이 완성되어서, 실제로 딱 수행된 시간입니다.

수행된 시간만 들어간다는 의미는 무엇일까요? 즉 패킷이 완성되기 까지 대기하는 시간은 포함되지 않는다는 것입니다. 여기서 Redis slowlog의 맹점이 하나 존재합니다. 그것은 Redis는 Single Threaded 라는 겁니다.

스크린샷 2016-08-09 오전 1.41.44

Redis Event Loop는 처음부터 연결된 이벤트가 발생된 클라이언트의 루프를 돌면서 데이터를 읽고 패킷이 완성되면 그 때 실행하게 됩니다. 그런데 클라이언트들이 많고, 처리해야 하는 명령들이 많다면, 뒤에 있는 녀석은 실행이 늦게될 수 있습니다. 그런데 그 명령이 수행되는 시간 자체는 짧은 경우에 slowlog에는 남지 않습니다. 즉 실제 응답은 늦고 처리도 늦게 되었지만, 명령이 수행되는 시간 자체는 짧으므로, slowlog에 남지 않는 경우가 됩니다.

그러므로 slowlog에 잡히지는 않지만, 서버의 응답이 느려지는 경우는 Redis 서버가 너무 많은 쿼리를 처리하고 있는 건 아닌지 확인하셔야 합니다. 그리고 쿼리 수 가 너무 많다면, 서버를 분리하여, 쿼리 처리량을 줄이는 것이 해결책입니다.