JAVA 애플리케이션 성능 모니터링 (폐쇄망 온프레미스 환경)

250x250

Notice

Recent Posts

Recent Comments

Link

« 2024/11 »
일	월	화	수	목	금	토
					1	2
3	4	5	6	7	8	9
10	11	12	13	14	15	16
17	18	19	20	21	22	23
24	25	26	27	28	29	30

Tags more

Archives

Today

Total

관리 메뉴

매일 조금씩

JAVA 애플리케이션 성능 모니터링 (폐쇄망 온프레미스 환경) 본문

기타

JAVA 애플리케이션 성능 모니터링 (폐쇄망 온프레미스 환경)

mezo 2024. 10. 14. 21:36

728x90

“__매주 월요일 오전9-10시 쯤,

서비스를 사용하는 거의 모든 사용자가 화이트 아웃이 발생하거나 켜지기까지 10초 이상 소요된다”

는 이슈가 있었다.

네트워크 탭을 확인해보니 특정 서비스가 타임아웃이 걸리거나 서비스 실패하는 것이 확인되었다.

그러나 이것만 보고는 이 서비스에 문제가 있다고 단정짓기는 어렵다.
네트워크 환경, 서버 리소스, 의존성 문제 등 여러 가능성을 종합적으로 분석하여야 정확한 원인을 파악할 수 있다.

[서버 스펙]
- CPU: 12 cores
- mem: 16 Gi (17.2 GB)
replica 수 : 3

[목차]

가설
예상 원인
원인 파악 과정
요약
결론

가설

가설 1. 네트워크 환경 문제라면?

네트워크 문제는 특정 시간대나 특정 서비스에 국한되지 않고 전반적인 네트워크 상태에 따라 불규칙하게 발생하는 경우가 많다.

그러나 여기선 다른 서비스나 시간대는 문제가 없지만 특정 시간대(사용자가 몰리는 시간), 거의 모든 사용자에게 동일한 에러가 발생하는 것으로 봐서 네트워크 문제보다는 서버 리소스 또는 애플리케이션 설정 및 로직 문제가 더 가능성이 높아 보인다.

가설2. 서버 리소스 문제라면?

그라파나로 CPU, 메모리, 디스크 I/O, 네트워크 사용량을 모니터링해 보았다. 나머진 문제없지만 메모리 사용량이 이슈가 있는 시간대에 갑자기 급증하여 줄어들지 않는 것을 확인했다.

가설3. 애플리케이션 설정 및 로직 문제라면?

스레드 풀 사이즈는 적정량으로 설정되어 있었다. 설정 문제보단 쿼리나 로직 혹은 처리하는 데이터 양의 문제일 가능성이 커보인다.

예상 원인

그렇다면 예상 되는 원인은 크게 두가지이다.

메모리 누수 *** GC 로그, 힙 덤프 모니터링 필요
- 메모리 고갈 → GC 과부하(GC 실행시간 증가로 자원 소모 많음) → 자원부족으로 요청 처리 지연 → 타임아웃
- 위 과정을 통해 서비스 성능 저하와 타임아웃을 유발
애플리케이션 성능 문제 *** 애플리케이션 로그 모니터링으로 서비스 특정 필요
- 쿼리 성능 문제
  - 쿼리 성능이 낮아 메모리를 많이 소모하면서 오랜 시간 실행되는 경우, 스레드가 쿼리 실행 대기 상태에 들어가며 스레드 풀이 고갈될 수 있다. 이로 인해 새로운 요청을 받을 스레드가 부족해져 타임아웃이 발생할 수 있다.
  - 만약 특정 쿼리 하나가 과도한 CPU와 메모리를 점유하고, 다른 쿼리와의 경합이 발생하여 전체 서비스 응답이 느려진다면, 타임아웃 문제가 나타날 수 있다.
- 서비스 내 특정 로직의 실행 속도 문제
  - 서비스 자체의 로직이 복잡하거나 대용량 데이터를 처리하고 있다면, 응답 속도가 느려지면서 메모리 사용량이 증가할 수 있다. 이러한 문제는 결국 서비스 지연을 유발하고, 요청이 처리되지 않으면서 타임아웃이 발생할 수 있다.

