AOF fsync is taking too long

개요 槪要 Outline

레디스 서버 로그에 "Asynchronous AOF fsync is taking too long..." 로 시작하는 메시지가 남고 레디스 서버에서 처리가 늦어진다.   클라이언트에서 예외(exception) 또는 접속 시간초과(connection timeout)가 발생할 수 있다.   이것은 AOF를 활성화(appendonly yes)했고, appendfsync 파라미터가 everysec이고, 디스크 I/O 부하가 심할 경우 발행한다.
이 글에서는 발생 사례와 원인에 대해서 설명하고 해결 방안을 제시한다.

발생 사례 事例 Case

• Case 1)   AOF 파일을 백업용으로 디스크의 다른 디렉토리에 복사할 때 이 로그가 발생하고 클라이언트(jedis)에서 예외(exception) 발생
• Case 2)   동일 서버에 여러 대의 레디스 서버를 운영할 경우 A 레디스 인스턴스에서 RDB를 쓰는 도중 B 레디스 인스턴스에서 fsync 중 이 로그 발생하고 클라이언트에서 연결 시간초과(connection timeout) 발생

원인(原因, root cause) 찾기 테스트

• 테스트 개요: 해당 로그가 발생하면 레디스 인스턴스가 잠시 멈추어서 처리 지연이 발생하는지에 대한 테스트이다.
• 1개 클라이언트(python)에서 입력(set) 실행 중 10GB AOF 파일 복사
  서버 로그
  29662:M 05 Oct 11:14:55.010 * Asynchronous AOF fsync is taking too long...
  29662:M 05 Oct 11:14:58.023 * Asynchronous AOF fsync is taking too long...
  29662:M 05 Oct 11:15:41.053 * Asynchronous AOF fsync is taking too long...
  
  클라이언트 로그
  key:keyTA10000404512, Current time: 11:14:55.009, Elapsed time(ms): 0.037
  key:keyTA10000404513, Current time: 11:14:55.207, Elapsed time(ms): 197.449
  
  key:keyTA10000445256, Current time: 11:14:58.022, Elapsed time(ms): 0.052
  key:keyTA10000445257, Current time: 11:14:58.254, Elapsed time(ms): 231.616
  
  key:keyTA10000833487, Current time: 11:15:41.052, Elapsed time(ms): 0.040
  key:keyTA10000833488, Current time: 11:15:41.222, Elapsed time(ms): 169.548
  
  서버 로그 발생 시각 별로 클라이언트 로그를 보면 처리 시간이 197ms, 231ms, 169ms로 평상시 0.03ms ~ 0.05ms에 비교해서 상당히 오래걸렸음을 알 수 있다.
