로그를 Elasticsearch 한 자리에 모으기로 하고 각 서버에 Logstash 를 올렸다. 붙인 다음 날 응답 시간이 늘었다는 말이 나왔다.
Table of contents
Open Table of contents
증상 — 붙이고 나서 늘어난 것
top 으로 자원 사용량을 보니 Logstash 의 JVM 이 애플리케이션보다 많은 CPU 를 쓰고 있었다. 디스크 읽기도 늘어 로그 파일을 계속 읽고 있었다.
로그를 모으는 것 자체가 공짜가 아니라는 것이 숫자로 드러났다. 붙인 뒤에 재 보지 않았으면 응답 지연의 원인을 애플리케이션에서 찾았을 것이다.
원인 — 모으는 비용과 파싱 비용
logstash.conf 를 보니 각 서버에서 grok 정규식으로 한 줄씩 뜯어 구조화하고 있었다. 초당 수천 줄이면 그만큼 정규식이 돈다.
보내는 비용보다 파싱하는 비용이 훨씬 컸다. 무엇이 비싼지를 가르지 않으면 전송량만 줄이는 엉뚱한 대응으로 간다.
조치 — 어디서 처리할지가 비용을 바꾼다
두 가지 방법이 있었다. 각 서버의 Logstash 를 그대로 두고 grok 패턴만 가볍게 다듬는 것과, 각 서버에는 Filebeat 만 두고 파싱을 중앙 Logstash 로 옮기는 것이다. 뒤쪽을 골랐다. 이유는 중앙 쪽은 전용 장비라 그 처리를 감당할 여유가 있어서다. 대신 중앙 Logstash 한 대가 전 서버 로그의 병목이 되는 것을 감수했다. 옮기니 API 서버의 CPU 가 크게 내려갔다.
같은 처리를 어디서 하느냐가 비용을 통째로 바꾸므로 여유가 있는 쪽에서 하게 배치한다. 더 나은 방법은 애플리케이션이 처음부터 구조화된 형태로 쓰는 것이라 새로 쓰는 로그부터 logstash-logback-encoder 로 JSON 으로 바꿨다.
무엇을 보낼지와 얼마나 둘지
종류별 양을 세어 보니 DEBUG 로그가 가장 많은데 아무도 보지 않았다. ERROR 와 WARN 과 접속과 감사만 보내고 DEBUG 는 서버 파일로만 남겨 며칠 뒤 지우게 하니 전송량이 크게 줄었다.
보관 기간도 Elasticsearch 인덱스마다 다르게 뒀다. 오류와 감사는 오래 봐야 하고 접속 로그는 Kibana 로 통계를 뽑은 뒤에는 덜 보므로 필요한 용량이 절반 아래로 내려갔다.
끊겼을 때와 감시 경로
Elasticsearch 가 죽으면 못 보내므로 중앙 Logstash 에 queue.type: persisted 로 디스크 큐를 두고 붙으면 보내게 했다. Logstash 7.8 공식 문서대로 queue.max_bytes 상한에 닿으면 입력에 백프레셔가 걸리는데, 그 사이 서버 쪽 로그 파일이 회전해 오래된 것이 사라지는 것은 받아들였다. 로그 때문에 서비스가 멈추면 안 되기 때문이다.
Filebeat 가 살아 있는지와 큐가 얼마나 밀렸는지와 사라진 것이 있는지를 셌다. 로그 수집이 안 되면 아무 로그도 안 남으므로 그 상태는 로그가 아니라 별도 경로로 확인하게 했다.
정리
- 로그를 모으면 그만큼 자원을 쓰므로 붙이고 나서 잰다
- 재 보지 않으면 지연의 원인을 엉뚱한 데서 찾는다
- 모으는 비용보다
grok파싱 비용이 클 수 있다 - 같은 처리를 어디서 하느냐가 비용을 통째로 바꾼다
- 애플리케이션이 처음부터 JSON 으로 쓰면 파싱이 필요 없다
- 아무도 안 보는
DEBUG를 빼고 보관 기간을 인덱스마다 다르게 둔다 Elasticsearch가 죽어도 서비스가 안 멈추게 하고 사라지는 것을 받아들인다- 수집 자체의 상태는 로그가 아닌 별도 경로로 확인한다