원인 파악 과정

1) GC 로그 수집 및 모니터링

목적: GC 활동과 메모리 회수 상태를 초기 단계에서부터 확인하여 메모리 누수 여부를 감지.

폐쇄망에서도 VisualVM, MAT, jstat 등 오프라인으로 동작 가능한 도구는 사용할 수 있다.
다만, 인터넷 연결 없이 사용할 수 있도록 초기 설치와 설정을 온프레미스 환경에 맞췄다.

GC 로그를 주기적으로 수집하여 분석할 수 있도록 JAVA_OPTS에 로그 설정을 추가할 수 있다.

스크립트 예시)

#!/bin/bash

# GC 로그를 저장할 경로 설정
LOG_DIR="/path/to/logs"
GC_LOG_FILE="$LOG_DIR/gc.log"

# JVM 옵션 설정: GC 로그 기록 및 파일 크기와 순환 설정
JAVA_OPTS="-Xloggc:$GC_LOG_FILE -XX:+PrintGCDetails -XX:+PrintGCDateStamps"
JAVA_OPTS="$JAVA_OPTS -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=50 -XX:GCLogFileSize=50M"

# Java 애플리케이션 실행 (예: Spring Boot 애플리케이션)
java $JAVA_OPTS -jar /path/to/yourapp.jar

위 스크립트를 실행하면, GC 로그가 gc.log 파일에 저장되고, 최대 파일 크기가 50MB를 넘으면 최대 50개까지 순환하며 보관한다.

그 이후에 생성되는 로그파일은 처음 로그파일에 덮어씌워진다.

이때 파드가 3개로 분산되어있어서 각 파드당 로그 저장 디렉토리를 분리하였다.

왜 filecount = 50, filesize = 50m??

이전 GC 1시간 모니터링시 Young GC가 약 3-4분에 1번 정도로 일어난 것을 확인
로컬에서 테스트 결과 Young GC 한번 당 약 1.5kb의 로그 생성
위의 정보로 로그가 쌓이는 속도를 1.5kb/3m = 43mb/1day 로 추정
pod별 용량을 화인했을 때, 750G의 여유용량이 있는 것을 확인
추정치로 계산했을 때, 2달 정도의 로그를 보관할 수 있는 2.5G로 total 용량을 산정하고 PS팀과 확인 후 적용

Minor gc가 불규칙적으로 발생했으나, 이는 에덴 영역이 꽉차면 발생하므로 자연스럽다.

또한, 일정하게 빈번한 gc가 발생하지 않으므로, 메모리 누수는 없는 것으로 보인다.

Minor GC 빈도가 일정하지 않은데 메모리 누수 발생 근거로 볼수 있을까?

메모리 누수는 GC가 발생해도 메모리가 회수되지 않는 패턴을 보이며, 결국 Old Generation 메모리가 지속적으로 증가하여 Full GC가 빈번하게 발생하게 됨.
- 그러나 여기서는 Minor GC가 갑작스럽게 빈번해지지 않았으므로, 지속적인 메모리 누수 증상과는 차이가 있음.
- Minor GC가 발생하더라도 Old Generation 메모리 사용량이 크게 변화하지 않고 일정하게 유지된다면, 메모리 누수보다는 일시적인 메모리 사용량 급증 문제일 가능성이 큼.

특정 시간대의 메모리 증가는 메모리 누수가 아니면 뭘까?

서비스 타임아웃이 발생하는 시간대에 메모리를 많이 소모하는 작업(대량 데이터 로드, 특정 API 호출 등)이 있는지 확인해야함.
- 이 경우, 메모리 최적화, 캐싱 활용, 데이터 로드 방식을 최적화하는 방식으로 문제를 해결할 수 있음.

서비스 요청이 집중되거나 특정 기능에서 메모리를 많이 소비하는 현상일 가능성이 높다고 판단하였다.

메모리를 과도하게 사용하게되면,

