Server

Redis LATENCY subcommand

Redis Server Course	Redis Technical Support	Redis Enterprise Server

Redis LATENCY

Latency Monitor(응답시간 모니터)는 시간을 millisecond로 설정해서, 레디스 서버에서 실행되는 명령/오퍼레이션의 수행시간이 설정한 시간 이상이면 기록해서 분석할 수 있는 레디스 서버 성능 분석 도구입니다. Slowlog 와 같이 사용하면 더욱 세밀한 분석이 가능합니다. 이 기능은 2014년 7월 14일(월) 발표된 버전 2.8.13부터 사용가능합니다.

활성화 방법 - 응답시간 설정

Latency Monitor 기능은 디폴트로 disable 되어 있습니다. 활성화 방법은 redis.conf LATENCY MONITOR 파트에 latency-monitor-threshold 파라미터의 값을 1 이상으로 설정하고 레디스 서버를 시작하면 됩니다. 0 이면 Latency Monitor 기능을 사용하지 않는 것입니다. 단위는 millisecond 이고, 디폴트는 0 입니다.

Threshold 시간은 서버 실행 중에도 config 명령으로 변경 가능합니다. 설정은 config set latency-monitor-threshold <milliseconds> 이고, config get latency-monitor-threshold로 현재 설정된 값을 볼 수 있습니다.

응답시간 모니터 대상 - 명령/오퍼레이션

응답시간 모니터는 event-name으로 구분되어 기록되면, 버전 3.2.0 기준으로 15가지 이벤트가 있습니다. 종류별로 보면 클라이언트에서 수행하는 모든 명령(2가지), AOF(8가지), RDB(1가지) 수행, fork(1가지), 만료된(expire) 키 삭제(1가지), Maxmemory 설정에 따른 키 삭제(2가지)입니다.

기억할 것은 이벤트 기록은 초 단위로 되며, 같은 이벤트가 1초에 여러번 발생했을 경우에는 가장 큰 값 하나만 기록됩니다. 자세한 Event 설명은 여기를 보세요.

버전 3.2.0 버그 2가지 영향과 수정 방법

Max 값 버그 영향과 수정 방법

같은 이벤트가 1초 안에 여러 번 발생했을 때, Max 값이 Update 되지 않는 버그가 있다.
버그를 그대로 두면,
latest 3)에 나오는 최근 응답시간이 4)에 나오는 최대(max) 응답시간 보다 큰 경우가 발생하고,
graph에서 "all time high"와 doctor에서 "Worst all time event" 시간이 최대 응답시간이 아닌 경우가 발생한다.

버그 수정 방법은 latency.c에 있는 latencyAddSample()에 아래 한 줄을 추가하면 된다.

if (latency > ts->max) ts->max = latency;

void latencyAddSample(char *event, mstime_t latency) {
	... 중간 생략 ...
    if (ts->samples[prev].time == now) {
        if (latency > ts->samples[prev].latency)
            ts->samples[prev].latency = latency;
        if (latency > ts->max) ts->max = latency; 	/* Add this line */
        return;
    }
	... 이후 생략 ...

이 버그는 2018년 3월 26일(월)에 발표된 버전 4.0.9 에서 수정되었습니다.

rdb-unlink-temp-file 이벤트명 오류 영향과 수정 방법

RDB 임시 파일 삭제 응답시간 이벤트명을 rdb.c에서 기록할 때는 "rdb-unlink-temp-file"으로 하는데, latency.c에서 doctor로 분석할 때는 'unlink' 에서 'n'을 빼고 'unlik'로 해서 doctor에서 분석 데이터가 나오지 않는다.
createLatencyReport()에서 "rdb-unlik-temp-file"를 "rdb-unlink-temp-file"로 수정하면 된다.

sds createLatencyReport(void) {
	... 중간 생략 ...
	if (!strcasecmp(event,"aof-fstat") ||
		!strcasecmp(event,"rdb-unlink-temp-file")) {
		advise_disk_contention = 1;
		advise_local_disk = 1;
		advices += 2;
	... 이후 생략 ...

LATENCY Subcommand

Latency 명령에는 총 5개의 subcommand가 있다.

LATEST: 사용법 latency latest
Latency Monitor에 기록된 모든 이벤트명, 마지막 실행 시각(Linux timestamp), 마지막 수행된 응답시간(milliseconds), 가장 오래 걸린 응답시간(milliseconds)을 보여준다.
LATESTH: 사용법 latency latesth
보기 쉽게(Human) 표기했습니다.
HISTORY: 사용법 latency history event-name
주어진 이벤트의 실행 시각(Linux timestamp)과 수행 시간(milliseconds)를 최근 160개까지 보여준다.
HISTORYH: 사용법 latency historyh event-name
보기 쉽게(Human) 표기했습니다.
LOG: 사용법 latency log
내용을 로그 파일에 기록합니다.
GRAPH: 사용법 latency graph event-name
응답 시간을 특수문자를 사용해서 막대그래프로 최근 160개까지 보여준다.
DOCTOR: 사용법 latency doctor
응답시간 기록을 토대로 분석해서 통계정보(발생 횟수, 평균, 평균 편차(mean deviation), 최대값)과 권고 사항(advices)를 문장으로 보여준다.
RESET: 사용법 latency reset [event-name ... event-name]
Latency Monitor 기록을 삭제한다. Event-name이 주어지면 해당하는 기록만 삭제하고, 주어지지 않으면 모든 이벤트(응답시간) 기록을 삭제한다.

LATENCY LATEST

최근 응답시간을 포함해서 발생한 이벤트 리스트를 보여주는 기능이다. 이 명령으로 Latency Monitor에 어떤 이벤트들이 기록되었는지 확인할 수 있다.
이벤트별로 다음 네 항목을 보여준다.

이벤트명
마지막 실행 시각(Linux timestamp)
마지막 수행된 응답시간(milliseconds)
가장 오래걸린 응답시간(milliseconds)

우선 latency monitor를 활성화(5ms 이상 응답시간)하고, 기록을 삭제한다.

127.0.0.1:6200> config set latency-monitor-threshold 5
OK
127.0.0.1:6200> latency reset
(integer) 1

일반 명령은 5ms 이상 걸리게 하기 어려우므로, debug sleep 명령을 이용해서 테스트한다.

127.0.0.1:6200> debug sleep 1
OK
(1.00s)
127.0.0.1:6200> debug sleep 0.4
OK
127.0.0.1:6200> latency latest
1) 1) "command"  <- 이벤트명
   2) (integer) 1463729306  <- 마지막 명령 실행 시작 Linux timestamp
   3) (integer) 400         <- 마지막 명령 수행 응답시간(ms)
   4) (integer) 1000        <- 응답시간이 가장 큰(max) 시간

발생한 이벤트 모두 리스트로 나온다. 그러므로 어떤 이벤트가 발생했는지를 알 수 있어서, 이벤트 확인 용도로도 많이 사용된다.

LATENCY LATESTH

위 내용을 보기 쉽게 표현했습니다. H는 Human의 약자입니다.

127.0.0.1:6000> latency latesth
1) 1) "Event: command"
     2) "Last Time: 2019-09-13 00:22:25"
     3) "Last Duration(ms):        3"
     4) "Max Duration(ms):         3"

이 기능은 Enterprise 버전에서 사용 가능합니다.

LATENCY HISTORY

Latency monitor는 각 이벤트 당 160개의 기록을 유지한다.
사용법은 latency history event-name 이다.
위 테스트 결과를 history로 확인해 보자.

127.0.0.1:6200> latency history command
1) 1) (integer) 1463729290   <- debug sleep 1 실행 시각 Linux timestamp
   2) (integer) 1000              <- debug sleep 1 실행 시간 1000ms
2) 1) (integer) 1463729306	 <- debug sleep 0.4 실행 시각 Linux timestamp	
   2) (integer) 400  		     <- debug sleep 0.4 실행 시간 400ms

LATENCY HISTORYH

위 내용을 보기 쉽게 표현했습니다. H는 Human의 약자입니다.

127.0.0.1:6000> latency historyh command
1) 1) "Time: 2019-09-13 00:22:20"
   2) "Duration(ms):        2"
2) 1) "Time: 2019-09-13 00:22:25"
   2) "Duration(ms):        3"

이 기능은 Enterprise 버전에서 사용 가능합니다.

LATENCY LOG

내용을 로그 파일에 기록합니다.

Event name               Timestamp           Duration(ms)
aof-write                2019-09-12 23:00:02           1
aof-write                2019-09-12 23:00:03           1
command                  2019-09-13 00:22:20           2
command                  2019-09-13 00:22:25           3

이 기능은 Enterprise 버전에서 사용 가능합니다.

LATENCY GRAPH

응답 시간을 특수문자를 사용해서 막대그래프(ASCII-art style)로 최근 160개까지 보여준다.
debug sleep 명령을 이용해서 그래프가 어떻게 그려지는지 확인해보자.

'high'는 최근 160개 중에서 가장 큰 값, 'low'는 최근 160개 중에서 가장 적은 값이다. 'all time high'는 이벤트가 기록된 처음부터 현재까지 중 가장 큰 값이다. 예를 들어 현재까지 300개의 'command' 이벤트가 발생했다면, 'high'는 최근 160개 중에서 가장 큰 값이고, 'all time high'는 300개 중에서 가장 큰 값이다. 그러므로 'all time high'는 'high'보다 크거나 같은 값이어야 한다.

127.0.0.1:6200> debug sleep 0.1
127.0.0.1:6200> debug sleep 0.2
127.0.0.1:6200> debug sleep 0.3
127.0.0.1:6200> debug sleep 0.4
127.0.0.1:6200> debug sleep 0.5
127.0.0.1:6200> debug sleep 0.4
127.0.0.1:6200> debug sleep 0.3
127.0.0.1:6200> debug sleep 0.2
127.0.0.1:6200> debug sleep 0.1
127.0.0.1:6200> latency graph command
command - high 500 ms, low 100 ms (all time high 500 ms)
--------------------------------------------------------------------------------
   _#_   
  _|||_  
 _|||||_ 
_|||||||_
         
332222111
208740754
sssssssss

그래프가 폰트에 따라 그래프가 좀 이상하게 보일 수 있어서 이미지를 복사했다.

그림 1-1 Latency graph ASCII-art style

이 데이터로 일반적인 막대그래프를 그리면 다음과 같다.

그림 1-2 Latency bar graph

ASCII-art 스타일 막대그래프는 4층으로 그려지고, 값에 따라 비율이 정해진다. 응답시간이 크다고 그래프를 더 높게 그리지 않는다. 각 막대그래프 위쪽에 문자는 값에 따라 '_', 'o', '#' 중 하나로 그려진다.
그래프 아래에 있는 숫자는 각 막대그래프 명령이 실행된 시간을 지금 시간에서 뺀것이다. 숫자는 세로(칼럼)으로 봐야 한다. 첫 번째 노란색 박스를 가로로 표현하면 '32s'인데 이것은 32초 전에 실행했다는 뜻이다.
두 번째 하늘색 박스(마지막 숫자)는 '14s'인데 이것은 14초 전에 실행했다는 뜻이다.
초는 's', 분은 'm', 시는 'h', 일은 'd'로 표시한다.

몇 분 후에 latency graph 명령을 다시 실행했을 때 나온 화면이다.

그림 1-3 Latency graph ASCII-art style

그래프 아래 시간이 모두 '15m'으로 바뀌었다. 15분 전에 실행되었다는 것이다.

debug sleep 명령으로 몇 번 더 입력하고 다시 그래프를 보자.

127.0.0.1:6200> debug sleep 0.01
127.0.0.1:6200> debug sleep 0.02
127.0.0.1:6200> debug sleep 0.03
127.0.0.1:6200> debug sleep 1

마지막 실행한 sleep 1초 짜리 명령으로 이전 막대그래프가 줄어들었다.

그림 1-4 Latency graph ASCII-art style

이 기록들은 모두 threshold 값 이상이어야 한다. threshold 값 미만은 기록되지 않는다.

LATENCY DOCTOR

응답시간 기록을 토대로 분석해서 통계정보(발생 횟수, 평균, 평균 편차(mean deviation), 최대값)과 권고 사항(advices)를 문장으로 보여준다.

명령을 실행하면 맨 위에 다음과 같은 문장을 보여준다.

Dave, I have observed latency spikes in this Redis instance.
You don't mind talking about it, do you Dave?

레디스 인스턴스에서 몇 개의 튀는 값을 관찰했습니다. 말씀드려도 되겠죠? 데이브.

다음에 이벤트명, 발생 횟수(latency spikes), 평균(average), 평균 편차(mean deviation), 기간(period), 최대값(Worst all time event)을 보여준다.

1. aof-fsync-always: 160 latency spikes (average 30ms, mean deviation 11ms, period 3.12 sec). Worst all time event 80ms.

여기서 기간(period)은 latency doctor를 실행하는 현재 시각에서 처음 이벤트가 발생한 시각을 뺀 시간을 발생 횟수로 나누어 준 값이다. 즉 이벤트가 평균 몇 초 간격으로 나타났는지를 알려주는 정보이다. 그런데 이 기간(period)을 현재 시각에서 계산하므로 명령을 실행할 때마다 증가한다.

