로그 모니터링 개발 기록 03. 검색엔진의 성능 최적화

2021년 11월부터 현재(24년 1월)까지 약 2년동안 와탭 로그 모니터링을 개발하면서 배우고 느꼈던 것들을 정리하고 있습니다. 검색 엔진의 저장 구조, 조회 구조 다음으로 성능 최적화를 다루고 있습니다. 이번 글에서는 가장 아쉬움이 많이 남는 기능인 동시에, 가장 성능 개선이 많이 진행된 기능인 ‘임의의 문자열로 검색하기’에 대해서 이야기를 해보겠습니다.

---

들어가며

엄청나게 많은 문서 속에서 임의의 문자열이 등장하는 단 하나의 문서를 찾으려면 어떻게 해야할까요?

첫 번째 방법은 모든 키워드에 대해서 색인을 생성하는 것입니다. 검색엔진의 저장 구조 이해하기를 읽어주신 분이라면 ‘색인’은 특정 단어로 직접 이동할 수 있는 자료구조라는 것과 Inverted Index, SSTable을 사용해서 개념적으로 어떻게 색인이 원본 데이터를 찾아갈 수 있는지를 이해하셨을거라고 생각합니다.

두 번째 방법은 전체 문서를 Full Scan 하는 방법이 있습니다. 모든 데이터를 대상으로 Full Scan을 한다는 것은 엔지니어에게 어떻게 보면 자존심이 상하는 일이기도 합니다. 하지만 Lucene에서 제공하는 문자열 분석 과정(Field → List<Token>)에 대한 접근법을 제외한 상태에서는 요구사항에 만족하는 유일한 방법이기도 합니다. 검색엔진의 저장 구조 이해하기, 검색엔진의 조회 구조 이해하기 라는 글을 쓴 것도, Lucene의 접근 방법을 몰라서, 저와 같은 뼈아픈 선택을 하는 분들이 없었으면 좋겠다는 마음에 작성된 글이기도 합니다.

이번 글은 무모하게도 하루 23건의 로그를 대상으로 임의의 키워드를 문자열 매칭(contains)로 검색하는 기능을 개발하고 개선한 과정을 담고 있습니다.

요구사항

하루 약 23억건의 로그가 쌓이는 환경이 있습니다. 대부분의 로그는 07시부터 21시 사이에 수집되고, 가장 많은 로그가 수집되는 시간은 13시 전후입니다. 1분동안 수집되는 로그 수는 약 최대 330만건입니다. 이러한 상황에서 사용자는 임의의 키워드가 포함된 로그를 검색하고자 합니다. 여기서 임의의 키워드란 “RuntimeException”, “BusinessCode A031”, “error”, “12323523432578”, “request.header.key” 등과 같이 정말로 임의의 키워드를 말합니다.

접근 방법 고민하기

먼저 당장 사용할 수 있는 기술력의 범위를 점검해봤습니다. 색인을 사용한 검색은 수 억개의 데이터 속에서 찾는 데이터를 0.5초 이내로 검색할 수 있을정도로 굉장히 빠른 상황입니다. 하지만 색인을 생성해야하는 키워드가 임의의 키워드이기 때문에 어떤 키워드에 대해서 색인을 생성할지 알 수 없다는 어려움이 있습니다. 이 시점에서 논의도 많이 해보고 검색도 많이 해보았지만, 지금은 알고 있는 Lucene의 문자열 분석 방법에 대한 아이디어를 얻지 못해서, 차선책으로 당장 제공할 수 있는 방법인 Full Scan 기능을 제공하는 것으로 방향을 잡았습니다.

과거의 저에게 Lucene In Action을 조금만 시간을 내어서 읽어보라고 알려주고 싶지만, 고객사 요구사항이 엑셀 시트로 관리되고 각 항목마다 배포 일정이 정해져있고 하루에도 2번씩 우선순위가 변경되어 잦은 야근으로 많이 피곤했던 당시의 상황에서는 책을 찾아볼 여유가 없었던 것도 사실입니다. 그저 신규 제품이었던 로그 모니터링에 운좋게도 찾아온 대형 고객사 레퍼런스를 잡기 위해서 가장 빠르게 대응할 수 있는 방법을 찾아서 진행했었습니다.