GC 빈도가 증가하고, 빈번한 GC가 실행되는 동안 스레드는 멈춰 있기 때문에,

스레드는 대기 상태에 들어가고 스레드 풀이 고갈된다.

이는 서비스 타임아웃 또는 서비스 실패로 이어진다.

따라서, pmap, jmap, jstat으로 자바 프로세스 메모리 사용량을 비교하고,

추가적으로 jmap으로 힙덤프를 따서 객체당 할당된 메모리 주소를 비교하여 jvm내의 힙 메모리 영역이 맞는지 확인하고!

이 과정에서 메모리를 과도하게 사용하는 서비스를 찾아 최적화하도록 방향을 잡았다.

2) pmap으로 프로세스 메모리 확인

목적: Java 프로세스가 사용하는 메모리 맵을 확인하여, 메모리 누수 의심 영역 파악.

# pmap -x <pid>
pmap -x 1

Address 0000000082000000 ~ 00000007bf800000 (0x7bf800000 - 0x82000000) 에서 약 30G의 물리 메모리를 잡고 있었다.
Heap Dump를 떠서 해당 메모리 주소를 확인해 봐야 정확하겠지만 지금은 이 해당 메모리 구간이 JVM Heap으로 예상된다.
- 하지만 동시간 JVM Heap status를 jmap -heap {pid} 로 보았을 때 30G 만큼 쓰고 있지 않았고 Eden Space가 꽉차는 것을 고려해도 30G에 훨씬 못미침. (jmap으로 힘덤프 따야함)
- 따라서 실제로 차지하는 30G 와 jvm heap status와의 간극에 대해서는 알아볼 필요가 있음.

그라파나 상으로 메모리가 많이 잡히는 때에 실행시켜 확인한 결과,

약 30GiB 에 해당하는 메모리가 특정 구간에 할당되어 있음.

pmap, jmap, jstat에서 출력되는 메모리 사용량의 차이는?

pmap 은 운영체제 전체 관점에서 프로세스의 메모리 사용량을 보여주며, JVM 외부의 메모리까지 포함한다.
jmap 은 JVM 내부 힙 메모리 상태 및 덤프를 생성하여 분석하는데 사용된다.
jstat 은 JVM의 실시간 메모리 및 성능 상태를 모니터링하는 데 유용하다.

3) 힙 덤프 생성 및 분석

목적: 메모리 누수가 의심되는 객체와 참조 경로를 추적하여 메모리 누수 원인을 구체적으로 파악.

jmap 명령어로 특정 PID에 대해 힙 덤프 파일을 생성하고,
파일을 보안 절차에 따라 로컬 PC로 옮긴 후 MAT 또는 VisualVM으로 분석한다.
덤프 파일이 클 경우, 필요한 정보만 선택적으로 추출하여 전송할 수 있다.

실사용 메모리양을 프로메테우스로 수집할 수 있게 그라파나에 템플릿을 추가해서 봐도 되지만,

해당 jar에 프로메테우스 의존성이 없어서 새로 패치가 나가야하므로.. 힙덤프를 사용하기로 했다.

스크립트 예시)

#!/bin/bash

# Java 프로세스 ID 설정 (예: Java 애플리케이션 PID)
JAVA_PID=1

# 힙 덤프를 저장할 경로
DUMP_DIR="/path/to/dump"
DUMP_FILE="${DUMP_DIR}/heapdump_$(date +%Y%m%d%H%M%S).hprof"

# 힙 덤프 생성
echo "Generating heap dump for PID $JAVA_PID..."
jmap -dump:format=b,file=$DUMP_FILE $JAVA_PID

# 힙 덤프 생성 완료 메시지
echo "Heap dump saved to $DUMP_FILE"

해당 스크립트로 저장된 덤프 파일을 Eclipse Memory Analyzer Tool(MAT) 로 열어서 메모리 누수 의심 객체를 확인할 수 있다.

Java 프로세스 메모리를 확인했을 때 확인된 약 30GiB의 메모리 구간(0x7bf800000 - 0x82000000)이
Heap Dump의 메모리 주소 확인을 통해 JVM Heap 구간임을 확인.