문제 분석 관점에서 보면, 마지막 발생 시각에서 처음 발생 시각을 뺀 시간을 발생 횟수로 나눈 값이 더 가치 있을 것으로 본다. 예를 들어 이틀 전에 어떤 이벤트가 1분 동안 30회 발생하고 이후에 발생하지 않았다면, 지금 제시한 새 방식으로 계산한 기간(period)은 2sec로, 1분 동안 2초 간격으로 30회 발생했다는 것을 발견할 수 있다. 그런데 현재 방식대로 계산하면 현재 시각을 기준으로 기간(period)을 계산하므로 2초 훨씬 보다 큰 값이 나오므로, 문제를 분석하는데 도움이 되지 않을 것으로 생각된다.
현재 방식이 개발자의 의도인지 실수인지 알 수 없다.

다음에 아래와 같이 "몇 가지 권고사항이 있습니다."라는 말을 하고 권고사항을 문장으로 보여준다.

I have a few advices for you:

권고사항은 아래 이벤트별로 자세히 설명하겠습니다.

redis.io의 latency-monitor 문서 맨 마지막에 다음과 문장이 있습니다.

The doctor has erratic psychological behaviors, so we recommend interacting with it carefully.

여기서 제시하는 권고사항을 바로 그대로 따르지 말고, 충분한 테스트를 거친 후 신중하게 적용하기를 바랍니다.

LATENCY RESET

모든 이벤트 또는 특정 이벤트의 Latency monitor 기록을 삭제한다.
사용법은 latency reset [event-name ... event-name] 이다.
이벤트명을 하나 이상 줄 수 있고, 이벤트명을 주지 않으면 모든 이벤트의 latency monitor 기록을 삭제한다.

127.0.0.1:6200> latency reset
(integer) 1
127.0.0.1:6200> latency history command
(empty list or set)	      <- 좀 전에 보았던 기록이 삭제되었다.

LATENCY EVENT

응답시간 모니터는 event-name으로 구분되어 기록되면, 버전 3.2.0 기준으로 15가지 이벤트가 있습니다. 종류별로 보면 AppendOnly 관련 이벤트가 8가지로 가장 많고, RDB 1가지, Fork(AOF, RDB) 1가지, 만료된 키를 삭제하는 Expire 관련 이벤트 1가지, Maxmemory 설정에 따라 키를 삭제하는 Eviction 이벤트가 2가지, 끝으로 모든 명령을 fast-command와 일반 command로 구분해서 각 1가지씩 있습니다.

명령은 각 명령 이름(command-name)이 기록되는 것이 아니고, fast-command와 command로만 구분되어 기록되므로 실제로 어느 명령에서 수행시간이 오래 걸렸는지는 알 수 없습니다.
각 명령에 대한 수행시간 기록은 Slowlog을 사용하시면 됩니다.

아래 리스트는 이벤트명과 간단한 설명입니다. 이벤트명을 클릭하면 자세한 설명 섹션으로 이동합니다.

fast-command: fast 명령, 수행 시간이 O(1) 또는 O(log(N)) 인 명령,
command: fast-command를 제외한 명령
aof-fsync-always: appendfsync가 always 일때 fsync()를 수행하는데 소요된 시간
aof-write: AOF write를 수행하는데 소요된 시간
aof-write-pending-fsync: AOF thread가 fsync를 수행하는 중에 write를 수행했을 때 write에 소요된 시간
aof-write-active-child: AOF 또는 RDB Child Process가 수행하는 중에 write를 수행했을 때 write에 소요된 시간
aof-write-alone: 일반적인 경우(위 두 경우가 아님)에 write를 수행했을 때 write에 소요된 시간
aof-rewrite-diff-write: AOF Child Process가 rewrite를 종료한 다음, Parent Process가 serverCron에서 남아있는 AOF buffer의 내용을 write 하는데 걸린 시간.
aof-rename: Parent Process가 AOF write를 완료한 후에 rename() 하는데 소요된 시간.
aof-fstat: file 정보(size 등)를 얻어오는데 걸린 시간
fork: AOF나 RDB Child Process를 fork 하는데 걸린 시간
rdb-unlink-temp-file: Background로 RDB 파일 저장 시 오류가 발생하여 임시 RDB 파일 삭제을 삭제하는데 걸린 시간
expire-cycle: 만료된 키를 삭제하는데 소요된 시간
eviction-cycle: 메모리 부족시 부족한 만큼의 메모리를 확보하기 위해 데이터(키)들를 삭제하는데 소요된 시간
eviction-del: 위 작업 시 키 하나를 삭제하는데 소요된 시간

LATENCY FAST-COMMAND

Fast-command는 일반적으로 수행 시간이 O(1) 또는 O(log(N))인 명령이지만, 반드시 그런 것은 아니다. 하여간 빠르게 수행되는 명령이다.
버전 3.2.0 기준으로 총 171개 명령 중 Fast-command는 67개, Command는 104개이다.
일반적으로 fast-command는 latency monitor에 잘 잡히지 않는다.
다음은 server.c에 있는 Fast-command에 대한 설명이다.

 Fast command: O(1) or O(log(N)) command that should never delay
 its execution as long as the kernel scheduler is giving us time.
 Note that commands that may trigger a DEL as a side effect (like SET)
 are not fast commands.

latency doctor : fast-command

이 이벤트의 권고 사항은 다음과 같다. - The system is slow to execute Redis code paths not containing system calls. This usually means the system does not provide Redis CPU time to run for long periods. You should try to: 1) Lower the system load. 2) Use a computer / VM just for Redis if you are running other softawre in the same system. 3) Check if you have a "noisy neighbour" problem. 4) Check with 'redis-cli --intrinsic-latency 100' what is the intrinsic latency in your system. 5) Check if the problem is allocator-related by recompiling Redis with MALLOC=libc, if you are using Jemalloc. However this may create fragmentation problems.

Fast-command와 Command에 대한 리스트를 보려면 여기를 클릭하세요.

LATENCY COMMAND

Command는 Fast-command를 제외한 명령이다.
버전 3.2.0 기준으로 총 171개 명령 중 Command는 104개이다. 위에서 테스트한 debug 명령은 command에 해당한다.

latency doctor : command

Slowlog가 disable되어 있으면, slowlog-log-slower-than 파라미터를 latency_monitor_threshold*1000으로 설정하라는 권고이다. 5000은 threshold 값에 따라 다르다. - There are latency issues with potentially slow commands you are using. Try to enable the Slow Log Redis feature using the command 'CONFIG SET slowlog-log-slower-than 5000'. If the Slow log is disabled Redis is not able to log slow commands execution for you.

Slowlog가 enable되어 있으면, slowlog-log-slower-than 파라미터를 latency_monitor_threshold*1000으로 변경하라는 권고이다. 여기서도 5000은 threshold 값에 따라 다르다. - Your current Slow Log configuration only logs events that are slower than your configured latency monitor threshold. Please use 'CONFIG SET slowlog-log-slower-than 5000'.

Slowlog 설정과 관계없이 다음 두 가지 권고사항이 나온다. - Check your Slow Log to understand what are the commands you are running which are too slow to execute. Please check http://redis.io/commands/slowlog for more information. - Deleting, expiring or evicting (because of maxmemory policy) large objects is a blocking operation. If you have very large objects that are often deleted, expired, or evicted, try to fragment those objects into multiple smaller objects.

Fast-command와 Command에 대한 리스트를 보려면 여기를 클릭하세요.

LATENCY AOF-FSYNC-ALWAYS

이 이벤트가 발생할 조건은 appendonly가 yes이고 appendfsync가 always 일때이다. 이 경우에 fsync()를 수행하는데 소요된 시간을 기록한다. fsync는 메모리에 있는 데이터를 디스크에 쓰는 오퍼레이션이다. 따라서 always로 했을 경우 fsync는 write마다 실행되어 성능에 가장 큰 영향을 미친다.

자. 이제 appendfsync를 always로 설정해 놓고 테스트해보자.

127.0.0.1:6200> config set appendfsync always
OK

Python을 이용해서 set 명령으로 길이 115 바이트 값을 10000회 입력했다.
다음는 Python 소스이다. 파일명은 test.py이다.

def set115(conn,key,start_index,end_index):
    print '=== STRING : set115 test ==='
    start_time=time.time()
    print 'Start time:',start_time
    msg = "Redis is an open source (BSD licensed), in-memory data structure store, used as database, cache and message broker."
    i = start_index
    while i <= end_index:
       conn.set(key+str(i),msg)
       i = i+1
    end_time = time.time()
    print 'End time:', end_time
    print 'Elapsed time(sec):', end_time-start_time

Python에서 실행 방법과 결과이다.

[root@localhost redis-3.2.0]# python
Python 2.7.5 (default, Jun 17 2014, 18:11:42) 
[GCC 4.8.2 20140120 (Red Hat 4.8.2-16)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import redis
>>> import test
>>> conn=redis.Redis(port=6200)
>>> test.set115(conn,'key',1,10000)
=== STRING : set115 test ===
Start time: 1464335491.6
End time: 1464335697.71
Elapsed time(sec): 206.10338378

latency latest

latency latest 명령으로 결과를 확인해 보자. 최대값이 103이고 이것은 'all time high' 값이다.

127.0.0.1:6200> latency latest
1) 1) "aof-fsync-always"
   2) (integer) 1464335697
   3) (integer) 22
   4) (integer) 103

latency history aof-fsync-always

latency history aof-fsync-always 명령으로 결과를 확인해 보자.

127.0.0.1:6200> latency history aof-fsync-always
  1) 1) (integer) 1464335538
     2) (integer) 22
  2) 1) (integer) 1464335539
     2) (integer) 22
  3) 1) (integer) 1464335540
     2) (integer) 22
  4) 1) (integer) 1464335541
     2) (integer) 32
  5) 1) (integer) 1464335542
     2) (integer) 22
  6) 1) (integer) 1464335543
     2) (integer) 39
  7) 1) (integer) 1464335544
     2) (integer) 22
  8) 1) (integer) 1464335545
     2) (integer) 29
  9) 1) (integer) 1464335546
     2) (integer) 50
 10) 1) (integer) 1464335547
     2) (integer) 22
 11) 1) (integer) 1464335548
     2) (integer) 22
 12) 1) (integer) 1464335549
     2) (integer) 22
 13) 1) (integer) 1464335550
     2) (integer) 32
 14) 1) (integer) 1464335551
     2) (integer) 22
 15) 1) (integer) 1464335552
     2) (integer) 22
 16) 1) (integer) 1464335553
     2) (integer) 32
 17) 1) (integer) 1464335554
     2) (integer) 22
 18) 1) (integer) 1464335555
     2) (integer) 22
 19) 1) (integer) 1464335556
     2) (integer) 50
 20) 1) (integer) 1464335557
     2) (integer) 30
 21) 1) (integer) 1464335558
     2) (integer) 22
 22) 1) (integer) 1464335559
     2) (integer) 22
 23) 1) (integer) 1464335560
     2) (integer) 22
 24) 1) (integer) 1464335561
     2) (integer) 22
 25) 1) (integer) 1464335562
     2) (integer) 22
 26) 1) (integer) 1464335563
     2) (integer) 22
 27) 1) (integer) 1464335564
     2) (integer) 22
 28) 1) (integer) 1464335565
     2) (integer) 22
 29) 1) (integer) 1464335566
     2) (integer) 29
 30) 1) (integer) 1464335567
     2) (integer) 60
 31) 1) (integer) 1464335568
     2) (integer) 22
 32) 1) (integer) 1464335569
     2) (integer) 22
 33) 1) (integer) 1464335570
     2) (integer) 22
 34) 1) (integer) 1464335571
     2) (integer) 22
 35) 1) (integer) 1464335572
     2) (integer) 32
 36) 1) (integer) 1464335573
     2) (integer) 39
 37) 1) (integer) 1464335574
     2) (integer) 22
 38) 1) (integer) 1464335575
     2) (integer) 22
 39) 1) (integer) 1464335576
     2) (integer) 22
 40) 1) (integer) 1464335577
     2) (integer) 50
 41) 1) (integer) 1464335578
     2) (integer) 23
 42) 1) (integer) 1464335579
     2) (integer) 22
 43) 1) (integer) 1464335580
     2) (integer) 22
 44) 1) (integer) 1464335581
     2) (integer) 30
 45) 1) (integer) 1464335582
     2) (integer) 22
 46) 1) (integer) 1464335583
     2) (integer) 22
 47) 1) (integer) 1464335584
     2) (integer) 22
 48) 1) (integer) 1464335585
     2) (integer) 22
 49) 1) (integer) 1464335586
     2) (integer) 22
 50) 1) (integer) 1464335587
     2) (integer) 29
 51) 1) (integer) 1464335588
     2) (integer) 60
 52) 1) (integer) 1464335589
     2) (integer) 22
 53) 1) (integer) 1464335590
     2) (integer) 22
 54) 1) (integer) 1464335591
     2) (integer) 22
 55) 1) (integer) 1464335592
     2) (integer) 22
 56) 1) (integer) 1464335593
     2) (integer) 22
 57) 1) (integer) 1464335594
     2) (integer) 22
 58) 1) (integer) 1464335595
     2) (integer) 22
 59) 1) (integer) 1464335596
     2) (integer) 22
 60) 1) (integer) 1464335597
     2) (integer) 31
 61) 1) (integer) 1464335598
     2) (integer) 70
 62) 1) (integer) 1464335599
     2) (integer) 22
 63) 1) (integer) 1464335600
     2) (integer) 22
 64) 1) (integer) 1464335601
     2) (integer) 32
 65) 1) (integer) 1464335602
     2) (integer) 22
 66) 1) (integer) 1464335603
     2) (integer) 82
 67) 1) (integer) 1464335604
     2) (integer) 22
 68) 1) (integer) 1464335605
     2) (integer) 22
 69) 1) (integer) 1464335606
     2) (integer) 22
 70) 1) (integer) 1464335607
     2) (integer) 22
 71) 1) (integer) 1464335608
     2) (integer) 22
 72) 1) (integer) 1464335609
     2) (integer) 81
 73) 1) (integer) 1464335610
     2) (integer) 22
 74) 1) (integer) 1464335611
     2) (integer) 22
 75) 1) (integer) 1464335612
     2) (integer) 32
 76) 1) (integer) 1464335613
     2) (integer) 22
 77) 1) (integer) 1464335614
     2) (integer) 31
 78) 1) (integer) 1464335615
     2) (integer) 22
 79) 1) (integer) 1464335616
     2) (integer) 29
 80) 1) (integer) 1464335617
     2) (integer) 22
 81) 1) (integer) 1464335618
     2) (integer) 22
 82) 1) (integer) 1464335619
     2) (integer) 80
 83) 1) (integer) 1464335620
     2) (integer) 32
 84) 1) (integer) 1464335621
     2) (integer) 22
 85) 1) (integer) 1464335622
     2) (integer) 22
 86) 1) (integer) 1464335623
     2) (integer) 22
 87) 1) (integer) 1464335624
     2) (integer) 22
 88) 1) (integer) 1464335625
     2) (integer) 22
 89) 1) (integer) 1464335626
     2) (integer) 22
 90) 1) (integer) 1464335627
     2) (integer) 22
 91) 1) (integer) 1464335628
     2) (integer) 29
 92) 1) (integer) 1464335629
     2) (integer) 22
 93) 1) (integer) 1464335630
     2) (integer) 91
 94) 1) (integer) 1464335631
     2) (integer) 22
 95) 1) (integer) 1464335632
     2) (integer) 22
 96) 1) (integer) 1464335633
     2) (integer) 92
 97) 1) (integer) 1464335634
     2) (integer) 31
 98) 1) (integer) 1464335635
     2) (integer) 22
 99) 1) (integer) 1464335636
     2) (integer) 22
