소개
앱에서 평소보다 지연 시간이 길거나, 처리량이 낮거나, Java Datastore 클라이언트에서 시간 제한이 발생하는 경우 Firestore/Datastore 백엔드가 아닌 클라이언트 측 gRPC 구성에서 문제가 발생할 수 있습니다. 이 가이드는 일반적인 클라이언트 측 제한 문제, 잘못된 채널 풀 설정, 과도한 채널 변동을 진단하고 해결하는 데 도움이 됩니다.
진단
Java 클라이언트를 사용할 때는 채널 풀 동적 모니터링, 제한 진단, 연결 재사용 문제 또는 과도한 채널 변동 식별을 위해 자세한 gRPC 및 gax-java 로깅을 사용 설정하는 것이 중요합니다.
Java 클라이언트의 로깅 사용 설정
자세한 로깅을 사용 설정하려면 다음과 같이 logging.properties 파일을 수정합니다.
## This tracks the lifecycle events of each grpc channel
io.grpc.ChannelLogger.level=FINEST
## Tracks channel pool events(resizing, shrinking) from GAX level
com.google.api.gax.grpc.ChannelPool.level=FINEST
또한 logging.properties에서 출력 로깅 수준을 업데이트하여 이러한 로그를 캡처합니다.
# This could be changed to a file or other log output
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
구성 적용
logging.properties 파일은 다음 두 가지 방법 중 하나를 사용하여 적용할 수 있습니다.
1. JVM 시스템 속성을 통해
Java 애플리케이션을 시작할 때 다음 인수를 추가합니다.
-Djava.util.logging.config.file=/path/to/logging.properties
2. 프로그래매틱 방식으로 로드
이 메서드는 통합 테스트나 코드 내에서 로깅 구성이 관리되는 애플리케이션에 유용합니다. 이 코드가 애플리케이션 수명 주기 초기에 실행되는지 확인합니다.
LogManager logManager = LogManager.getLogManager();
try (final InputStream is = Main.class.getResourceAsStream("/logging.properties")) {
logManager.readConfiguration(is);
}
로깅 예시
상세 로깅을 사용 설정하면 com.google.api.gax.grpc.ChannelPool 및 io.grpc.ChannelLogger의 메시지가 혼합되어 표시됩니다.
채널 풀 확장을 트리거한 프로비저닝 부족 채널:
09:15:30.123 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6.
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering IDLE state
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering IDLE state
09:15:30.125 [grpc-nio-worker-ELG-1-5] TRACE io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] newCall() called
09:15:30.126 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:30.127 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<7>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}
09:15:31.201 [grpc-nio-worker-ELG-1-6] TRACE io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] newCall() called
09:15:31.202 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:31.203 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<8>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}
채널이 과도하게 프로비저닝되어 채널 풀이 축소됨:
09:13:59.609 [grpc-nio-worker-ELG-1-4] DEBUG io.grpc.ChannelLogger - [Channel<21>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<23>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}
09:14:01.998 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput drop to 0, shrinking channel pool size: 8 -> 6.
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Terminated
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Terminated
이러한 로그 항목은 다음의 경우에 유용합니다.
- 채널 크기 조절 결정 모니터링
- 채널 재사용과 Churn
- 전송 연결 문제 파악
증상 진단을 위한 로그 해석
높은 지연 시간이나 오류와 같은 성능 문제를 해결할 때는 com.google.api.gax.grpc.ChannelPool 및 io.grpc.ChannelLogger의 로깅을 사용 설정하는 것부터 시작하세요. 그런 다음 관찰한 증상을 이 가이드의 일반적인 시나리오와 일치시켜 로그를 해석하고 해결 방법을 찾습니다.
증상 1: 시작 시 또는 트래픽 급증 시 지연 시간 증가
애플리케이션이 시작된 후 처음 몇 개의 요청이 느리거나 트래픽이 갑자기 증가할 때마다 지연 시간이 급격히 증가할 수 있습니다.
가능한 원인
이 지연 시간은 채널 풀이 프로비저닝되지 않은 경우에 자주 발생합니다. 각 gRPC 채널은 제한된 수의 동시 요청 (Google 미들웨어에 의해 100개로 제한됨)을 처리할 수 있습니다. 이 한도에 도달하면 새 RPC가 클라이언트 측에서 대기열에 추가되어 사용 가능한 슬롯을 기다립니다. 이 대기열은 지연 시간의 기본 소스입니다.
채널 풀은 부하 변화에 적응하도록 설계되었지만 크기 조절 로직은 주기적으로 (기본적으로 매분) 실행되며 점진적으로 확장됩니다 (기본적으로 한 번에 최대 2개의 채널 추가). 따라서 초기 트래픽 급증과 풀 확산 사이에는 내재된 지연이 있습니다. 이 기간 동안 지연 시간이 발생하며, 이는 새 요청이 포화된 채널이 정리되거나 풀이 다음 크기 조절 주기에서 새 채널을 추가할 때까지 대기하기 때문입니다.
확인할 로그
채널 풀이 확장되고 있음을 나타내는 로그를 찾습니다. 이는 클라이언트가 현재 용량을 초과하는 트래픽 급증에 반응하고 있다는 기본 증거입니다.
채널 풀 확장 로그:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6.
해석: 풀에서 트래픽 급증을 감지하여 증가한 부하를 처리하기 위해 새 연결을 열고 있습니다. 특히 시작 근처에서 자주 확장되는 것은 초기 구성이 일반적인 워크로드에 충분하지 않다는 명확한 신호입니다.
해결 방법
목표는 트래픽이 도착하기 전에 충분한 채널을 준비하여 클라이언트가 압박을 받는 상황에서 채널을 만들지 않도록 하는 것입니다.
initialChannelCount 증가 (시작 시 지연 시간 높음):
시작 시 지연 시간이 길면 ChannelPoolSettings에서 initialChannelCount를 늘리는 것이 가장 효과적인 해결책입니다. 기본적으로 이 값은 10으로 설정되어 있으며, 이는 시작 시 상당한 트래픽을 처리하는 애플리케이션에는 너무 낮을 수 있습니다.
애플리케이션에 적합한 값을 찾으려면 다음 단계를 따르세요.
com.google.api.gax.grpc.ChannelPool에FINEST수준 로깅을 사용 설정합니다.- 일반적인 시작 워크로드 또는 트래픽 급증 상황에서 애플리케이션을 실행합니다.
- 채널 풀 확장 로그를 관찰하여 풀이 안정화되는 크기를 확인합니다.
예를 들어 다음과 같은 로그가 표시되는 경우
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 80, expanding channel pool size: 4 -> 6.
1분 후 다음과 같은 로그가 표시됩니다.
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 95, expanding channel pool size: 6 -> 8.
확장된 채널 풀 크기가 8개 채널로 안정화되고 더 이상 확장 로그를 찾을 수 없는 경우 애플리케이션이 워크로드를 처리하는 데 8개 채널이 필요했음을 나타냅니다. initialChannelCount를 8로 설정하는 것이 좋습니다. 이렇게 하면 연결이 미리 설정되어 즉석 확장으로 인한 지연 시간이 줄어들거나 제거됩니다.
목표는 요청을 대기열에 추가하지 않고 최대 부하를 처리할 수 있는 충분한 용량을 풀에 확보하는 것입니다.
minChannelCount 증가 (트래픽 급증):
트래픽 급증이 시작될 때 특히 지연 시간이 길어지면 채널 풀이 새 연결을 반응적으로 생성하는 것보다 트래픽이 더 빠르게 증가하고 있다는 신호입니다. 이는 예측 가능하고 갑작스러운 트래픽 급증이 있는 애플리케이션에 일반적입니다.
풀은 일반 트래픽 중에 소수의 채널로 안정화되고 트래픽이 증가하면 포화를 방지하기 위해 더 많은 채널을 사전에 추가합니다. 이 확장 프로세스에는 시간이 걸리므로 버스트의 초기 요청이 대기열에 추가되어 지연 시간이 길어집니다.
minChannelCount를 늘리면 영구적으로 열린 채널의 기준이 높아집니다. 이렇게 하면 초기 버스트를 처리할 수 있는 충분한 용량이 이미 확보되므로 확장 지연과 관련 지연 시간 급증이 발생하지 않습니다.
maxChannelCount 증가 (트래픽 급증):
트래픽 급증 시 지연 시간이 높고 로그에 채널 풀이 지속적으로 최대 크기 (maxChannelCount)로 표시되면 현재 한도가 최대 트래픽에 비해 너무 낮은 것일 수 있습니다. 기본적으로 maxChannelCount는 200으로 설정됩니다. 더 나은 값을 확인하려면 연결 풀 구성 가이드를 사용하여 애플리케이션의 최대 초당 쿼리 수 (QPS)와 평균 요청 지연 시간을 기반으로 최적의 연결 수를 계산하세요.
증상 2: 간헐적인 제한 시간 또는 RPC 실패
애플리케이션이 대부분의 시간 동안 정상적으로 실행되지만 정상 트래픽 기간에도 간헐적인 시간 초과 또는 RPC 실패가 발생하는 경우가 있습니다.
가능한 원인: 네트워크 불안정
클라이언트와 Datastore 서비스 간의 연결이 끊어집니다. gRPC 클라이언트는 자동으로 다시 연결을 시도하지만 이 프로세스로 인해 일시적인 오류와 지연 시간이 발생할 수 있습니다.
확인할 로그
네트워크 문제를 진단하는 데 가장 중요한 로그는 TRANSIENT_FAILURE입니다.
- 일시적 오류 로그:
[grpc-nio-worker-ELG-1-7] DEBUG io.grpc.ChannelLogger - [Channel<9>: (datastore.googleapis.com:443)] Entering TRANSIENT_FAILURE state
- 해석: 이 로그는 채널의 연결이 끊어졌음을 나타내는 심각한 경고입니다. 단일 고립된 장애는 사소한 네트워크 문제일 수 있습니다. 하지만 이러한 메시지가 자주 표시되거나 채널이 이 상태로 멈춰 있다면 근본적인 심각한 문제가 있는 것입니다.
해결 방법
네트워크 환경 조사하기 애플리케이션과 datastore.googleapis.com 간의 방화벽, 프록시, 라우터 또는 일반적인 네트워크 불안정성 문제를 확인합니다.
증상 3: 클라이언트당 동시 요청이 20,000개를 초과하는 경우 지연 시간이 김
이 특정 증상은 매우 높은 규모로 실행되는 애플리케이션에 적용됩니다. 일반적으로 단일 클라이언트 인스턴스가 20,000개가 넘는 동시 요청을 처리해야 하는 경우에 해당합니다. 애플리케이션은 정상적인 조건에서는 잘 작동하지만 트래픽이 클라이언트당 20,000개가 넘는 동시 요청으로 증가하면 성능이 급격하게 저하됩니다. 지연 시간이 크게 증가하고 트래픽이 가장 많은 기간 내내 높은 상태를 유지합니다. 이는 클라이언트의 연결 풀이 최대 크기에 도달하여 더 이상 확장할 수 없기 때문에 발생합니다.
가능한 원인
채널 풀이 구성된 maxChannelCount에 도달하여 클라이언트가 채널 포화 상태를 겪고 있습니다. 기본적으로 풀은 채널 200개로 제한되도록 구성됩니다. 각 gRPC 채널은 최대 100개의 동시 요청을 처리할 수 있으므로 단일 클라이언트 인스턴스가 동시에 약 20,000개의 요청을 처리하는 경우에만 이 한도에 도달합니다.
풀이 이 한도에 도달하면 더 이상 연결을 만들 수 없습니다. 200개 채널이 모두 과부하되고 새 요청이 클라이언트 측에 대기열에 추가되어 지연 시간이 급격히 증가합니다.
다음 로그는 maxChannelCount에 도달했는지 확인하는 데 도움이 됩니다.
확인할 로그
핵심 지표는 부하가 계속되더라도 채널 풀이 구성된 한도에서 바로 확장되지 않는다는 점입니다.
- 로그: 풀이 확장된 이전 로그가 표시됩니다. 기본 설정에서는 지연 시간이 급증하기 전에 표시되는 마지막 확장 로그가 풀이 200개 채널에 도달하는 로그입니다.
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - ... expanding channel pool size: 198 -> 200.
- 표시기: 지연 시간이 긴 기간에는 '채널 풀 크기 확장' 로그가 더 이상 표시되지 않습니다. 이러한 로그가 없고 지연 시간이 길면
maxChannelCount한도에 도달했음을 나타내는 강력한 지표입니다.
해결 방법
목표는 요청을 대기열에 추가하지 않고 최대 부하를 처리할 수 있는 충분한 용량을 풀에 확보하는 것입니다.
maxChannelCount늘리기: 기본 솔루션은 애플리케이션의 최대 트래픽을 지원할 수 있는 값으로maxChannelCount설정을 늘리는 것입니다. 연결 풀 구성 가이드를 참고하여 애플리케이션의 최대 초당 쿼리 수 (QPS)와 평균 요청 지연 시간을 기준으로 최적의 연결 수를 계산합니다.
부록
다음 섹션에서는 문제 해결에 도움이 되는 추가 정보를 제공합니다.
채널 상태 이해하기
로그에 다음 채널 상태가 표시되어 연결 동작에 관한 유용한 정보를 제공할 수 있습니다.
| 주 | 설명 |
|---|---|
| IDLE | 채널이 생성되었지만 활성 연결이나 RPC가 없습니다. 트래픽을 기다리는 중입니다. |
| 연결 중 | 채널이 gRPC 서버에 대한 새 네트워크 전송 (연결)을 설정하려고 적극적으로 시도하고 있습니다. |
| READY | 채널에 안정적이고 정상적인 전송이 설정되어 있으며 RPC를 전송할 준비가 되었습니다. |
| TRANSIENT_FAILURE | 채널에 복구 가능한 장애 (예: 네트워크 문제, 일시적인 서버 사용 불가)가 발생했습니다. 자동으로 다시 연결을 시도합니다. |
| SHUTDOWN | 채널이 수동으로 (예: shutdown()가 호출되었거나 유휴 상태 제한 시간으로 인해 새 RPC를 시작할 수 없습니다. |
팁
- SLF4J 또는 Logback과 같은 구조화된 로깅 프레임워크를 사용하는 경우
logback.xml또는 기타 로거 구성 파일에서 상응하는 로그 수준을 구성해야 합니다.java.util.logging수준은 로깅 파사드에 의해 매핑됩니다.