지금 상태로 다시 만든다면 Lucene의 Analyzer 부분만 뜯어다가 서비스로 만들거나, 색인과 조회 기능만을 위해 Lucene을 도입하는 방향으로 조직에 제안을 드려볼 것 같습니다. Lucene의 Analyzer 부분만 뜯어다가 사용하는 이유는 Tokenize 전략에 대한 고도화와 최적화가 직접 구현하기에는 어쩔 수 없이 시간이 많이 걸리는 부분이기 때문입니다. 예를 들어 “hwanseok-dev@gmail.com”라는 문자열을 분석해야한다면 단순히 특수 문자를 기준으로 “hwanseok”, “dev”, “gmail.com” 뿐만 아니라 “hwanseok-dev@gmail.com”이라는 하나의 Token으로도 다루는 등의 고도화된 Tokenize 전략이 많이 필요합니다. 그런데 이러한 고도화 과정의 대부분이 Lucene의 StandardAnalyzer 에서 이미 발전이 되어 있고, Lucene이 Apache 2.0 라이센스라서 솔루션 제품에서도 부담없이 가져와서 사용할 수 있기 때문입니다.

Phase 1. Full Scan 검색 일단 적용해보기, 약 80만개 / 30초

접근 방법에 대해서 아쉬움이 많이 남아서 사설이 길어졌네요. 다시 돌아와서, 일단 임의의 키워드로 Full Scan 검색 기능을 추가해봤습니다.

getFullScanHandler

 

위 코드 조각은 Functional Interface를 사용하는 형태로 개발되어 있습니다. H1은 파라미터를 1개를 전달받아서 사용하는 Handler라는 뜻입니다.

public interface H1<A> {
	public void process(A a) throws Exception;
}

getOriginWrapper 클래스의 파라미터의 의미는 아래와 같습니다.

• long fetchLimit : DB에서 한 번에 조회할 수 있는 최대 데이터 갯수. 이 값을 제한하지 않으면 Disk IOPS 성능에 과부하가 발생합니다.
• long searchLimit : fetch된 데이터 중에서 임의의 키워드와 매칭되어 사용자에게 전달되어야 하는 최대 데이터 갯수. 이 값을 제한하지 않으면 String#contains을 수행하는 과정에서 CPU 성능에 과부하가 발생합니다.
• H1<LogSinkPack> origin : DB에서 조회된 데이터가 하나씩 전달되는 Handler
• SeKey contentSeKey : 사용자가 입력한 임의의 문자열이 포함된 객체 (SearchKey)

getOriginWrapper 클래스는 크게 3 부분으로 나뉘어져 있습니다. withLimit, withContentSearch 그리고 return에서 익명으로 전달되는 Handler. 실제로 DB에서 조회된 데이터는 익명 handler → withContentSearch → withLimit 순서대로 역순으로 실행됩니다.

성능 체크

일단 Full Scan 기능을 붙여보니 현재 시스템 자원을 기준으로 약 30초동안 최대 80만개의 로그를 검색하는 속도가 측정되었습니다. 1분동안 최대 330만개의 로그가 수집되는 것을 고려할 때, 시간 범위를 1분으로 선택하면 약 2분(330만 / 80만 * 30초)의 시간이 걸린다는 것을 알게 됩니다. 색임 검색이 수억개의 데이터를 기준으로 0.5초가 걸리를 것을 고려할 때 매우매우 느린 속도라는 것을 알 수 있습니다. 뿐만 아니라 이 과정에서 Network 지표와 Disk IO 사용량이 다소 높게 측정되었습니다.

DFS 이해하기

검색 속도와 자원 최적화를 위해서는 우선 분산 파일 시스템(Distributed File System, 이하 DFS)의 구조를 알아야 합니다. 처리해야하는 데이터의 양이 하나의 서버에서 담당할 수 있는 수준이라면, 단일 검색 서버에서 트래픽을 소화합니다.

만약 하나의 서버에서 담당할 수 있는 수준 이상의 데이터가 수집되고 검색 요청이 들어오면 검색 서버의 역할을 DFS Client와 DFS Server 두 개로 나누어서 담당합니다. Cluster와 Node라는 이름으로 불리기도 하지만 단순하게 Client와 Server라고 부르겠습니다.

이 때 DFS Client와 DFS Server가 수행하는 역할은 아래와 같은 구조로 나누어져 있습니다.

• DFS Client
  • 로그 수집, 전처리, 파싱
  • 모든 처리가 끝난 로그를 DFS Server로 전달
  • 여러 개의 DFS Server에서 검색된 결과를 수신 및 정렬
• DFS Server
  • 로그 검색 및 저장

즉, 사용자의 검색 요청을 DFS Client에서 받아서 DFS Server로 전송하고, DFS Server에서 검색된 결과를 DFS Client가 취합해서 사용자에게 응답을 주는 형태입니다.

성능 체크 결과 이해하기

임시로 적용되었던 코드 조각 getFullScanHandler는 DFS Server가 아닌 DFS Client에 적용된 상태입니다.