100) 1) (integer) 1464335637
     2) (integer) 22
101) 1) (integer) 1464335638
     2) (integer) 22
102) 1) (integer) 1464335639
     2) (integer) 22
103) 1) (integer) 1464335640
     2) (integer) 70
104) 1) (integer) 1464335641
     2) (integer) 22
105) 1) (integer) 1464335642
     2) (integer) 22
106) 1) (integer) 1464335643
     2) (integer) 22
107) 1) (integer) 1464335644
     2) (integer) 22
108) 1) (integer) 1464335645
     2) (integer) 22
109) 1) (integer) 1464335646
     2) (integer) 22
110) 1) (integer) 1464335647
     2) (integer) 22
111) 1) (integer) 1464335648
     2) (integer) 29
112) 1) (integer) 1464335649
     2) (integer) 22
113) 1) (integer) 1464335650
     2) (integer) 22
114) 1) (integer) 1464335651
     2) (integer) 91
115) 1) (integer) 1464335652
     2) (integer) 22
116) 1) (integer) 1464335653
     2) (integer) 22
117) 1) (integer) 1464335654
     2) (integer) 30
118) 1) (integer) 1464335655
     2) (integer) 22
119) 1) (integer) 1464335656
     2) (integer) 22
120) 1) (integer) 1464335657
     2) (integer) 22
121) 1) (integer) 1464335658
     2) (integer) 29
122) 1) (integer) 1464335659
     2) (integer) 22
123) 1) (integer) 1464335660
     2) (integer) 22
124) 1) (integer) 1464335661
     2) (integer) 70
125) 1) (integer) 1464335662
     2) (integer) 22
126) 1) (integer) 1464335663
     2) (integer) 40
127) 1) (integer) 1464335664
     2) (integer) 32
128) 1) (integer) 1464335665
     2) (integer) 22
129) 1) (integer) 1464335666
     2) (integer) 22
130) 1) (integer) 1464335667
     2) (integer) 22
131) 1) (integer) 1464335668
     2) (integer) 22
132) 1) (integer) 1464335669
     2) (integer) 22
133) 1) (integer) 1464335670
     2) (integer) 22
134) 1) (integer) 1464335671
     2) (integer) 22
135) 1) (integer) 1464335672
     2) (integer) 81
136) 1) (integer) 1464335673
     2) (integer) 22
137) 1) (integer) 1464335674
     2) (integer) 22
138) 1) (integer) 1464335675
     2) (integer) 22
139) 1) (integer) 1464335676
     2) (integer) 22
140) 1) (integer) 1464335677
     2) (integer) 22
141) 1) (integer) 1464335678
     2) (integer) 22
142) 1) (integer) 1464335679
     2) (integer) 22
143) 1) (integer) 1464335680
     2) (integer) 22
144) 1) (integer) 1464335681
     2) (integer) 22
145) 1) (integer) 1464335682
     2) (integer) 70
146) 1) (integer) 1464335683
     2) (integer) 22
147) 1) (integer) 1464335684
     2) (integer) 22
148) 1) (integer) 1464335685
     2) (integer) 22
149) 1) (integer) 1464335686
     2) (integer) 22
150) 1) (integer) 1464335687
     2) (integer) 22
151) 1) (integer) 1464335688
     2) (integer) 22
152) 1) (integer) 1464335689
     2) (integer) 22
153) 1) (integer) 1464335690
     2) (integer) 22
154) 1) (integer) 1464335691
     2) (integer) 30
155) 1) (integer) 1464335692
     2) (integer) 23
156) 1) (integer) 1464335693
     2) (integer) 80
157) 1) (integer) 1464335694
     2) (integer) 22
158) 1) (integer) 1464335695
     2) (integer) 22
159) 1) (integer) 1464335696
     2) (integer) 22
160) 1) (integer) 1464335697
     2) (integer) 22

latency graph aof-fsync-always

latency graph 명령을 사용해보자. 'high'는 최근 160개 중에 가장 큰 값인 92 ms이고, 'low'도 최근 160개 중에 가장 적은 값인 22 ms이다. 'all time high'는 1만개 입력 중 가장 큰 값인 103 ms이다.
이것은 위에서 설명한 Max 값 버그를 수정했을때 잘 나온다. 그렇지 않으면 'high'가 'all time high' 보다 큰 값이 나올 수도 있다.

latency graph ASCII-art style aof-fsync-always

그림 1-5 Latency graph aof-fsync-always

도로에 가로등 같은 그래프가 나왔다. 본 테스트 서버에서 Fsync 하는데 20ms 정도가 소요되는데, 약 10초 마다 한 번씩 80~90ms로 튀었다는 것을 알 수 있다. History 명령은 값을 하나씩 모두 확인할 수 있지만, 전체를 한 눈에 파악하기에는 graph가 낫다.

Latency Monitor는 초 단위로 기록된다. 1 초에 여러개 발생하면 그 중 가장 큰 값으로 대치되어 결국 가장 큰 값이 남는다. 데이터가 1 초에 하나씩 만 있다고 해서 해당 이벤트가 1 초에 한 번만 발생한 것으로 오해하지 말기 바란다.

latency doctor : aof-fsync-always

doctor 명령은 어떻게 나오는지 보자.

127.0.0.1:6200> latency doctor
Dave, I have observed latency spikes in this Redis instance. You don't mind talking about it, do you Dave?

1. aof-fsync-always: 160 latency spikes (average 28ms, mean deviation 9ms, period 25.29 sec). Worst all time event 103ms.

I have a few advices for you:

- Your fsync policy is set to 'always'. It is very hard to get good performances with such a setup, if possible try to relax the fsync policy to 'onesec'.

본 테스트 서버에서 fsync하는데 평균 28ms 걸렸다. 그럼 1초에 약 35회를 입력할 수 있다. Appendfsync를 always로 설정하면 데이터는 디스크에 안전하게 보관할 수 있지만, 성능은 디스크에 데이터를 저장하는 일반 RDBMS와 크게 다르지 않다는 것을 알 수 있다.
권고 내용(advice)은 fsync 시간에 관계없이 appendfsync를 'everysec'로 변경할 권고한다.

LATENCY AOF-WRITE

이 이벤트는 AppendOnly 파일에 write하는 시간이 설정한 threshold 시간 이상일때 기록된다. 이후에 설명하는 aof-write로 시작하는 이벤트 기록의 합이 이 이벤트 기록과 같다.
예에서는
aof-write 12 회 = aof-write-pending-fsync 3 회 + aof-write-active-child 8 회 + aof-write-alone 1 회

latency latest

이벤트가 발생했는지 확인해보자. 127.0.0.1:6200> latency latest ... 4) 1) "aof-write" 2) (integer) 1463813189 3) (integer) 1684 4) (integer) 1769
다른 이벤트도 있는데 여기서는 생략했다. 최근 이벤트가 1684ms 걸렸고, 최대(Max)는 1769ms 걸렸다. Write하는 시간이 최대 1.7초 걸렸으니 상당히 오래 걸린 것이다. Write는 user 메모리에 있는 데이터를 kernel 메모리로 이동하는 메모리간 이동인데 시간이 꾀 많이 걸린 것이다.
이제 부터 어디에 원인이 있는지 알아보자.

latency history aof-write

그 동안의 기록을 확인해 보자. 기록은 1초에 한 번만 남긴다. 같은 이벤트가 1초에 여러번 발생하면 가장 큰 값을 남긴다. 127.0.0.1:6200> latency history aof-write 1) 1) (integer) 1463813107 2) (integer) 11 2) 1) (integer) 1463813108 2) (integer) 23 3) 1) (integer) 1463813109 2) (integer) 16 4) 1) (integer) 1463813112 2) (integer) 9 5) 1) (integer) 1463813114 2) (integer) 694 6) 1) (integer) 1463813116 2) (integer) 68 7) 1) (integer) 1463813177 2) (integer) 38 8) 1) (integer) 1463813179 2) (integer) 35 9) 1) (integer) 1463813181 2) (integer) 351 10) 1) (integer) 1463813184 2) (integer) 1769 11) 1) (integer) 1463813186 2) (integer) 418 12) 1) (integer) 1463813189 2) (integer) 1684
일반적인 write 시간은 1ms 이내로, 첫 번째 값 11ms도 오래 걸린 것이지만, 10 번째 1769ms에 비해서는 적게 걸린 것이다. 튜닝 관점에서는 큰 값부터 처리하는 것이 순서이므로 여기서는 10, 12 번째를 중심으로 확인해보자.

latency graph aof-write

latency graph ASCII-art style aof-write

그림 1-5 Latency aof-write graph

History로 파악했지만 graph는 한 눈에 볼 수 있어 좋다.

latency doctor : aof-write

127.0.0.1:6200> latency doctor Dave, I have observed latency spikes in this Redis instance. You don't mind talking about it, do you Dave? 4. aof-write: 12 latency spikes (average 426ms, mean deviation 477ms, period 726.67 sec). Worst all time event 1769ms. aof-write는 통계정보는 나오지만 advices(튜닝 권고사항)는 나오지 않는다. 왜냐하면 aof-write 이벤트는 세 가지 세부 이벤트(aof-write-pending-fsync, aof-write-active-child, aof-write-alone) 로 분리되고, 각 세부 이벤트에서 advices가 나온다.
이제 aof-write-pending-fsync 이벤트 부터 확인해 보자.

LATENCY AOF-WRITE-PENDING-FSYNC

이 이벤트는 appendonly가 yes이고 appendfsync가 everysec 일때 발생하는데, 1 초 마다 수행되는 AOF fsync 쓰레드가 fsync를 수행하는 중에 레디스 서버 메인 쓰레드에서 write를 수행했을때 write에 소요된 시간이 threshold 이상일때 기록된다.
threshold 값을 5ms로 하고 테스트 결과를 얻으려면 value를 큰 값(1만 이상 바이트)로 해야 할 것이다.

aof-write 12 회 = aof-write-pending-fsync 3 회 + aof-write-active-child 8 회 + aof-write-alone 1 회

latency latest

이벤트가 발생했는지 확인해보자. 127.0.0.1:6200> latency latest ... 7) 1) "aof-write-pending-fsync" 2) (integer) 1463813116 3) (integer) 68 4) (integer) 694
다른 이벤트도 있는데 여기서는 생략했다. 최근 이벤트가 68ms 걸렸고, 최대(Max)는 694ms 걸렸다.

latency history aof-write-pending-fsync

127.0.0.1:6200> latency history aof-write-pending-fsync 1) 1) (integer) 1463813112 2) (integer) 9 2) 1) (integer) 1463813114 2) (integer) 694 3) 1) (integer) 1463813116 2) (integer) 68
총 3번 발생했고, 최소값(Low) 8ms, 최고값(High) 694ms 이다.

latency graph aof-write-pending-fsync

latency graph ASCII-art style aof-write-pending-fsync

