Fluentd tail input 로그 1개 손실 & 로그 느리게 들어오는 이유 해결

한줄요약 : multiline 때문입니다. multiline_flush_interval 옵션을 사용하면 해결됩니다.

 

Fluentd로 로그를 수집하는데, 

초당 로그를 일정하게 발생시키는 스크립트를 짜고 로그 수집을 테스트해보는데

왜인지 테스트 할때마다 로그가 1개씩 덜 들어왔다.

왜 그러지..? 싶었으나 원인을 쉽게 찾을 수 없었다.

 

그리고 Kinesis output을 사용할 때, 

로그가 1초에 여러번 들어오면 '로그 발생 -> Kinesis -> ES 적재'까지 몇 초 내로 적재되었으나

로그를 1분에 한 번 꼴로 발생시킬 경우 '로그 발생 -> Kinesis -> ES 적재'까지 60초 + flush interval에 해당하는 시간이 걸렸다.
(여기서 알아챘어야 했다.. ㅎㅎ)

 

왜 위의 두가지 현상이 발생하나 했더니, 

<parse>
  @type multiline
  format_firstline /\d{4}-\d{1,2}-\d{1,2}/
  format1 /^(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2}) \[(?<thread>.*)\] (?<level>[^\s]+)(?<message>.*)/
</parse>

tail input에서 위와 같이 multiline parser를 사용할 경우, 

2013-3-03 14:27:33 [main] INFO  Main - Start
2013-3-03 14:27:33 [main] ERROR Main - Exception
javax.management.RuntimeErrorException: null
    at Main.main(Main.java:16) ~[bin/:na]
2013-3-03 14:27:33 [main] INFO  Main - End

위와 같은 로그에서

\d{4}-\d{1,2}=\d{1,2} (2013-3-03) 과 같은 연-월-일 형식으로 로그가 시작한다면 각 줄을 다른 로그로 인식한다.

그러면서 다음 줄을 기다리며 목적지로 flush 되지 않는다. 그래야 현재의 로그를 어떻게 처리할지 알 수 있기 때문이다.

그렇기 때문에 로그 수집이 1개씩 덜 되었고, 60초 뒤에 다음 로그가 생성될 때까지 로그 수집이 지연되었던 것이었다.

 

<source>
  @type tail
  <parse>
    @type multiline
    format_firstline /\d{4}-\d{1,2}-\d{1,2}/
    format1 /^(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2}) \[(?<thread>.*)\] (?<level>[^\s]+)(?<message>.*)/
  </parse>
  tag multiline.*
  multiline_flush_interval 1s
</source>

<match multiline.**>
  @type kinesis_streams
  region ap-northeast-2
  stream_name test-stream
  <buffer>
    flush_interval 1s
    flush_thread_interval 0.1 # The sleep interval (seconds) for threads to wait for the next flush try (when no chunks are waiting)
    flush_thread_burst_interval 0.01 # The sleep interval (seconds) for threads between flushes when the output plugin flushes the waiting chunks to the next ones
    flush_thread_count 4 # The number of threads to flush/write chunks in parallel
  </buffer>
</match>

tail에 multiline_flush_interval을 넣으면 해결할 수 있다.

기존에는 로그스태시 -> SQS 를 사용하였는데, 로그 발생 -> 적재까지 1초 정도가 걸렸다.

같은 성능을 내기 위해 flush_interval, multiline_flush_interval을 1초로 해 주었는데,

1초에 50개씩 로그를 수집하는 환경에서 flush_interval을 5초, 1초, 0초로 달리하며 실험을 해 보았다.

flush_interval이 0초인 경우 flush_mode가 immediate고 multiline_flush_interval은 0.1로 설정해 주었다.

CPU 사용 측면에서는 multiline_flush_interval이 0.1초(flush mode는 immediate) 인 경우가 
multiline_flush_interval이 1초, 5초인 경우보다 CPU 사용량이 2.5배 이상 많았다.

흥미로운 점은 1초와 5초의 경우 별반 차이가 나지 않았다는 점이다. 

 

메모리 사용량의 경우 오히려 flush_interval이 짧을 수록 낮았는데, 

kinesis output 플러그인이 메모리 버퍼를 사용해서 그런 듯 하다.