• 5개 클라이언트(python)에서 입력(set) 실행 중 10GB AOF 파일 5개를 동시에 복사
  AOF 파일을 동일 SSD의 다른 디렉토리로 복사한 것이다.
  서버 로그: 거의 2초마다 발생했다.
  30583:M 05 Oct 15:12:09.096 * Asynchronous AOF fsync is taking too long...
  30583:M 05 Oct 15:12:11.095 * Asynchronous AOF fsync is taking too long...
  30583:M 05 Oct 15:12:13.026 * Asynchronous AOF fsync is taking too long...
  30583:M 05 Oct 15:12:15.030 * Asynchronous AOF fsync is taking too long...
  30583:M 05 Oct 15:12:17.083 * Asynchronous AOF fsync is taking too long...
  ...
  
  첫 번째 서버 로그에 대한 5개 클라이언트 로그: 5개 클라이언트에서 거의 일정하게 899ms의 처리 시간 지연이 발생했다.
  key:key1D10000473658, Current time: 15:12:09.095, Elapsed time(ms): 0.041
  key:key1D10000473659, Current time: 15:12:09.995, Elapsed time(ms): 899.736
  
  key:key2D10000409453, Current time: 15:12:09.095, Elapsed time(ms): 0.068
  key:key2D10000409454, Current time: 15:12:09.995, Elapsed time(ms): 899.760
  
  key:key3D10000354581, Current time: 15:12:09.095, Elapsed time(ms): 0.071
  key:key3D10000354582, Current time: 15:12:09.995, Elapsed time(ms): 899.729
  
  key:key4D10000316558, Current time: 15:12:09.095, Elapsed time(ms): 0.066
  key:key4D10000316559, Current time: 15:12:09.995, Elapsed time(ms): 899.752
  
  key:key5D10000266604, Current time: 15:12:09.095, Elapsed time(ms): 0.068
  key:key5D10000266605, Current time: 15:12:09.995, Elapsed time(ms): 899.731
  아래는 iostat 값이다.   명령: iostat -x sda3 sdb1 -t -m 1
  CPU iowait은 상당히 높게 나타났다. 2016년 10월 05일 15시 12분 08초 avg-cpu: %user %nice %system %iowait %steal %idle 45.03 0.00 20.41 23.98 0.00 10.59 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sdb1 0.00 9.00 0.00 84.00 0.00 38.21 931.62 18.19 211.73 0.00 211.73 4.89 41.10 sda3 52.00 0.00 15.00 0.00 0.26 0.00 35.73 0.25 16.33 16.33 0.00 9.40 14.10 2016년 10월 05일 15시 12분 09초 avg-cpu: %user %nice %system %iowait %steal %idle 44.49 0.00 19.10 22.56 0.00 13.85 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sdb1 0.00 0.00 0.00 40.00 0.00 8.09 414.20 0.78 29.65 0.00 29.65 5.42 21.70 sda3 8.00 0.00 24.00 0.00 0.12 0.00 10.67 0.16 6.67 6.67 0.00 2.88 6.90 2016년 10월 05일 15시 12분 10초 avg-cpu: %user %nice %system %iowait %steal %idle 3.92 0.00 2.28 52.03 0.00 41.77 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sdb1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sda3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 2016년 10월 05일 15시 12분 11초 avg-cpu: %user %nice %system %iowait %steal %idle 44.29 0.00 18.49 25.42 0.00 11.81 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sdb1 0.00 0.00 0.00 33.00 0.00 5.85 362.91 0.58 17.64 0.00 17.64 5.09 16.80 sda3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 2016년 10월 05일 15시 12분 12초 avg-cpu: %user %nice %system %iowait %steal %idle 24.17 0.00 11.07 37.91 0.00 26.84 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sdb1 0.00 0.00 0.00 11.00 0.00 1.55 288.73 0.22 19.82 0.00 19.82 6.36 7.00 sda3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 아래는 15시 12분 1분간 CPU 사용률과 iowait 차트이다.
  
• 동일 환경 테스트에서 HDD보다 SSD에서 해당 로그가 더 자주 발생했다.   SSD가 HDD에 비해서 성능은 좋은 반면 읽기/쓰기 시에 블록킹(blocking)이 발생하는 것으로 보인다.
• latency monitor: 여기서는 로그 발생시점에 latency monitor의 aof-write-pending-fsync 이벤트 시간과 클라이언트 지연 시간을 같이 보았다.   첫 번째는 로그 발생 시각, 두 번째는 aof-write-pending-fsync 이벤트 시각과 지연 시간(ms), 세 번째는 클라이언트 지연시간(ms)이다.
  발생 시각과 지연 시간이 거의 일치함을 알 수 있다.
  41768:M 07 Oct 09:58:48.059 * Asynchronous AOF fsync is taking too long...
  
  1) (integer) 1475801928
  2) (integer) 155
  
  key:keyXXX101483560, Current time: 09:58:48.059, Elapsed time(ms): 0.043
  key:keyXXX101483561, Current time: 09:58:48.214, Elapsed time(ms): 155.673
  41768:M 07 Oct 09:58:59.040 * Asynchronous AOF fsync is taking too long...
  
  1) (integer) 1475801939
  2) (integer) 239
  
  1691418 key:keyXXX101691417, Current time: 09:58:59.037, Elapsed time(ms): 0.044
  1691419 key:keyXXX101691418, Current time: 09:58:59.279, Elapsed time(ms): 241.579
  결론적으로 fsync로 인한 write 시간 지연이 발생하는 것을 알 수 있다.