그림 1-5 Latency aof-write-pending-fsync graph

1 번 막대 그래프가 9ms, 2 번 막대 그래프가 694ms, 3 번 막대 그래프가 68ms 이다. 모두 57분 전에 실행되었다.

latency doctor : aof-write-pending-fsync

127.0.0.1:6200> latency doctor 7. aof-write-pending-fsync: 3 latency spikes (average 257ms, mean deviation 291ms, period 1172.00 sec). Worst all time event 694ms. I have a few advices for you: - It is strongly advised to use local disks for persistence, especially if you are using AOF. Remote disks provided by platform-as-a-service providers are known to be slow. - SSD disks are able to reduce fsync latency, and total time needed for snapshotting and AOF log rewriting (resulting in smaller memory usage and smaller final AOF rewrite buffer flushes). With extremely high write load SSD disks can be a good option. However Redis should perform reasonably with high load using normal disks. Use this advice as a last resort. - Mounting ext3/4 filesystems with data=writeback can provide a performance boost compared to data=ordered, however this mode of operation provides less guarantees, and sometimes it can happen that after a hard crash the AOF file will have an half-written command at the end and will require to be repaired before Redis restarts. - Try to lower the disk contention. This is often caused by other disk intensive processes running in the same computer (including other Redis instances).
모두 4 가지 권고 사항인데, local disk, SSD, ext3/4 filesystem, disk contention(경합) 관련 내용이다.
Local disk나 SSD를 사용하면 성능이 좋아질 수 있다는 것과 ext3/4 filesystem을 사용하는 것이 성능에 좋다는 것이다. 테스트 서버는 xfs 를 사용하고 있다. 이 권고는 응답 시간에 따라 달리 나오는 것이 아니고, 이 이벤트가 threshold 이상이면 나오는 내용이다.

LATENCY AOF-WRITE-ACTIVE-CHILD

AOF 또는 RDB Child Process가 AppendOnlyFile 또는 RDB File에 백그라운드로 쓰는 중에, 레디스 서버에서 write를 수행했을때 write에 소요된 시간이다.

aof-write 12 회 = aof-write-pending-fsync 3 회 + aof-write-active-child 8 회 + aof-write-alone 1 회

이전에 수행했던 테스트에 이 이벤트도 발생했는지, latency latest 로 확인해보자. 127.0.0.1:6200> latency latest ... 3) 1) "aof-write-active-child" 2) (integer) 1463813189 3) (integer) 1684 4) (integer) 1769
최근 이벤트가 1684ms 걸렸고, 최대(Max)는 1769ms 걸렸다.
AOF Child Process가 수행중에 동시에 레디스 서버에서 write를 수행했을때 가장 오랜 시간이 소요되었다는 것을 알았다.

latency history aof-write-active-child 로 확인해보자. 127.0.0.1:6200> latency history aof-write-active-child 1) 1) (integer) 1463813108 2) (integer) 23 2) 1) (integer) 1463813109 2) (integer) 16 3) 1) (integer) 1463813177 2) (integer) 38 4) 1) (integer) 1463813179 2) (integer) 35 5) 1) (integer) 1463813181 2) (integer) 351 6) 1) (integer) 1463813184 2) (integer) 1769 7) 1) (integer) 1463813186 2) (integer) 418 8) 1) (integer) 1463813189 2) (integer) 1684
총 8번 발생했고, 최소값(Low) 16ms, 최고값(High) 1769ms 이다.
이번에는 graph로 확인해보자.

latency graph ASCII-art style aof-write-active-child

그림 1-5 Latency aof-write-active-child graph

위 history 데이터와 비교해 보면 좋을 것이다.

Doctor에 다른 내용도 있어서 이 이벤트 관련 권고 사항만 추려서 아래 정리했다. 127.0.0.1:6200> latency doctor Dave, I have observed latency spikes in this Redis instance. You don't mind talking about it, do you Dave? 3. aof-write-active-child: 8 latency spikes (average 541ms, mean deviation 592ms, period 1089.88 sec). Worst all time event 1769ms. I have a few advices for you: - SSD disks are able to reduce fsync latency, and total time needed for snapshotting and AOF log rewriting (resulting in smaller memory usage and smaller final AOF rewrite buffer flushes). With extremely high write load SSD disks can be a good option. However Redis should perform reasonably with high load using normal disks. Use this advice as a last resort. - Mounting ext3/4 filesystems with data=writeback can provide a performance boost compared to data=ordered, however this mode of operation provides less guarantees, and sometimes it can happen that after a hard crash the AOF file will have an half-written command at the end and will require to be repaired before Redis restarts. - Assuming from the point of view of data safety this is viable in your environment, you could try to enable the 'no-appendfsync-on-rewrite' option, so that fsync will not be performed while there is a child rewriting the AOF file or producing an RDB file (the moment where there is high disk contention).
모두 3 가지 권고 사항인데, SSD, ext3/4 filesystem, no-appendfsync-on-rewrite 설정 관련 내용이다.
해결 방법은 세 가지이다.
첫 번째는 SSD같은 빠른 디스크로 교체하는 것이다.
두 번째는 현재 사용하고 있는 filesystem이 ext3/4가 아니면 ext3/4로 설치하는 것이다.
세 번째 no-appendfsync-on-rewrite 는 redis.conf에서 설정하는 것으로 yes로 설정하면 AOF Child Process가 rewrite 중 일때, 레디스 서버 Process에서는 fsync를 수행하지 않는 것이다. No로 설정하면 AOF Child Process가 rewrite 중 일때, 레디스 서버 Process에서도 fsync를 수행한다. 데이터의 안전한 보관을 위해서는 no로 설정하는 것이 맞지만, 성능에 문제가 된다면, yes로 설정하는 것을 고려해 보시기 바랍니다. 디폴트는 no이다.
자 이제 세 가지 튜닝 사항 중 적용할 수 있는 것 부터 선택해서 적용하면 된다.

LATENCY AOF-WRITE-ALONE

이 aof-write-alone 이벤트는 aof-write 이벤트 중에서 aof-write-pending-fsync와 aof-write-active-child 이벤트를 제외한 것이다. 그러니까, 레디스의 다른 쓰레드나 자식 프로세스와의 경합없이 write 자체가 늦는 것이다.

aof-write 12 회 = aof-write-pending-fsync 3 회 + aof-write-active-child 8 회 + aof-write-alone 1 회

latency latest로 확인해보자. 127.0.0.1:6200> latency latest ... 1) 1) "aof-write-alone" 2) (integer) 1463813107 3) (integer) 11 4) (integer) 11

latency history aof-write-alone으로 확인해보자. 127.0.0.1:6200> latency history aof-write-alone 1) 1) (integer) 1463813107 2) (integer) 11
앞에서 이미 확인했지만 1회 발생했다.

latency graph aof-write-alone으로 확인해보자.

latency graph ASCII-art style aof-write-alone

그림 1-6 Latency aof-write-alone graph

데이터가 1개 이므로 특별한 의미는 없다. '1d'는 1일 전에 발생했다는 것이다.
latency doctor 내용을 보자. aof-write-alone은 local disk, SSD, writeback 세 가지 권고가 출력된다. 이 권고들은 위에서 본 것과 중복되므로 여기서는 세 가지 이벤트(aof-write-pending-fsync, aof-write-active-child, aof-write-alone)의 내용을 같이 정리해 보았다. 127.0.0.1:6200> latency doctor Dave, I have observed latency spikes in this Redis instance. You don't mind talking about it, do you Dave? 1. aof-write-alone: 1 latency spikes (average 11ms, mean deviation 0ms, period 90629.00 sec). Worst all time event 11ms. 3. aof-write-active-child: 8 latency spikes (average 541ms, mean deviation 592ms, period 11328.50 sec). Worst all time event 1769ms. 4. aof-write: 12 latency spikes (average 426ms, mean deviation 477ms, period 7552.42 sec). Worst all time event 1769ms. 7. aof-write-pending-fsync: 3 latency spikes (average 257ms, mean deviation 291ms, period 30208.00 sec). Worst all time event 694ms. I have a few advices for you: - It is strongly advised to use local disks for persistence, especially if you are using AOF. Remote disks provided by platform-as-a-service providers are known to be slow. - SSD disks are able to reduce fsync latency, and total time needed for snapshotting and AOF log rewriting (resulting in smaller memory usage and smaller final AOF rewrite buffer flushes). With extremely high write load SSD disks can be a good option. However Redis should perform reasonably with high load using normal disks. Use this advice as a last resort. - Mounting ext3/4 filesystems with data=writeback can provide a performance boost compared to data=ordered, however this mode of operation provides less guarantees, and sometimes it can happen that after a hard crash the AOF file will have an half-written command at the end and will require to be repaired before Redis restarts. - Try to lower the disk contention. This is often caused by other disk intensive processes running in the same computer (including other Redis instances). - Assuming from the point of view of data safety this is viable in your environment, you could try to enable the 'no-appendfsync-on-rewrite' option, so that fsync will not be performed while there is a child rewriting the AOF file or producing an RDB file (the moment where there is high disk contention).
여기서 ext3/4 filesystem의 data=writeback에 대해서 잠시 설명하면, 데이터가 cache와 main memory에 같이 있을때, cache에만 update하고 main memory에는 나중에 쓰는 것이다. 디스크 관점에서 설명하면 디스크 컨트롤러의 cache와 disk일 것이다. 성능에 문제가 있다면 속도가 빠르기 때문에 사용을 권장하지만, main memory에 update 되지 전에 hard crash가 발생하면 AOF 파일의 끝에 명령이 반 만 기록될 수도 있으니, 재 시작하기 전에 AOF 파일을 고칠 필요가 있는 것입니다. 하지만 크게 걱정하지 말고 ext3/4를 사용하도록 합시다.

Cache와 writeback에 대한 자세한 한글 자료는 여기를 보시고,
Write-Back와 Write-Through에 대한 영문 자료는 여기를 보세요.
XFS의 write back에 대한 자료는 XFS FAQ와 XFS Wiki를 보세요.

LATENCY AOF-REWRITE-DIFF-WRITE

AOF Child Process가 rewrite를 종료한 다음, Parent Process의 serverCron에서 남아있는 AOF buffer의 내용을 write하는데 걸린 시간이다.
AOF bgrewirteaof의 step 3에 해당한다. AOF berewriteaof에 대한 자세한 설명은 여기를 보세요.
latency latest로 확인해보자. 127.0.0.1:6200> latency latest ... 6) 1) "aof-rewrite-diff-write" 2) (integer) 1463813202 3) (integer) 3289 4) (integer) 3289

latency history aof-rewrite-diff-write으로 확인해보자. 127.0.0.1:6200> latency history aof-rewrite-diff-write 1) 1) (integer) 1463813111 2) (integer) 89 2) 1) (integer) 1463813202 2) (integer) 3289
2회 발생했다. 다행히 이 기록은 redis.log에서도 찾아 볼 수 있다. 48331:M 15:45:11.767 * Background AOF rewrite terminated with success 48331:M 15:45:11.856 * Residual parent diff successfully flushed to the rewritten AOF (229.76 MB) 48331:M 15:46:38.911 * Background AOF rewrite terminated with success 48331:M 15:46:42.200 * Residual parent diff successfully flushed to the rewritten AOF (511.59 MB)
"Background AOF rewrite terminated with success" 메시지가 AOF buffer에 쌓여있는 데이터를 write하기 직전에 출력하는 로그이고, "Residual parent diff successfully flushed to the rewritten AOF (229.76 MB)" 메시지가 write 완료한 직후 출력하는 로그이다.
첫 번째 케이스에서 229.76 MB를 write하는데, 11.856 - 11.767 = 89ms가 걸렸고,
두 번째 케이스에서 511.59 MB를 write하는데, 42.200 - 38.911 = 3289ms가 걸렸다.
이 수치는 latency history에서 나온 소요시간과 같다.

latency graph aof-rewrite-diff-write으로 확인해보자.

latency graph ASCII-art style aof-rewrite-diff-write

그림 1-7 Latency aof-rewrite-diff-write graph

latency doctor 내용을 보자. aof-rewrite-diff-write 내용만 간추렸다. 127.0.0.1:6200> latency doctor 6. aof-rewrite-diff-write: 2 latency spikes (average 1689ms, mean deviation 1600ms, pe067.00 sec). Worst all time event 3289ms. - Latency during the AOF atomic rename operation or when the final difference is flushed to the AOF file at the end of the rewrite, sometimes is caused by very high write load, causing the AOF buffer to get very large. If possible try to send less commands to accomplish the same work, or use Lua scripts to group multiple operations into a single EVALSHA call.
여기 나온 advice는 rename operation에 대한 내용은 'aof-rename' 이벤트도 같은 advice를 사용하기 때문에 나온 것이다. 'aof-rewrite-diff-write'에 대한 advice는 "when the final difference ~"부터 이다.
이 이벤트도 local disk, SSD, data=writeback(ext3/4) 권고도 나오는데 여기서는 생략했다.

LATENCY AOF-RENAME

Parent Process가 AOF write를 완료한 후에 rename()하는데 소요된 시간이다.
이전 이벤트인 aof-rewrite-diff-write 수행 후에 바로 수행하는 오퍼레이션이다. 이번 테스트에서는 aof-rename 이벤트는 발생하지 않았다.