그러나 힙 덤프를 지속적으로 따서 확인했을 때 실 사용 메모리양이 이상했다.

cat /proc/{pid}/status로 확인한 Java process 메모리 사용량과 pmap -x {pid}으로 자바 프로세스 메모리 주소까지 확인했을 땐, 운영체제관점에서 특정 프로세스의 메모리 사용량을 보기때문에, Heap이 30GiB를 점유하고 있다고 나왔는데..

jmap의 해당 프로세스 메모리 사용량과 jstat로 확인한 실시간 메모리 사용량 JVM Heap Status 둘 다에서, 이에 훨씬 미치지 못하는 최대 15GiB, 평균 10GiB 정도의 Usage를 계속 보여주고 있었다.

따라서, 그라파나에서 보이는 메모리가 증가해서 영원히 내려오지 않는 것은 메모리 누수가 아닌..

JVM이 Heap 메모리를 OS에 반환하지 않는 것이 아닌가에 대한 추정을 해보았다.

4) JVM이 OS에 Memory를 반환할까?

JEP 346: Promptly Return Unused Committed Memory from G1

JEP 346: Promptly Return Unused Committed Memory from G1 AuthorsRodrigo Bruno, Thomas Schatzl, Ruslan SynytskyOwnerThomas SchatzlTypeFeatureScopeImplementationStatusClosed / DeliveredRelease12Componenthotspot / gcDiscussionhotspot dash gc dash dev

openjdk.org

위의 내용은 Java Enhancement Proposal(JEP)의 내용으로 JVM이 점유했지만

사용하지 않는 Heap 메모리에 대해 OS에 반환하지 않는 이슈에 대한 해결을 제안한다.

이는 Java12 에서 해결 되어 Release 됐다고 한다.

Java12 부터는 ~

JVM이 메모리 반환을 더 효율적으로 하도록 개선되었다.
- G1 GC가 개선되어, 가비지 컬렉션 후 사용하지 않는 메모리를 OS에 보다 적극적으로 반환할 수 있는 기능이 추가되었다.
- 이 기능은 특히 애플리케이션이 메모리 사용량이 급격히 증가했다가 감소하는 경우에 유용하며, 메모리 반환 효율이 크게 향상되었다.

이로 미루어 보았을 때,

특정 시점의 메모리 사용량의 증가로 JVM이 Max Heap 까지 메모리를 점유했지만,

이후 메모리 사용량이 급감한 상태로 지속되어도 메모리를 OS에 반환하지 않았을 것이다.

지금 까지 GC 로그, Java 프로세스 메모리, 힙 덤프 를 분석 및 모니터링한 결과..
메모리 누수는 없는 걸로 확정이다.

그럼 남은 예상 원인은 서비스 로직이나 쿼리의 성능 문제이다.
지금부터, 어떤 서비스의 성능 문제인지 서비스를 특정해야한다.

5) Python 로그 모니터링

목적: 힙덤프로 메모리를 많이 잡는 객체들은 알았으나 어느 서비스의 객체인지 모르기 때문에, 수집된 로그에서 메모리 사용 패턴을 실시간으로 분석하여 메모리를 많이 잡는 서비스를 특정.

Python 스크립트를 써야하는 이유는?

현재 사업건 환경은 폐쇄망이라서 APM 도구를 사용할 수 없다.

Why ???

apm 도구들은 New Relic, AppDynamics, Dynatrace 등이 있는데,
얘네는 대부분 클라우드 기반 서비스 형태로 운영되어 대시보드를 통해 사용자가 언제든 서버의 상태를 확인할 수 있도록 하기때문..
다음과 같이 동작한다.

에이전트 설치: 서버에 APM 에이전트를 설치하여 애플리케이션의 성능 데이터를 수집함.
데이터 전송: 수집된 데이터를 APM의 클라우드 서버로 전송함.
웹 대시보드 제공: APM의 웹사이트나 클라우드 콘솔에서 데이터를 시각화하고, 실시간 모니터링 기능을 제공.