• slowlog: 지금까지 설명한 것처럼 클라이언트의 명령 처리는 지연되었다.   그런데 slowlog를 보면 조회되지 않는다.   이유를 생각해 보면, slowlog에 남는 처리 시간은 클라이언트에서 명령을 받아 파싱한 후 서버내에서 처리 시간만으로 측정하는데, 이 경우 write로 인한 서버 멈춤이 발생하면 클라이언트로 부터의 요청 조차도 받아들이지 못하기 때문인 것으로 보인다.   멈춤이 풀리면 그 다음에 클라이언트의 요청을 받아들여 처리하기 때문에 서버 내에서의 처리 시간은 slowlog-log-slower-than 설정값을 이상으로 나오지 않는것이다.
  
• 테스트 결과: fsync중에는 데이터를 커널에 쓰는 system call인 write명령 수행이 지연된다. Write는 불록킹(blocking)명령이므로 write가 완료될 때까지 레디스 서버는 멈춘 상태가 된다.

해결 방안 解決 方案 Solution

• "Case 1)   AOF 파일을 백업용으로 디스크의 다른 디렉토리에 복사"에 대한 해결 방안
  이 로그는 성능이 좋은 디스크를 사용하면 발생 빈도를 많이 줄일 수는 있지만 디스크 I/O 부하에 따라 완전히 없앨 수는 없을 것으로 보인다.   여기서는 디스크 성능 의존적이지 않은 방법으로 레디스 서버 설정 값 변경으로 해결한다.   파일을 복사하기 직전에 appendfsync를 no로 변경하고, 복사 후에 appendfsync everysec로 원래대로 변경한다.
  처리 순서
  • Step 1: redis-cli config set appendfsync no
  • Step 2: AOF 파일 복사
  • Step 3: redis-cli config set appendfsync everysec
  appendfsync no로 했을 경우 디스크 쓰기는 OS(linux)가 한다.   쓰기 지연은 최대 30초까지 발행할 수 있다.   그러므로 이 방법은 데이터 유실을 30초까지 허용할 경우에 적용할 수 있다.   하지만 슬레이브 서버를 운영할 경우에는 거의 실시간으로 슬레이브에 복제되므로 슬레이브에서 복구할 수 있다.
  AOF 파일 백업에 대한 자세한 내용은 여기를 보세요.
• "Case 2)   A 레디스에서 RDB를 쓰는 도중 B 레디스 fsync 중 이 로그 발생"에 대한 해결 방안
  이것은 Case 1) 해결 방법으로 하는 해결할 수 없다.   왜냐하면 AOF 파일 복사는 운영자가 하는 것이지만, RDB 쓰기는 레디스 서버에서 하는 것이기 때문이다.   이 경우 RDB 사용을 중지하고 AOF만 사용할 것을 제안한다.   인터넷에 올라와있는 어떤 사용자의 경우에도 RDB 사용을 중지하고 이 문제가 발생하지 않았다고 한다.

하드디스크 구성 Hard Disk Configuration

여기서는 AOF 사용 시 SSD와 HDD를 어떻게 적절히 사용할 것인가 대해서 얘기한다.

• SSD: AOF 파일 위치를 SSD에 놓을 것을 권장한다.   auto-aof-rewrite-percentage를 0으로 설정해서 AOF가 자동 rewrite하지 않도록 한다.   AOF를 자동 rewrite할 경우 또는 RDB를 사용할 경우 Case 2)에서 처럼 다른 레디스 서버에서 이 로그가 발생할 수 있다.   AOF rewrite는 하루에 한번 정도 사용이 적은 시간을 선택해서 bgrewriteaof 명령을 사용해서 크기를 줄인다.
  물리적인 서버(박스) 1대에 레디스 인스턴스를 4개 올려서 운영할 경우 레디스 인스턴스 당 메모리 사용량을 32GB 사용한다면, AOF 파일이 메모리 보다 늘어날 것을 대비해서 64GB 씩 잡고 64GB * 4개 인스턴스 = 256GB,   SSD 용량을 256GB로 할 것을 권장한다.