소스코드는 aof.c에 backgroundRewriteDoneHandler()에 있다. 로그 남기는 부분도 같이 표시했다. mstime_t latency; serverLog(LL_NOTICE, "Background AOF rewrite terminated with success"); /* Flush the differences accumulated by the parent to the rewritten AOF. */ latencyStartMonitor(latency); snprintf(tmpfile,256,"temp-rewriteaof-bg-%d.aof", (int)server.aof_child_pid); newfd = open(tmpfile,O_WRONLY|O_APPEND); if (newfd == -1) { serverLog(LL_WARNING, "Unable to open the temporary AOF produced by the child: %s", strerror(errno)); goto cleanup; } if (aofRewriteBufferWrite(newfd) == -1) { serverLog(LL_WARNING, "Error trying to flush the parent diff to the rewritten AOF: %s", strerror(errno)); close(newfd); goto cleanup; } latencyEndMonitor(latency); latencyAddSampleIfNeeded("aof-rewrite-diff-write",latency); serverLog(LL_NOTICE, "Residual parent diff successfully flushed to the rewritten AOF (%.2f MB)", (double) aofRewriteBufferSize() / (1024*1024));
권고 사항은 위에서 설명한 aof-rewrite-diff-write 이벤트와 같다.

LATENCY FORK

AOF나 RDB Child Process를 fork하는데 걸린 시간이다.
정확히 세 곳에서 측정하는데,
1) bgrewriteaof 명령으로 AOF Child Process를 fork할때,
2) bgsave 명령으로 RDB Child Process를 fork할때,
3) 슬레이브에 socket으로 replication하기 위해 RDB Child Process를 fork할때 측정한다.

latency latest로 확인해보자. 127.0.0.1:6200> latency latest ... 2) 1) "fork" 2) (integer) 1463813176 3) (integer) 23 4) (integer) 23

latency history fork으로 확인해보자. 127.0.0.1:6200> latency history aof-rewrite-diff-write 1) 1) (integer) 1463813176 2) (integer) 23
한 번 발생했다. Graph는 별 의미가 없으니 생략하고, 소스코드를 보자.
아래 소스는 aof.c rewriteAppendOnlyFileBackground()에 있는 것이다. start = ustime(); if ((childpid = fork()) == 0) { char tmpfile[256]; /* Child */ closeListeningSockets(0); redisSetProcTitle("redis-aof-rewrite"); snprintf(tmpfile,256,"temp-rewriteaof-bg-%d.aof", (int) getpid()); if (rewriteAppendOnlyFile(tmpfile) == C_OK) { size_t private_dirty = zmalloc_get_private_dirty(); if (private_dirty) { serverLog(LL_NOTICE, "AOF rewrite: %zu MB of memory used by copy-on-write", private_dirty/(1024*1024)); } exitFromChild(0); } else { exitFromChild(1); } } else { /* Parent */ server.stat_fork_time = ustime()-start; server.stat_fork_rate = (double) zmalloc_used_memory() * 1000000 / server.stat_fork_time / (1024*1024*1024); /* GB per second. */ latencyAddSampleIfNeeded("fork",server.stat_fork_time/1000);

이제 latency doctor로 fork 이벤트 권고사항을 보자. 127.0.0.1:6200> latency doctor Dave, I have observed latency spikes in this Redis instance. You don't mind talking about it, do you Dave? 2. fork: 1 latency spikes (average 23ms, mean deviation 0ms, period 157239.00 sec). Worst all time event 23ms. Fork rate is 34.38 GB/sec (good).
Fork는 별도 advice는 없고 통계정보는 'terrible', 'poor', 'good', 'excellent'를 보여준다.
초당 속도가 10 GB 미만이면 'terrible'
10 GB 이상 25 GB 미만이면 'poor'
25 GB 이상 100 GB 미만이면 'good'
100 GB 이상이면 'excellent'를 보여준다.

LATENCY AOF-FSTAT

file 정보(size 등)를 얻어오는데 걸린 시간이다.
이번 테스트에서는 이 이벤트가 발생하지 않았다. 그래서 latency 명령을 사용한 설명은 doctor를 이용한 권고사항을 설명하고, 소스코드와 fstat에 대한 간단한 설명으로 대치한다. aof-fstat 이벤트는 server.aof_current_size를 update하는 aofUpdateCurrentSize()에서 측정한다.
소스코드는 aof.c에 있다. /* Update the server.aof_current_size field explicitly using stat(2) * to check the size of the file. This is useful after a rewrite or after * a restart, normally the size is updated just adding the write length * to the current length, that is much faster. */ void aofUpdateCurrentSize(void) { struct redis_stat sb; mstime_t latency; latencyStartMonitor(latency); if (redis_fstat(server.aof_fd,&sb) == -1) { serverLog(LL_WARNING,"Unable to obtain the AOF file length. stat: %s", strerror(errno)); } else { server.aof_current_size = sb.st_size; } latencyEndMonitor(latency); latencyAddSampleIfNeeded("aof-fstat",latency); }

redis_fstat는 config.h에 있다. /* Define redis_fstat to fstat or fstat64() */ #if defined(__APPLE__) && !defined(MAC_OS_X_VERSION_10_6) #define redis_fstat fstat64 #define redis_stat stat64 #else #define redis_fstat fstat #define redis_stat stat #endif

일반적인 상황에서는 파일 정보를 읽어오는데 시간이 오래 걸릴것 같지는 않다.
fstat()에 대한 한글 참고자료는 여기를 보세요.

doctor 권고사항은 disk contention과 local disk이다. - Try to lower the disk contention. This is often caused by other disk intensive processes running in the same computer (including other Redis instances). - It is strongly advised to use local disks for persistence, especially if you are using AOF. Remote disks provided by platform-as-a-service providers are known to be slow.

LATENCY RDB-UNLINK-TEMP-FILE

이 이벤트는 background로 RDB 파일을 저장 시 오류가 발생해서 임시 RDB 파일을 삭제하는데 걸린 시간이다.
RDB 파일 저장 시 일단 temp로 시작하는 임시 파일명에 데이터를 저장하고, 완료되면 정상 RDB 파일명으로 rename하는데, 정상적으로 완료되지 못하면, temp로 시작하는 임시 파일을 삭제한다.

Background로 RDB 파일을 저장하는 경우는 다음 세 가지 중 하나이다.

BGSAVE 명령을 실행했을때
redis.conf의 save 파리미터 설정에 따라
슬레이브 노드에 replication 할 때

latency doctor : rdb-unlink-temp-file

권고 사항은 디스크 경합(disk contention)과 로칼 디스크(local disks)이다. - Try to lower the disk contention. This is often caused by other disk intensive processes running in the same computer (including other Redis instances). - It is strongly advised to use local disks for persistence, especially if you are using AOF. Remote disks provided by platform-as-a-service providers are known to be slow.

소스코드

backgroundSaveDoneHandlerDisk() in rdb.c /* A background saving child (BGSAVE) terminated its work. Handle this. * This function covers the case of actual BGSAVEs. */ void backgroundSaveDoneHandlerDisk(int exitcode, int bysignal) { if (!bysignal && exitcode == 0) { serverLog(LL_NOTICE, "Background saving terminated with success"); server.dirty = server.dirty - server.dirty_before_bgsave; server.lastsave = time(NULL); server.lastbgsave_status = C_OK; } else if (!bysignal && exitcode != 0) { serverLog(LL_WARNING, "Background saving error"); server.lastbgsave_status = C_ERR; } else { mstime_t latency; serverLog(LL_WARNING, "Background saving terminated by signal %d", bysignal); latencyStartMonitor(latency); rdbRemoveTempFile(server.rdb_child_pid); latencyEndMonitor(latency); latencyAddSampleIfNeeded("rdb-unlink-temp-file",latency); /* SIGUSR1 is whitelisted, so we have a way to kill a child without * tirggering an error conditon. */ if (bysignal != SIGUSR1) server.lastbgsave_status = C_ERR; }

rdbRemoveTempFile() in rdb.c void rdbRemoveTempFile(pid_t childpid) { char tmpfile[256]; snprintf(tmpfile,sizeof(tmpfile),"temp-%d.rdb", (int) childpid); unlink(tmpfile); }

LATENCY EXPIRE-CYCLE

이 이벤트는 만료된 키를 주기적으로 삭제하는데 소요된 시간이다.
만료된 키 삭제는 세 군데에서 실행되는데, 주기적으로 여러개의 키를 삭제하는 첫 번째, 두 번째가 latency 모니터 대상이고, 해당 키 하나만 삭제하는 세 번째는 latency 모니터 대상이 아니다. 각각을 좀 자세히 설명하면 다음과 같다.

주기적(100ms 마다)으로 만료된 키들을 삭제

100ms 마다 실행되는 databasesCron()에서 activeExpireCycle()를 수행해서 만료된 키를 삭제한다.
이때는 activeExpireCycle()을 SLOW type으로 실행하는데, SLOW type은 수행 제한 시간을 25ms로 설정되어 있다. 그런데 25ms를 초과해서 실행 할 수도 있다. 왜냐하면, 키가 expire되었는지 random으로 검사하는데 20회씩 16회를 반복해서, 총 160회를 실행하고 소요시간을 검사해서 25ms가 지났으면 종료한다. 25ms가 지나지 않았으면 다시 20회 * 16회를 반복 실행하고 소요시간을 다시 검사한다. 이런 방식으로 진행하기 때문에 소요시간이 25ms 이상이 될 수 있다. 예를 들어 한 세트 수행하는데 10ms가 걸린다면 두 번째 세트는 20ms로 제한 시간이 25ms 이하이므로 통과되고, 세 번째 세트 수행 후 30ms일때 비교해서 25ms 이상이므로 종료된다.

명령을 실행하면 끝날때 마다 만료된 키들을 삭제

명령을 실행하면 끝날때 마다 beforeSleep()에서 activeExpireCycle()를 수행해서 만료된 키를 삭제한다.
이때는 FAST type으로 실행하는데, 제한 시간이 1ms로 짧다. 그러나 FAST type도 위와 같이 한 세트가 20회 * 16회 단위로 실행되므로, 일반적으로 5ms 이상은 소요된다.

각 명령에서 해당 키 하나만 삭제

각 명령을 실행할때, 주 작업을 실행하기 전에 키가 만료되었는지 확인해서 만료되었으면 삭제한다.
예를 들어 get key 명령을 실행하면 "key"가 있는지 확인해서 있으면 expire time을 확인해서 expire 되었으면 key를 삭제하고 클라이언트에서 null을 리턴한다. Expire time이 아직 지나지 않았거나 expire time이 없으면 value을 리턴한다.
이 경우는 해당 키 하나만 삭제하는 것이므로 latency monitor에서 소요시간을 측정하지는 않는다.

주기적 키 삭제 function 관계도

latency event-name expire-cycle

그림 1-8 Latency expire-cycle

실제 키 삭제는 activeExpireCycleTryExpire()에서 dbDelete()를 호출해서 이루어진다.

주기적 키 삭제 기능 비활성화

Debug 명령으로 이 기능을 비활성화할 수 있다. debug set-active-expire 0
활성화는 debug set-active-expire 1 이다.

Threshold 값 이상인데도 latency monitor 기록에 남지 않는 경우

다른 이벤트들은 정확히 수행 시간을 체크해서 threshold 값 이상이면 latency monitor에 기록하는데, 이 expire-cycle 이벤트는 기록을 남기지 못하는 경우도 발생한다. Expire-cycle은 Latency monitor 기록을 키 하나 검사/삭제할때 마다 제한 시간을 체크해서 남기는 것이 아니고, 한 세트(20회 검사 * 16회 반복) 단위로 제한 시간을 체크해서 종료한다. 종료 조건이 하나 더 있는데 20회를 검사했을때 삭제된 키 수가 5 이하일때, 즉 25% 이하면 종료한다.
예를 들어 threshold 5 이고, SLOW type으로 수행할때 두 세트(32회 반복) 수행 후 소요 시간이 20ms 이면 다음 세트를 시작하는데, 33회에 20개 키를 검사해서 5개 이하로 키가 삭제되면 종료한다. Latency 모니터는 16회, 32회, 48회, ... 반복때 마다 남기는데, 33회 반복이므로 소요 시간이 20ms 이상임에도 불구하고 latency monitor에 기록이 남지 않는다.
그러므로 expire-cycle 이벤트의 latency monitor 기록은 정확하지 않을 수 있다.

키 삭제 dbDelete() 설명

redisDb 구조체에는 키들을 저장하는 dict(Hash table)과 expire time이 setting되어 있는 키들을 저장하는 expires(Hash table)가 있다. set key value 하면 dict에만 저장한다. expire key 10 하면 dict에 있던 key를 exipres(Hash table)에도 저장한다. 키를 삭제하는 dbDelete()는 expires(Hash table)과 dict(Hash table) 양쪽을 검사해서 삭제한다.

소스코드

databasesCron()에서 activeExpireCycle(SLOW)로 호출하는 소스코드: server.c /* This function handles 'background' operations we are required to do * incrementally in Redis databases, such as active key expiring, resizing, * rehashing. */ void databasesCron(void) { /* Expire keys by random sampling. Not required for slaves * as master will synthesize DELs for us. */ if (server.active_expire_enabled && server.masterhost == NULL) activeExpireCycle(ACTIVE_EXPIRE_CYCLE_SLOW);

beforeSleep()에서 activeExpireCycle(FAST)로 호출하는 소스코드: server.c /* This function gets called every time Redis is entering the * main loop of the event driven library, that is, before to sleep * for ready file descriptors. */ void beforeSleep(struct aeEventLoop *eventLoop) { UNUSED(eventLoop); /* Call the Redis Cluster before sleep function. Note that this function * may change the state of Redis Cluster (from ok to fail or vice versa), * so it's a good idea to call it before serving the unblocked clients * later in this function. */ if (server.cluster_enabled) clusterBeforeSleep(); /* Run a fast expire cycle (the called function will return * ASAP if a fast cycle is not needed). */ if (server.active_expire_enabled && server.masterhost == NULL) activeExpireCycle(ACTIVE_EXPIRE_CYCLE_FAST);

만료된 키를 주기적으로 삭제 메인 function activeExpireCycle() 소스코드: server.c
여기서 expire time이 설정된 키를 검사해서 만료되었으면 키를 삭제한다. 세트(20개씩 16회 반복) 단위로 실행 후 제한 시간을 검사해서 초과했으면 종료한다. /* Try to expire a few timed out keys. The algorithm used is adaptive and * will use few CPU cycles if there are few expiring keys, otherwise * it will get more aggressive to avoid that too much memory is used by * keys that can be removed from the keyspace. * * No more than CRON_DBS_PER_CALL databases are tested at every * iteration. * * This kind of call is used when Redis detects that timelimit_exit is * true, so there is more work to do, and we do it more incrementally from * the beforeSleep() function of the event loop. * * Expire cycle type: * * If type is ACTIVE_EXPIRE_CYCLE_FAST the function will try to run a * "fast" expire cycle that takes no longer than EXPIRE_FAST_CYCLE_DURATION * microseconds, and is not repeated again before the same amount of time. * * If type is ACTIVE_EXPIRE_CYCLE_SLOW, that normal expire cycle is * executed, where the time limit is a percentage of the REDIS_HZ period * as specified by the REDIS_EXPIRELOOKUPS_TIME_PERC define. */ void activeExpireCycle(int type) { /* This function has some global state in order to continue the work * incrementally across calls. */ static unsigned int current_db = 0; /* Last DB tested. */ static int timelimit_exit = 0; /* Time limit hit in previous call? */ static long long last_fast_cycle = 0; /* When last fast cycle ran. */ int j, iteration = 0; int dbs_per_call = CRON_DBS_PER_CALL; long long start = ustime(), timelimit; if (type == ACTIVE_EXPIRE_CYCLE_FAST) { /* Don't start a fast cycle if the previous cycle did not exited * for time limt. Also don't repeat a fast cycle for the same period * as the fast cycle total duration itself. */ if (!timelimit_exit) return; if (start < last_fast_cycle + ACTIVE_EXPIRE_CYCLE_FAST_DURATION*2) return; last_fast_cycle = start; } /* We usually should test CRON_DBS_PER_CALL per iteration, with * two exceptions: * * 1) Don't test more DBs than we have. * 2) If last time we hit the time limit, we want to scan all DBs * in this iteration, as there is work to do in some DB and we don't want * expired keys to use memory for too much time. */ if (dbs_per_call > server.dbnum || timelimit_exit) dbs_per_call = server.dbnum; /* We can use at max ACTIVE_EXPIRE_CYCLE_SLOW_TIME_PERC percentage of CPU time * per iteration. Since this function gets called with a frequency of * server.hz times per second, the following is the max amount of * microseconds we can spend in this function. */ timelimit = 1000000*ACTIVE_EXPIRE_CYCLE_SLOW_TIME_PERC/server.hz/100; timelimit_exit = 0; if (timelimit <= 0) timelimit = 1; if (type == ACTIVE_EXPIRE_CYCLE_FAST) timelimit = ACTIVE_EXPIRE_CYCLE_FAST_DURATION; /* in microseconds. */ for (j = 0; j < dbs_per_call; j++) { int expired; redisDb *db = server.db+(current_db % server.dbnum); /* Increment the DB now so we are sure if we run out of time * in the current DB we'll restart from the next. This allows to * distribute the time evenly across DBs. */ current_db++; /* Continue to expire if at the end of the cycle more than 25% * of the keys were expired. */ do { unsigned long num, slots; long long now, ttl_sum; int ttl_samples; /* If there is nothing to expire try next DB ASAP. */ if ((num = dictSize(db->expires)) == 0) { db->avg_ttl = 0; break; } slots = dictSlots(db->expires); now = mstime(); /* When there are less than 1% filled slots getting random * keys is expensive, so stop here waiting for better times... * The dictionary will be resized asap. */ if (num && slots > DICT_HT_INITIAL_SIZE && (num*100/slots < 1)) break; /* The main collection cycle. Sample random keys among keys * with an expire set, checking for expired ones. */ expired = 0; ttl_sum = 0; ttl_samples = 0; if (num > ACTIVE_EXPIRE_CYCLE_LOOKUPS_PER_LOOP) num = ACTIVE_EXPIRE_CYCLE_LOOKUPS_PER_LOOP; while (num--) { dictEntry *de; long long ttl; if ((de = dictGetRandomKey(db->expires)) == NULL) break; ttl = dictGetSignedIntegerVal(de)-now; if (activeExpireCycleTryExpire(db,de,now)) expired++; if (ttl > 0) { /* We want the average TTL of keys yet not expired. */ ttl_sum += ttl; ttl_samples++; } } /* Update the average TTL stats for this database. */ if (ttl_samples) { long long avg_ttl = ttl_sum/ttl_samples; /* Do a simple running average with a few samples. * We just use the current estimate with a weight of 2% * and the previous estimate with a weight of 98%. */ if (db->avg_ttl == 0) db->avg_ttl = avg_ttl; db->avg_ttl = (db->avg_ttl/50)*49 + (avg_ttl/50); } /* We can't block forever here even if there are many keys to * expire. So after a given amount of milliseconds return to the * caller waiting for the other active expire cycle. */ iteration++; if ((iteration & 0xf) == 0) { /* check once every 16 iterations. */ long long elapsed = ustime()-start; latencyAddSampleIfNeeded("expire-cycle",elapsed/1000); if (elapsed > timelimit) timelimit_exit = 1; } if (timelimit_exit) return; /* We don't repeat the cycle if there are less than 25% of keys * found expired in the current DB. */ } while (expired > ACTIVE_EXPIRE_CYCLE_LOOKUPS_PER_LOOP/4); } }

삭제를 수행하는 activeExpireCycleTryExpire() 소스코드: server.c
activeExpireCycle()에서 호출한다. /* Helper function for the activeExpireCycle() function. * This function will try to expire the key that is stored in the hash table * entry 'de' of the 'expires' hash table of a Redis database. * * If the key is found to be expired, it is removed from the database and * 1 is returned. Otherwise no operation is performed and 0 is returned. * * When a key is expired, server.stat_expiredkeys is incremented. * * The parameter 'now' is the current time in milliseconds as is passed * to the function to avoid too many gettimeofday() syscalls. */ int activeExpireCycleTryExpire(redisDb *db, dictEntry *de, long long now) { long long t = dictGetSignedIntegerVal(de); if (now > t) { sds key = dictGetKey(de); robj *keyobj = createStringObject(key,sdslen(key)); propagateExpire(db,keyobj); dbDelete(db,keyobj); notifyKeyspaceEvent(NOTIFY_EXPIRED, "expired",keyobj,db->id); decrRefCount(keyobj); server.stat_expiredkeys++; return 1; } else { return 0; } }

propagateExpire() 삭제할 키를 AOF 파일에 DEL 명령으로 기록하고, 슬레이브 노드에 전파해서 슬레이브 노드 DB에서 삭제되도록 한다. db.c /* Propagate expires into slaves and the AOF file. * When a key expires in the master, a DEL operation for this key is sent * to all the slaves and the AOF file if enabled. * * This way the key expiry is centralized in one place, and since both * AOF and the master->slave link guarantee operation ordering, everything * will be consistent even if we allow write operations against expiring * keys. */ void propagateExpire(redisDb *db, robj *key) { robj *argv[2]; argv[0] = shared.del; argv[1] = key; incrRefCount(argv[0]); incrRefCount(argv[1]); if (server.aof_state != AOF_OFF) feedAppendOnlyFile(server.delCommand,db->id,argv,2); replicationFeedSlaves(server.slaves,db->id,argv,2); decrRefCount(argv[0]); decrRefCount(argv[1]); }

dbDelete() 실제 키 삭제: expires와 dict 양쪽에서 삭제한다. db.c /* Delete a key, value, and associated expiration entry if any, from the DB */ int dbDelete(redisDb *db, robj *key) { /* Deleting an entry from the expires dict will not free the sds of * the key, because it is shared with the main dictionary. */ if (dictSize(db->expires) > 0) dictDelete(db->expires,key->ptr); if (dictDelete(db->dict,key->ptr) == DICT_OK) { if (server.cluster_enabled) slotToKeyDel(key); return 1; } else { return 0; } }

latency latest

127.0.0.1:6200> latency latest
1) 1) "expire-cycle"
   2) (integer) 1464135957
   3) (integer) 35
   4) (integer) 35