두 개의 DFS Server에서 각각 1000개의 로그를 조회해도, 사용자가 입력한 키워드에 매칭되는 로그가 없거나 적다면(fetchLimit) DFS Server는 더 많은 로그를 계속해서 조회해야합니다. 이 과정에서 DFS Server의 DISK Iops가 스파이크를 치고, DFS Client ↔ DFS Server 사이 구간의 Network 지표도 스파이크를 치고, DFS Client는 더 많은 데이터에 대해서 contains 연산을 수행해야해서 CPU가 치는 상황이 발생했습니다.

Phase 2. getFullScanHandler의 위치를 DFS Server로 변경하기 , 약 456만개 / 30초

getFullScanHandler의 위치를 DFS Server로 변경해봤습니다.

Phase 1에서는 30초동안 최대 80만개의 데이터를 검색하는 것에 비해서, Phase 2에서는 30초동안 최대 456만건의 로그를 조회하는 성능이 측정되었습니다. 이 과정에서 DFS Server → DFS Client 구간의 네트워크 지표는 줄어들었고, 키워드 매칭되는 로그만 전송되는 것을 고려할 때 예상했던 결과였습니다. 검색 속도가 개선되면서 예상했던 것보다 더 많은 로그를 DB에서 조회하게 되고 (같은 단위 시간 30초 동안 80만개 → 432만개) 이로 인해서 DISK IOPS가 80~90% 가까이 스파이크를 치는 현상이 발생했습니다.

Phase 3. Scale Out (DFS Server 2대 → 4대), 약 1000만개 / 30초

DISK IOPS가 스파이크치는 현상과 관련해서 데브옵스팀과 논의를 해보니, 하나의 EC2에 할당할 수 있는 최대 DISK IOPS에 제한이 있어 Scale Up보다는 Scale Out의 전략이 더 적합해보인다는 의견을 받았습니다. 이론적으로 DFS Client 1대에 N 대의 DFS Server가 연결될 수 있는 구조로 되어 있기 때문에 추가적인 인프라를 설정하고 config를 지정한 다음 조건으로 테스트를 진행했습니다.

Phase 2에서는 30초동안 최대 456만개의 데이터를 검색하는 것에 비해서, Phase 3에서는 30초 동안 최대 1000만건의 로그를 조회하는 성능이 측정되었습니다. 그런데 Phase 2에서 언급했던 것과 동일한 이유로 여전히 Disk IO가 80 ~ 90%를 가까이 스파이크 치는 현상이 유지됐습니다.

조회 성능이 30초에 1000만건까지 나왔으므로, 10초동안 1분 최대 수집량인 330만건의 로그를 한 번에 조회할 수 있다는 계산이 나옵니다. 아래의 와탭 로그 모니터링 서비스를 보면, 1분당 조건에 매칭되는 로그의 수를 조회하면 동선을 사용합니다. 물론 아직 10초라는 시간 제약은 개선의 여지가 많이 필요하지만, Phase 1.에서 30초동안 최대 80만개를 조회했던 것과 비교하면 많이 개선이 되었습니다. Phase 3.까지 진행한 뒤 논의를 통해 고객의 요구사항을 1차적으로는 만족시킨 것으로 판단했습니다. 이제 자원 사용량 최적화를 진행해야 합니다.

Phase 4. Scale Up (DFS Server 2대 유지), 약 500만개 / 30초

Phase 3.에서 DFS Server 2대 → 4대의 Scale Out을 통해서 검색 속도의 개선이 많이 진행이 되었으니, DFS Server를 2대로 유지한 상태로 Scale Up을 하면 비슷한 효과가 나올 것이라는 기대를 가지고 Scale Up을 진행했습니다. 만약 2배 Scale Out과 2배 Scale Up이 모두 비슷한 효과를 가진다면, Scale Up을 진행하는 것이 운영 측면에서 관리 포인트가 덜 늘어나기 때문에 더 선호되는 방식으로 생각됐습니다.

하지만 Phase 2.에서 진행했던 검색 속도 약 456만개 /30초와 비교하면 거의 차이가 없는 수준으로 검색 속도 측정이 됐습니다. 한 가지 달라진 점은 Scale Up 이후에 DISK 사용량은 15% 전후로 매우 안정이 되었다는 점입니다. 여기서부터는 File Block Read에 대한 이해가 필요합니다.

Phase 5. Block Read Size 최적화

Phase3.의 Scale Out에서 검색 성능은 잘 나왔지만 DISK IOPS 최적화가 부족했던 점 그리고 Phase 4.에서 Scale Up을 했을 때에 유의미한 검색 속도의 개선이 진행되지 않은 점은 모두 File Block Read의 효율을 최대한으로 뽑아내지 못해서 발생한 문제였습니다.

File Block Read란

File을 기반으로 데이터베이스를 만들어서 사용하는 서비스의 특성상, 최대의 병목은 DISK IOPS에서 발생합니다. 그런데 이 DISK IOPS라는 지표는 파일에 한 번 접근할 때 몇 바이트를 읽는지보다는 DISK에 접근하는 횟수가 중요한 지표입니다.