• HDD: HDD는 AOF 파일 백업용으로 보관할 때 사용한다.

로그(taking is too long) 발생 횟수 확인: info persistence

info persistence 명령으로 보면 마지막 항목에 aof_delayed_fsync가 나온다.   여기 나온 숫자가 서버 시작부터 현재 까지 이 로그 발생 횟수이다.   config resetstat를 사용하면 횟수가 초기화된다.

클라이언트 설정 Client Configuration

위에 설명드린 레디스 서버와 더불어 클라이언트 timeout 설정이나 connection pool 설정을 확인하는 것이 문제 해결에 도움이 될 것으로 생각됩니다.

관련 소스 설명 About Sources

AOF 관련 소스는 aof.c에 있다.   appendfsync가 everysec일 경우 fsync는 별도의 쓰레이드에서 실행된다.   fsync를 수행할 때 현재 수행중인지 체크한다.   수행중이고 2초 미만일 때는 후속 처리를 하지 않고 리턴한다.   2초 이상이면 aof_delayed_fsync를 1 증가 시키고(라인번호 314) 이 로그(AOF fsync is taking too long...)를 남기고(라인번호 315), 후속 처리를 계속한다. 하지만 이 경우에 fsync를 또 실행시키지는 않는다(라인번호 444). void flushAppendOnlyFile(int force) { ssize_t nwritten; int sync_in_progress = 0; mstime_t latency; if (sdslen(server.aof_buf) == 0) return; if (server.aof_fsync == AOF_FSYNC_EVERYSEC) sync_in_progress = bioPendingJobsOfType(BIO_AOF_FSYNC) != 0; if (server.aof_fsync == AOF_FSYNC_EVERYSEC && !force) { /* With this append fsync policy we do background fsyncing. * If the fsync is still in progress we can try to delay * the write for a couple of seconds. */ if (sync_in_progress) { if (server.aof_flush_postponed_start == 0) { /* No previous write postponing, remember that we are * postponing the flush and return. */ server.aof_flush_postponed_start = server.unixtime; return; } else if (server.unixtime - server.aof_flush_postponed_start < 2) { /* We were already waiting for fsync to finish, but for less * than two seconds this is still ok. Postpone again. */ return; } /* Otherwise fall trough, and go write since we can't wait * over two seconds. */ server.aof_delayed_fsync++; serverLog(LL_NOTICE,"Asynchronous AOF fsync is taking too long (disk is busy?). Writing the AOF buffer without waiting for fsync to complete, this may slow down Redis."); } } /* We want to perform a single write. This should be guaranteed atomic * at least if the filesystem we are writing is a real physical one. * While this will save us against the server being killed I don't think * there is much to do about the whole server stopping for power problems * or alike */ ... /* Perform the fsync if needed. */ if (server.aof_fsync == AOF_FSYNC_ALWAYS) { /* aof_fsync is defined as fdatasync() for Linux in order to avoid * flushing metadata. */ latencyStartMonitor(latency); aof_fsync(server.aof_fd); /* Let's try to get this data on the disk */ latencyEndMonitor(latency); latencyAddSampleIfNeeded("aof-fsync-always",latency); server.aof_last_fsync = server.unixtime; } else if ((server.aof_fsync == AOF_FSYNC_EVERYSEC && server.unixtime > server.aof_last_fsync)) { if (!sync_in_progress) aof_background_fsync(server.aof_fd); server.aof_last_fsync = server.unixtime; } }

정리 整理 Summary

"AOF fsync is taking too long..." 로그 발생 사례, 테스트를 해서 클라이언트 로그, iostat, latency monitor로 원인을 알아보았고, 해결 방법 살펴보았고, 더불어 하드 디스크 구성과 로그 발생 횟수를 조회해 보는 방법을 알아보았습니다.   이 글이 운영에 도움이 되기길 바랍니다.   이 글을 보시고 질문이나 의문사항있으면 댓글을 올려주세요.   더불어 잘못된 내용이 있으면 알려주시면 고맙겠습니다.