latency history expire-cycle

127.0.0.1:6200> latency history expire-cycle
1) 1) (integer) 1464135956
   2) (integer) 24
2) 1) (integer) 1464135957
   2) (integer) 35

latency doctor : expire-cycle

권고 사항은 두 가지인데,
첫 번째는 디폴트가 10인 hz 파라미터를 100으로 설정하라는 것이다. hz 파라미터는 여러 가지 background 작업을 하는 serverCron()의 주기를 정하는데, hz 10으로 하면 1000/10 = 100으로 100ms 마다(1초에 10번) serverCron()이 수행되는 것이다. hz를 100으로 하면 1000/100 = 10으로 10ms 마다(1초에 100번) 수행된다. serverCron() -> databasesCron() -> activeExpireCycle()을 호출해서 만료된 키들를 삭제하는데, 이것을 디폴트 1초에 10번에서 100번으로 증가시키라는 권고이다. 즉, 좀더 자주 실행해서 시간이 적게 걸리게하라는 것이다. hz 파라미터의 변경은 레디스 서버에 큰 영향을 미치므로 충분히 테스트 후에 적용을 권고합니다.

두 번째는 큰 value(object)는 삭제하는데 시간이 많이 걸리므로 가능한 작은 여러개로 나누어서 저장하라는 것이다.

127.0.0.1:6200> latency doctor
Dave, I have observed latency spikes in this Redis instance. You don't mind talking about it, do you Dave?

1. expire-cycle: 2 latency spikes (average 29ms, mean deviation 5ms, period 52.50 sec). Worst all time event 35ms.

I have a few advices for you:

- In order to make the Redis keys expiring process more incremental, try to set the 'hz' configuration parameter to 100 using 'CONFIG SET hz 100'.
- Deleting, expiring or evicting (because of maxmemory policy) large objects is a blocking operation. If you have very large objects that are often deleted, expired, or evicted, try to fragment those objects into multiple smaller objects.

redis.conf에 있는 hz 파라미터 설명

redis.conf에 있는 hz 파라미터 설명으로 expire-cycle 이벤트 설명을 마칩니다.

Redis calls an internal function to perform many background tasks, like
closing connections of clients in timeout, purging expired keys that are
never requested, and so forth.

Not all tasks are performed with the same frequency, but Redis checks for
tasks to perform according to the specified "hz" value.

By default "hz" is set to 10. Raising the value will use more CPU when
Redis is idle, but at the same time will make Redis more responsive when
there are many keys expiring at the same time, and timeouts may be
handled with more precision.

The range is between 1 and 500, however a value over 100 is usually not
a good idea. Most users should use the default of 10 and raise this up to
100 only in environments where very low latency is required.
hz 10

LATENCY EVICTION-CYCLE

Eviction은 redis.conf에 maxmemory를 설정했고, 사용 메모리가 이 한계를 넘어서면 기존 데이터(키)를 삭제하는 것이다. 클라이언트에서 명령을 입력하면 maxmemory 여부를 체크해서 메모리가 부족하면 기존 데이터를 삭제하고 본 명령을 실행하는 방식이다. Expire-cycle 처럼 주기적으로 처리하는 방식은 아니다.

MaxMemory를 설정하면 메모리를 설정한 값을 초과해서 사용할 수 없다. 메모리 관리 정책(maxmemory-policy)이 noeviction이면 레디스 서버는 새로운 입력을 더 이상 받지 않고, OOM(Out Of Memory) 에러를 내보낸다. 다른 메모리 관리 정책(allkeys-*, volatile-*)은 현재 사용 메모리에서 설정한 MaxMemory를 뺀 초과분(mem_tofree = mem_used - server.maxmemory) 만큼 기존 데이터(키)를 삭제한다. 초과분(mem_tofree)만큼 키들를 삭제하는데 걸린 시간이 eviction-cycle 이벤트로 기록한다.

여기서 주의할 사항은 eviction-del 이벤트가 eviction-cycle를 체크하는 Loop 안에 들어가 있어서 eviction-cycle 소요시간에 eviction-del이 포함되어 있을거 같지만, latencyRemoveNestedEvent()로 eviction-del 시간을 eviction-cycle 시간에서 빼주고 있으므로, eviction-cycle 시간은 eviction-del 시간을 제외한 시간이다. eviction-del은 dbDelete()로 키를 삭제하는 시간만 체크한다.