따라서, 일종의 1번 동작과 비슷한 동작을 직접 파이썬 스크립트로 짜서 로그파일을 받아 로컬에서 돌리도록 한다.

스크립트를 돌리기 위해선.

파이썬이 설치된 환경이어야 하고, tabulate, matplotlib같은 시각화 라이브러리가 없다면 설치해야 한다.

re 라이브러리를 사용해 메모리 사용량, 서비스명, 타임스탬프 등을 추출하고,

Pandas 라이브러리를 통해 데이터 프레임으로 정리할 수 있다.

# Python 설치
apt update
apt install -y python3 python3-pip
# 시각화 라이브러리 설치
pip3 install pandas

파이썬 스크립트엔

어떤 로그파일을 분석할거고 (로그파일 명)
어떻게 분석할거고 (메모리 사용량을 추출)
분석된 결과를 어떻게 보여줄건지 (표로 시각화 하기로함)

도 포함되어 있어야한다.

총 3개의 로그 분석 스크립트 개발한다.

모든 API 호출을 걸린 시간 순으로 나열해서 보여주는 스크립트
- Spring Application 로그 활용
시간 시간 ~ 끝 시간 사이에 요청된 API들의 집계 정보를 보여주는 스크립트
- 호출 횟수, 총 걸린 시간, 가장 오래 걸린 요청의 시간, 가장 짧게 걸린 요청의 시간, 평균처리 시간, 가장 길게 걸렸을 때의 시간
- Spring Application 로그 활용
Heap 내의 각 영역 및 최대 할당 가능 용량의 값을 시간에 따른 그래프로 보여주는 스크립트
- jstat -gc 명령어의 로그를 활용

스크립트 예시)

import re
import pandas as pd
from datetime import datetime

# 로그 파일 경로 설정
log_file_path = "gc.log"

# 시간 및 메모리 사용량을 저장할 리스트
timestamps = []
memory_usage = []

# 로그 파일 열기 및 패턴 분석
with open(log_file_path, "r") as file:
    for line in file:
        # GC 로그에서 시간과 메모리 사용량 추출 (로그 형식에 맞게 패턴 수정)
        match = re.search(r"(\d+-\d+-\d+T\d+:\d+:\d+).*?(\d+)K->(\d+)K", line)
        if match:
            timestamp = datetime.strptime(match.group(1), "%Y-%m-%dT%H:%M:%S")
            before_gc = int(match.group(2))
            after_gc = int(match.group(3))

            # 시간과 메모리 사용량 변화 저장
            timestamps.append(timestamp)
            memory_usage.append(before_gc - after_gc)

# 데이터프레임 생성
df = pd.DataFrame({
    "Timestamp": timestamps,
    "Memory Reclaimed (KB)": memory_usage
})

# 데이터프레임의 상위 5개 행만 출력
print(df.head())

해당 파이썬 스크립트를 로그 파일과 동일한 경로에 두고 명령어 실행한다.

# 스크립트 실행
python gc_log_analysis.py

그러면 분석 결과가 다음과 같이 시각화되어 출력된다. (표는 tabulate 사용)

해당 시간대에 가장 많은 시간, 메모리를 잡는 요청을 찾음 - MemberController.findAllMember

그 결과, 위와 같이 findAllMember 라는 서비스가 콜 될때 메모리 사용이 급증하는 것으로 출력되었다.

그렇다면 findAllMember 서비스를 최적화해야 한다..
findAllMember 서비스는 룸리스트에서 룸에 진입하면 룸의 모든 멤버들의 정보(닉네임, 프로필사진 등)를 조회하는 서비스이다.

왜? 굳이? 한번에 다? 라는 의문이 들것이다...

나도 그렇다!

Ehcache 라이브러리로 캐싱이 되어 있지만.. 화면상으로 진짜 필요한 멤버들의 정보만 조회해도 된다고 생각한다.
룸의 멤버가 최대 300명인데.. 아마 이 서비스가 대량 데이터를 로드하는 것도 서비스 성능저하 원인 중 하나인 것 같다.

요약