https://www.whatap.io/ko/blog/41/

그래서 한 번에 파일을 읽을 때 딱 필요한만큼만 읽는 것이 아니라, “굵직굵직하게 미리 파일을 읽서 메모리에 올려두자”라는 접근 방법을 사용합니다. 파일에서 읽어야하는 위치가 filePos라면 한 번에 읽는 파일 블럭 사이즈를 사타내는 상수 BLOCK_SIZE를 계속 늘려보면서 DISK IOPS 지표에 개선이 보이는지 검증해보면 됩니다. 쉽게 말해서 “DISK IOPS가 가장 중요한 병목으로 작용하니, DISK IOPS보다 메모리를 더 사용하겠다” 라는 전략입니다.

파일에서 미리 읽어둔 데이터는 메모리에 올려두는데, idx = fileSize / BLOCK_SIE의 공식을 사용해서Map<idx, FileBlock>로 메모리에 올려두면 파일에 접근하지 않고 메모리에 이미 올라온 블럭에서 파일의 내용을 읽을 수 있습니다. BLOCK_SIZE가 커질수록 메모리 사용량이 늘어나고, 메모리에서 유지하는 BLOCK_COUNT가 커질수록 메모리 사용량이 늘어나는 구조입니다. DISK 성능 최적화를 위해서 BLOCK_SIZE를 늘릴 때에는 BLOCK 갯수를 확인해서 Block Read가 차지하는 최대 메모리 사용량을 확인하면서 늘려야합니다.

File Block Read 테스트

아래의 사진은 File Block의 사이즈를 조절하면서 진행할 때 작성한 표입니다. BLOCK_SIZE는 점점 늘어나고BLOCK_COUNT는 유지된 상태로 테스트를 하다보니 나중에는 Memory가 최대 6GB 잡혀있는 환경에서는 OOM이 발생했습니다. 이렇게 되며 제대로 된 테스트가 진행되지 못한 것입니다. JVM의 최대 메모리를 좀 더 지정하고 BLOCK_COUNT와 BLOCK_SIZE를 조절해가면서 어느 지점에서 가장 개선된 자원 사용량과 검색 속도가 나오는지 테스트해봐야 합니다.

JVM의 메모리를 6GB → 12GB로 늘리고(java -Xms4g -Xmx12g) BLOCK_SIZE, BlOCK_COUNT를 조절해본 결과입니다.

BLOCK_SIZE , BLOCK_COUNT는 128k / 3k에서 최적의 값이 도출되었습니다. 그런데도 여전히 Phase 3.에서 Scale Out 했을 때 나왔던 약 1000만개 / 30초의 성능은 안나옵니다. 이미 DISK IOPS가 15% 이기 때문에 DISK IOPS는 병목이 아니고, CPU 사용량이 꽤 높기 때문에 CPU를 한 세대 더 높은 인스턴스로 지정해봐야겠다고 판단했습니다.

Phase 6. Scale Up Up (DFS Server 2대 유지, i3en → i4i), 약 1000만개 / 30초

AWS의 정책에서 거의 모든 경우 새로운 세대의 인스턴스의 가격과 성능이 기존 세대보다 더 뛰어납니다. i3에서 i4 세대로 올렸더니 단순히 인프라 자원만으로 38%의 개선이 되었습니다. CPU 사용량도 많이 내려왔네요.

결론

임의의 키워드를 검색해야한다는 요구사항에 의해서 아래와 같은 참 많은 단계를 거쳐서 왔습니다. Full Scan을 해야한다는 기술적인 제약 덕분에 마음 불편하게 시작했지만 그래도 인프라와 애플리케이션 레벨 모두에서 개선을 많이 진행해서 기존(약 80만개 / 30초) 대비 10배(약 1000만개 / 30초)에 가까운 검색 속도를 제공하도록 개선되었습니다.

지난 11월에 작업했던 내용이라 자원 사용량에 관한 스크린샷이 하나밖에 남아있지 않네요. 네트워크가 스파이크를 찍었을 때는 배포가 이루어졌던 시점이고, 그 사이사이가 테스트가 이루어진 시점입니다. Full Scan 조회가 수행되어도 CPU ,Mem, DISK 지표가 모두 적당한 수준에서 유지되네요.

모니터링 서비스의 특성상, 에이전트는 많을 수 있지만 데이터를 조회하는 사람은 운영 담당자와 개발자뿐으로 절대 소수이기 때문에 이정도로 마무리될 수 있었다고 생각합니다. 정말 많은 분들의 도움을 받아서 진행된 내용이었는데 거인들의 어깨에 올라타서 IT 서비스의 고도화 과정의 중심에서 참 많은 것들을 배운 경험이었습니다.