Maxmemory-policy

noeviction: 메모리가 부족해도 기존 데이터를 삭제하지 않고, 에러를 리턴한다. 더 이상 입력을 받을 수 없다.
allkeys-random: allkeys로 시작하는 파라미터는 삭제할 키 선택을 레디스의 주 데이터 관리 영역인 db->dict에서 한다. Random은 키를 랜덤으로 선택한다.
allkeys-lru: 주 데이터 관리 영역(db->dict)에서 LRU(Least Recently Used) 알고리즘으로 키를 선택해서 삭제한다.
allkeys-lfu: 주 데이터 관리 영역(db->dict)에서 LFU(Least Frequently Used) 알고리즘으로 키를 선택해서 삭제한다.
volatile-random: volatile로 시작하는 파라미터는 삭제할 키 선택을 레디스의 만료 시간이 설정된 키를 관리하는 영역인 db->expires에서 한다.
volatile-lru: 만료 시간이 설정된 키를 관리하는 영역(db->expires)에서 LRU(Least Recently Used) 알고리즘으로 키를 선택해서 삭제한다.
volatile-lfu: 만료 시간이 설정된 키를 관리하는 영역(db->expires)에서 LFU(Least Frequently Used) 알고리즘으로 키를 선택해서 삭제한다.
volatile-ttl: 만료 시간이 설정된 키를 관리하는 영역(db->expires)에서 만료시간이 근접한 키를 선택해서 삭제한다.

테스트 방법

테스트 방법은 100mb 정도 데이터를 넣은 다음 config set 명령으로 maxmemory 설정량을 10mb로 줄인다.
config set maxmemory 10mb
Latency 명령으로 확인한다.

Latency latest

127.0.0.1:6200> latency latest
2) 1) "eviction-cycle"
   2) (integer) 1464158071
   3) (integer) 748
   4) (integer) 748

Latency history eviction-cycle

127.0.0.1:6200> latency history eviction-cycle
1) 1) (integer) 1464157561
   2) (integer) 38
2) 1) (integer) 1464158071
   2) (integer) 748

Latency doctor : eviction-cycle

권고 사항은 한 가지가 나오는데, 이 테스트 경우 처럼 "config set" 명령으로 갑자기 메모리 설정값을 바꾸었을때 이 이벤트가 발생하거나, Sets 나 Sorted Sets에서 SUNIONSTORE, ZUNIONSTORE 같은 명령으로 큰 데이터를 생성했을때 발생할 수 있다는 것이다.

127.0.0.1:6200> latency doctor
2. eviction-cycle: 2 latency spikes (average 393ms, mean deviation 355ms, period 411.00 sec). Worst all time event 748ms.

- Sudden changes to the 'maxmemory' setting via 'CONFIG SET', or allocation of large objects via sets or sorted sets intersections, STORE option of SORT, Redis Cluster large keys migrations (RESTORE command), may create sudden memory pressure forcing the server to block trying to evict keys.

메모리 확보를 위한 키 삭제 function 호출 관계

그림 1-8 Latency eviction-cycle

freeMemoryIfNeeded()에서 메모리를 확보한 다음 call()에서 명령을 실행한다. 일반적인 호출 경로는 클라이언트에서 명령을 실행하면 processCommand()가 실행되고, 이어서 freeMemoryIfNeeded()와 call()이 실행된다.
Config set에서 maxmemory 설정을 변경하면 freeMemoryIfNeeded()가 호출된다.

소스코드

processCommand()에서 freeMemoryIfNeeded()를 호출하는 부분. server.c