트래픽이 몰리는 시간에 거의 모든 사용자가 서비스 타임아웃, 실패 에러를 겪음.
그라파나 리소스 모니터링으로 해당 시간에 사용 메모리가 급격히 증가 후, 영원히 떨어지지 않는 것을 확인.
GC 로그 수집, 분석 후, 메모리 누수는 없다고 거의 단정 지음.
Java 프로세스 메모리, 힙 덤프를 확인해봄.
이슈 시간에 메모리 사용이 급격히 증가하는 것은 맞지만, 이후엔 반이상의 메모리가 OS에 반환안되고 계속 놀고 있음을 확인.
이는 JVM이 OS에 GC후 메모리 반환을 하지 않고 있고, 이는 JAVA11 의 G1 GC의 이슈인 것으로 확인.
이슈 시간에 메모리 사용이 급격히 증가하는 것만 잡으면 됨. 이는 서비스 성능 문제임.
로그 분석 툴을 사용하여 메모리를 많이 잡아먹는 서비스를 특정함.
해당 서비스의 조회 쿼리 개선, 복잡한 로직 개선, 데이터 분할 등 성능 개선 포인트 탐색 중.

결론

동시간대에 거의 모든 사용자가 동일한 에러를 겪는다면 서버 리소스 혹은 애플리케이션 설정 혹은 로직 이슈일 가능성이 높다.
서버 리소스 충분하고, 메모리 누수 없고, 애플리케이션 설정도 적정량이라면, 서비스를 최적화 해야 한다.
서비스 최적화는 다음과 같은 방법들이 있다.
- 테이블 인덱스 추가, JOIN, 서브쿼리 최적화.
- 특정 쿼리가 대용량 데이터를 반환할 경우, 페이징 처리나 데이터 분할로 쿼리당 처리하는 데이터 양 줄이기.
- 오래 걸리는 쿼리나 특정 작업을 비동기로 전환하여, 이후 결과를 별도 스레드로 처리하게 처리.
- 캐싱 (이미 되어있음)
JAVA11는 G1 GC 문제로 JVM이 OS에 메모리를 반환하지 않는 이슈가 있고, 이는 JAVA12부터 해결되었다.

[추가로 알아볼 것들]

JVM의 메모리 관리 정책
G1 GC 튜닝 옵션 - 메모리 급증 시 GC 효율을 높이기 위해, 메모리 반환 속도와 효율을 조절하는 법
'Grafana + 메트릭 수집 도구(Prometheus)'로 '실사용 메모리양'을 모니터링 할순 없을까?
- JVM Exporter가 기본적으로 수집하는 메트릭이 jvm_memory_committed_bytes 와 같은 할당된 메모리 메트릭일 가능성이 높다. 이 경우 실제 사용 메모리(jvm_memory_used_bytes)를 따로 지정해야 정확한 사용량을 확인할 수 있다.
- 해결 방법
  - Prometheus 설정에서 jvm_memory_used_bytes 메트릭을 통해 현재 사용 중인 메모리 양을 수집하도록 추가하면, Grafana 대시보드에서 이 메트릭을 활용해 실사용 메모리를 시각화할 수 있다.
  - 사용자 정의 대시보드를 구성하여, jvm_memory_used_bytes와 jvm_memory_committed_bytes를 동시에 비교하도록 설정하면, 실제 메모리 사용 패턴을 파악할 수있다.
  - 가장 쉽게 그라파나에서 제공하는 템플릿을 사용할 수도 있다.
다양한 캐싱 전략

728x90

저작자표시

매일 조금씩

JAVA 애플리케이션 성능 모니터링 (폐쇄망 온프레미스 환경) 본문

JAVA 애플리케이션 성능 모니터링 (폐쇄망 온프레미스 환경)

가설

예상 원인

원인 파악 과정

1) GC 로그 수집 및 모니터링

2) pmap으로 프로세스 메모리 확인

3) 힙 덤프 생성 및 분석

4) JVM이 OS에 Memory를 반환할까?

5) Python 로그 모니터링

요약

결론

티스토리툴바