int processCommand(client *c) {
	... 중간 생략 ...
    /* Handle the maxmemory directive.
     *
     * First we try to free some memory if possible (if there are volatile
     * keys in the dataset). If there are not the only thing we can do
     * is returning an error. */
    if (server.maxmemory) {
        int retval = freeMemoryIfNeeded();
        /* freeMemoryIfNeeded may flush slave output buffers. This may result
         * into a slave, that may be the active client, to be freed. */
        if (server.current_client == NULL) return C_ERR;

        /* It was impossible to free enough memory, and the command the client
         * is trying to execute is denied during OOM conditions? Error. */
        if ((c->cmd->flags & CMD_DENYOOM) && retval == C_ERR) {
            flagTransaction(c);
            addReply(c, shared.oomerr);
            return C_OK;
        }
    }

freeMemoryIfNeeded() server.c -> evict.c (4.0.0부터)

int freeMemoryIfNeeded(void) {
    size_t mem_used, mem_tofree, mem_freed;
    int slaves = listLength(server.slaves);
    mstime_t latency, eviction_latency;

    /* Remove the size of slaves output buffers and AOF buffer from the
     * count of used memory. */
    mem_used = zmalloc_used_memory();
    if (slaves) {
        listIter li;
        listNode *ln;

        listRewind(server.slaves,&li);
        while((ln = listNext(&li))) {
            client *slave = listNodeValue(ln);
            unsigned long obuf_bytes = getClientOutputBufferMemoryUsage(slave);
            if (obuf_bytes > mem_used)
                mem_used = 0;
            else
                mem_used -= obuf_bytes;
        }
    }
    if (server.aof_state != AOF_OFF) {
        mem_used -= sdslen(server.aof_buf);
        mem_used -= aofRewriteBufferSize();
    }

    /* Check if we are over the memory limit. */
    if (mem_used <= server.maxmemory) return C_OK;

    if (server.maxmemory_policy == MAXMEMORY_NO_EVICTION)
        return C_ERR; /* We need to free memory, but policy forbids. */

    /* Compute how much memory we need to free. */
    mem_tofree = mem_used - server.maxmemory;
    mem_freed = 0;
    latencyStartMonitor(latency);
    while (mem_freed < mem_tofree) {
        int j, k, keys_freed = 0;

        for (j = 0; j < server.dbnum; j++) {
            long bestval = 0; /* just to prevent warning */
            sds bestkey = NULL;
            dictEntry *de;
            redisDb *db = server.db+j;
            dict *dict;

            if (server.maxmemory_policy == MAXMEMORY_ALLKEYS_LRU ||
                server.maxmemory_policy == MAXMEMORY_ALLKEYS_RANDOM)
            {
                dict = server.db[j].dict;
            } else {
                dict = server.db[j].expires;
            }
            if (dictSize(dict) == 0) continue;

            /* volatile-random and allkeys-random policy */
            if (server.maxmemory_policy == MAXMEMORY_ALLKEYS_RANDOM ||
                server.maxmemory_policy == MAXMEMORY_VOLATILE_RANDOM)
            {
                de = dictGetRandomKey(dict);
                bestkey = dictGetKey(de);
            }

            /* volatile-lru and allkeys-lru policy */
            else if (server.maxmemory_policy == MAXMEMORY_ALLKEYS_LRU ||
                server.maxmemory_policy == MAXMEMORY_VOLATILE_LRU)
            {
                struct evictionPoolEntry *pool = db->eviction_pool;

                while(bestkey == NULL) {
                    evictionPoolPopulate(dict, db->dict, db->eviction_pool);
                    /* Go backward from best to worst element to evict. */
					/* MAXMEMORY_EVICTION_POOL_SIZE 16 */
                    for (k = MAXMEMORY_EVICTION_POOL_SIZE-1; k >= 0; k--) {
                        if (pool[k].key == NULL) continue;
                        de = dictFind(dict,pool[k].key);

                        /* Remove the entry from the pool. */
                        sdsfree(pool[k].key);
                        /* Shift all elements on its right to left. */
                        memmove(pool+k,pool+k+1,
                            sizeof(pool[0])*(MAXMEMORY_EVICTION_POOL_SIZE-k-1));
                        /* Clear the element on the right which is empty
                         * since we shifted one position to the left.  */
                        pool[MAXMEMORY_EVICTION_POOL_SIZE-1].key = NULL;
                        pool[MAXMEMORY_EVICTION_POOL_SIZE-1].idle = 0;

                        /* If the key exists, is our pick. Otherwise it is
                         * a ghost and we need to try the next element. */
                        if (de) {
                            bestkey = dictGetKey(de);
                            break;
                        } else {
                            /* Ghost... */
                            continue;
                        }
                    }
                }
            }

            /* volatile-ttl */
            else if (server.maxmemory_policy == MAXMEMORY_VOLATILE_TTL) {
                for (k = 0; k < server.maxmemory_samples; k++) {
                    sds thiskey;
                    long thisval;

                    de = dictGetRandomKey(dict);
                    thiskey = dictGetKey(de);
                    thisval = (long) dictGetVal(de);

                    /* Expire sooner (minor expire unix timestamp) is better
                     * candidate for deletion */
                    if (bestkey == NULL || thisval < bestval) {
                        bestkey = thiskey;
                        bestval = thisval;
                    }
                }
            }

            /* Finally remove the selected key. */
            if (bestkey) {
                long long delta;

                robj *keyobj = createStringObject(bestkey,sdslen(bestkey));
                propagateExpire(db,keyobj);
                /* We compute the amount of memory freed by dbDelete() alone.
                 * It is possible that actually the memory needed to propagate
                 * the DEL in AOF and replication link is greater than the one
                 * we are freeing removing the key, but we can't account for
                 * that otherwise we would never exit the loop.
                 *
                 * AOF and Output buffer memory will be freed eventually so
                 * we only care about memory used by the key space. */
                delta = (long long) zmalloc_used_memory();
                latencyStartMonitor(eviction_latency);
                dbDelete(db,keyobj);
                latencyEndMonitor(eviction_latency);
                latencyAddSampleIfNeeded("eviction-del",eviction_latency);
                latencyRemoveNestedEvent(latency,eviction_latency);
                delta -= (long long) zmalloc_used_memory();
                mem_freed += delta;
                server.stat_evictedkeys++;
                notifyKeyspaceEvent(NOTIFY_EVICTED, "evicted",
                    keyobj, db->id);
                decrRefCount(keyobj);
                keys_freed++;

                /* When the memory to free starts to be big enough, we may
                 * start spending so much time here that is impossible to
                 * deliver data to the slaves fast enough, so we force the
                 * transmission here inside the loop. */
                if (slaves) flushSlavesOutputBuffers();
            }
        }
        if (!keys_freed) {
            latencyEndMonitor(latency);
            latencyAddSampleIfNeeded("eviction-cycle",latency);
            return C_ERR; /* nothing to free... */
        }
    }
    latencyEndMonitor(latency);
    latencyAddSampleIfNeeded("eviction-cycle",latency);
    return C_OK;
}

LATENCY EVICTION-DEL

이 이벤트는 eviction-cycle에서 실제로 키를 삭제하는 부분만의 소요시간을 체크해서 threshold 이상이면 기록한다. Eviction-cycle은 eviction-del 시간을 제외한 시간이다. latencyRemoveNestedEvent()가 eviction-cycle 시간에서 eviction-del 시간을 제외하는 function이다.

Latency doctor : eviction-del

권고 사항은 expire-cycle에서 나온 large object에 관한 것이다.

127.0.0.1:6200> latency doctor
- Deleting, expiring or evicting (because of maxmemory policy) large objects is a blocking operation. If you have very large objects that are often deleted, expired, or evicted, try to fragment those objects into multiple smaller objects.

freeMemoryIfNeeded()안에서 키를 삭제하는 부분 server.c

	latencyStartMonitor(eviction_latency);
	dbDelete(db,keyobj);
	latencyEndMonitor(eviction_latency);
	latencyAddSampleIfNeeded("eviction-del",eviction_latency);
	latencyRemoveNestedEvent(latency,eviction_latency);

redis-cli LATENCY

이것은 redis-cli에 있는 기능으로 해당 서버에 PING을 보내서 서버 성능(응답시간)을 파악하는 기능이다.

redis-cli --latency: 응답시간을 연속해서 보여준다.
redis-cli --latency-history: 응답시간을 연속해서 보여주는데 15초가 지나면 새 줄에 보여준다.
redis-cli --latency-dist: 응답시간을 색이 있는 그래프로 보여준다.
redis-cli --intrinsic-latency:

redis-cli --latency

10ms마다(1초에 100번) PING을 보내서 얻은 응답시간이다. 응답시간 최소(min), 최대(max), 평균(avg), PING 보낸 횟수를 보여준다. 시간 단위는 millisecond이고 samples가 PING 횟수이다. 멈추려면 ctrl+C를 누른다.
static void latencyMode(void) 함수가 실행된다.

# redis-cli -p 7124 --latency
min: 0, max: 1, avg: 0.14 (15863 samples)

redis-cli --latency-history

보여주는 내용은 latency와 같고, 주어진 시간 단위로 새 줄에 보여준다. 디폴트는 15초이고 -i second 옵션을 사용해서 간격을 조정할 수 있다. 시간 단위는 millisecond이다.
static void latencyMode(void) 함수가 실행된다.

# redis-cli -p 7124 --latency-history -i 5
min: 0, max: 1, avg: 0.14 (488 samples) -- 5.00 seconds range
min: 0, max: 1, avg: 0.14 (488 samples) -- 5.01 seconds range
min: 0, max: 1, avg: 0.13 (488 samples) -- 5.00 seconds range
min: 0, max: 1, avg: 0.16 (187 samples)^C

redis-cli --latency-dist

바탕색이 비율(%)이고 문자가 시간을 나타낸다. 시간단위 microsecond이다. PING 응답시간이 기준이다. dist는 distribution의 약자이다.
static void latencyDistMode(void) 함수가 실행된다.

# redis-cli -p 7124 --latency-dist : 1초 간격으로 보여준다.
# redis-cli -p 7124 --latency-dist -i 5 : 5초 간격으로 보여준다.

그림 2-1 Latency distribution mode graph

문자는 PING 응답시간이 0.01ms 이하일 때 '.', 0.125ms 이하일 때 '-' 등으로 표시된다.
바탕색은 응답시간의 비율을 나타낸다. 칸(색)이 19개 이므로 약 5% 단위이다.
첫 번째 줄을 보면 샾(#)은 0.25ms < 응답시간 <= 0.5ms가 약 75%를 차지하고, 별(*)은 0.125ms < 응답시간 <= 0.25ms가 10%, 1은 0.5ms < 응답시간 <= 1ms가 10%, 거의 보이지 않지만 바(-)는 0.01ms < 응답시간 <= 0.125ms가 5%를 뜻한다.

redis-cli --intrinsic-latency

이것은 redis-cli에서 연산을 수행해서 얻은 응답시간을 기준으로 보여준다. CPU 성능을 체크하는 것이라고 보는 편이 적절하겠다. redis-cli 수행 시 서버를 지정할 필요가 없다. redis-cli에서 수행되는 것이므로 서버와 같은 박스(머신/VM)에서 수행해야 한다.
static void intrinsicLatencyMode(void) 함수가 실행된다.

아래는 10초 동안 수행한 결과이다.

# redis-cli --intrinsic-latency 10
Max latency so far: 1 microseconds.
Max latency so far: 3 microseconds.
Max latency so far: 6 microseconds.
Max latency so far: 157 microseconds.

234859166 total runs (avg latency: 0.0426 microseconds / 42.58 nanoseconds per run).
Worst run took 3687x longer than the average latency.

10초 동안 234,859,166회 수행되었고, 수행 1회당 42.58 nanoseconds가 걸렸다.
아래는 실제 수행되는 코드이다.

unsigned long compute_something_fast(void) {
    unsigned char s[256], i, j, t;
    int count = 1000, k;
    unsigned long output = 0;

    for (k = 0; k < 256; k++) s[k] = k;

    i = 0;
    j = 0;
    while(count--) {
        i++;
        j = j + s[i];
        t = s[i];
        s[i] = s[j];
        s[j] = t;
        output += s[(s[i]+s[j])&255];
    }
    return output;
}

FAST-COMMAND와 COMMAND 리스트

Fast-command 여부는 소스 redisCommandTable의 플레그(F)를 기준으로 했다.

명령 분류

No	Category	Fast-command	Command	Sum
1	Strings	9	16	25
2	Lists	7	10	17
3	Sets	6	9	15
4	Sorted Sets	9	12	21
5	Hashes	9	6	15
6	Common Keys	11	12	23
7	Server	3	19	22
8	PubSub	1	5	6
9	Geo	0	6	6
10	Connection	4	0	4
11	Transactions	4	1	5
12	Seripting	-	3	3
13	HyperLogLog	1	4	5
14	Cluster	3	1	4
	Total	67	104	171

Strings

No	Category	Name	구분	Time complexity
1	Strings	get	Fast-command	O(1)
2	Strings	setnx	Fast-command	O(1)
3	Strings	strlen	Fast-command	O(1)
4	Strings	getbit	Fast-command	O(1)
5	Strings	incr	Fast-command	O(1)
6	Strings	decr	Fast-command	O(1)
7	Strings	incrby	Fast-command	O(1)
8	Strings	decrby	Fast-command	O(1)
9	Strings	incrbyfloat	Fast-command	O(1)
	---	---	---
10	Strings	set	Command	O(1)
11	Strings	setex	Command	O(1)
12	Strings	psetex	Command	O(1)
13	Strings	append	Command	O(1)
14	Strings	setrange	Command	O(1)~O(M)
15	Strings	getrange	Command	O(1)~O(N)
16	Strings	substr	Command	O(1)~O(N)
17	Strings	getset	Command	O(1)
18	Strings	mget	Command	O(N)
19	Strings	mset	Command	O(N)
20	Strings	msetnx	Command	O(N)
21	Strings	setbit	Command	O(1)
22	Strings	bitop	Command	O(N)
23	Strings	bitcount	Command	O(N)
24	Strings	bitpos	Command	O(N)
25	Strings	bitfield	Command	O(1)

Lists

No	Category	Name	구분	Time complexity
1	Lists	rpush	Fast-command	O(1)
2	Lists	lpush	Fast-command	O(1)
3	Lists	rpushx	Fast-command	O(1)
4	Lists	lpushx	Fast-command	O(1)
5	Lists	rpop	Fast-command	O(1)
6	Lists	lpop	Fast-command	O(1)
7	Lists	llen	Fast-command	O(1)
	---	---	---
8	Lists	linsert	Command	O(1)~O(N)
9	Lists	rpoplpush	Command	O(1)
10	Lists	brpop	Command	O(1)
11	Lists	blpop	Command	O(1)
12	Lists	brpoplpush	Command	O(1)
13	Lists	lindex	Command	O(1)~O(N)
14	Lists	lset	Command	O(1)~O(N)
15	Lists	lrange	Command	O(S+N)
16	Lists	ltrim	Command	O(N)
17	Lists	lrem	Command	O(N)

Sets

No	Category	Name	구분	Time complexity
1	Sets	sadd	Fast-command	O(N)
2	Sets	srem	Fast-command	O(N)
3	Sets	smove	Fast-command	O(1)
4	Sets	sismember	Fast-command	O(1)
5	Sets	scard	Fast-command	O(1)
6	Sets	spop	Fast-command	O(1)
	---	---	---
7	Sets	srandmember	Command	O(1)~O(N)
8	Sets	sinter	Command	O(N*M)
9	Sets	sinterstore	Command	O(N*M)
10	Sets	sunion	Command	O(N)
11	Sets	sunionstore	Command	O(N)
12	Sets	sdiff	Command	O(N)
13	Sets	sdiffstore	Command	O(N)
14	Sets	smembers	Command	O(N)
15	Sets	sscan	Command	O(1)~O(N)

Sorted Sets

No	Category	Name	구분	Time complexity
1	Sorted Sets	zadd	Fast-command	O(log(N))
2	Sorted Sets	zcard	Fast-command	O(1)
3	Sorted Sets	zscore	Fast-command	O(1)
4	Sorted Sets	zincrby	Fast-command	O(log(N))
5	Sorted Sets	zrem	Fast-command	O(M*log(N))
6	Sorted Sets	zcount	Fast-command	O(log(N))
7	Sorted Sets	zlexcount	Fast-command	O(log(N))
8	Sorted Sets	zrank	Fast-command	O(log(N))
9	Sorted Sets	zrevrank	Fast-command	O(log(N))
	---	---	---
10	Sorted Sets	zrange	Command	O(log(N)+M)
11	Sorted Sets	zrangebylex	Command	O(log(N)+M)
12	Sorted Sets	zrangebyscore	Command	O(log(N)+M)
13	Sorted Sets	zremrangebylex	Command	O(log(N)+M)
14	Sorted Sets	zremrangebyrank	Command	O(log(N)+M)
15	Sorted Sets	zremrangebyscore	Command	O(log(N)+M)
16	Sorted Sets	zrevrange	Command	O(log(N)+M)
17	Sorted Sets	zrevrangebylex	Command	O(log(N)+M)
18	Sorted Sets	zrevrangebyscore	Command	O(log(N)+M)
19	Sorted Sets	zinterstore	Command	O(NK)+O(Mlog(M))
20	Sorted Sets	zunionstore	Command	O(N)+O(M log(M))
21	Sorted Sets	zscan	Command	O(1)~O(N)

Hashes

No	Category	Name	구분	Time complexity
1	Hashes	hset	Fast-command	O(1)
2	Hashes	hsetnx	Fast-command	O(1)
3	Hashes	hget	Fast-command	O(1)
4	Hashes	hincrby	Fast-command	O(1)
5	Hashes	hincrbyfloat	Fast-command	O(1)
6	Hashes	hdel	Fast-command	O(N)
7	Hashes	hlen	Fast-command	O(1)
8	Hashes	hstrlen	Fast-command	O(1)
9	Hashes	hexists	Fast-command	O(1)
	---	---	---
10	Hashes	hmset	Command	O(N)
11	Hashes	hmget	Command	O(N)
12	Hashes	hkeys	Command	O(N)
13	Hashes	hvals	Command	O(N)
14	Hashes	hgetall	Command	O(N)
15	Hashes	hscan	Command	O(1)~O(N)

Common Keys

No	Category	Name	구분	Time complexity
1	Common Keys	exists	Fast-command	O(1)
2	Common Keys	move	Fast-command	O(1)
3	Common Keys	renamenx	Fast-command	O(1)
4	Common Keys	expire	Fast-command	O(1)
5	Common Keys	expireat	Fast-command	O(1)
6	Common Keys	pexpire	Fast-command	O(1)
7	Common Keys	pexpireat	Fast-command	O(1)
8	Common Keys	type	Fast-command	O(1)
9	Common Keys	ttl	Fast-command	O(1)
10	Common Keys	pttl	Fast-command	O(1)
11	Common Keys	persist	Fast-command	O(1)
	---	---	---
12	Common Keys	del	Command	O(N)
13	Common Keys	randomkey	Command	O(1)
14	Common Keys	rename	Command	O(1)
15	Common Keys	keys	Command	O(N)
16	Common Keys	scan	Command	O(1)~O(N)
17	Common Keys	sort	Command	O(N+M*log(M))
18	Common Keys	restore	Command	O(1)~O(N*M)
19	Common Keys	restore-asking	Command
20	Common Keys	migrate	Command	dump+del
21	Common Keys	dump	Command	O(1)+O(N*M)
22	Common Keys	object	Command	O(1)
23	Common Keys	wait	Command	O(1)

Server

No	Category	Name	구분
1	Server	dbsize	Fast-command
2	Server	lastsave	Fast-command
3	Server	time	Fast-command
	---	---	---
4	Server	save	Command
5	Server	bgsave	Command
6	Server	bgrewriteaof	Command
7	Server	shutdown	Command
8	Server	sync	Command
9	Server	psync	Command
10	Server	replconf	Command
11	Server	flushdb	Command
12	Server	flushall	Command
13	Server	info	Command
14	Server	monitor	Command
15	Server	latency	Command
16	Server	slaveof	Command
17	Server	role	Command
18	Server	debug	Command
19	Server	config	Command
20	Server	slowlog	Command
21	Server	command	Command
22	Server	client	Command

PubSub

O(N)

No	Category	Name	구분	Time complexity
1	PubSub	publish	Fast-command	O(N+M)
	---	---	---
2	PubSub	subscribe	Command	O(N)
3	PubSub	unsubscribe	Command	O(N)
4	PubSub	psubscribe	Command	O(N)
5	PubSub	punsubscribe	Command	O(N+M)
6	PubSub	pubsub	Command

Geo

No	Category	Name	구분	Time complexity
1	Geo	geoadd	Command	O(log(N))
2	Geo	georadius	Command	O(N+log(M))
3	Geo	georadiusbymember	Command	O(N+log(M))
4	Geo	geohash	Command	O(log(N))
5	Geo	geopos	Command	O(log(N))
6	Geo	geodist	Command	O(N+log(M))

Connection

No	Category	Name	구분
1	Connection	auth	Fast-command
2	Connection	ping	Fast-command
3	Connection	echo	Fast-command
4	Connection	select	Fast-command

Transactions

No	Category	Name	구분	Time complexity
1	Transactions	multi	Fast-command
2	Transactions	discard	Fast-command
3	Transactions	watch	Fast-command	O(1)
4	Transactions	unwatch	Command	O(1)
	---	---	---
5	Transactions	exec	Command

Scripting

No	Category	Name	구분	Time complexity
1	Scripting	eval	Command
2	Scripting	evalsha	Command
3	Scripting	script	Command	O(1)~O(N)

HyperLogLog

No	Category	Name	구분	Time complexity
1	HyperLogLog	pfadd	Fast-command	O(1)
	---	---	---
2	HyperLogLog	pfcount	Command	O(1)~O(N)
3	HyperLogLog	pfmerge	Command	O(N)
4	HyperLogLog	pfdebug	Command
5	HyperLogLog	pfselftest	Command

Cluster

No	Category	Name	구분	Time complexity
1	Cluster	readonly	Fast-command	O(1)
2	Cluster	readwrite	Fast-command	O(1)
3	Cluster	asking	Fast-command
	---	---	---
4	Cluster	cluster	Command

LATENCY 관련 참고 자료

명령문

LATENCY subcommand [event-name1 event-name2 ... event-nameN]

이 기능은 2014년 7월 14일(월) 발표된 버전 2.8.13부터 사용가능합니다.

Clients for C

Hiredis

<< SLOWLOG	LATENCY	MONITOR >>

조회수 :

Email 답글이 올라오면 이메일로 알려드리겠습니다.