Slow And Steady Wins The Race

출처 : https://bamdule.tistory.com/51

Entity에 다른 entity와 lazy loaded relationship이 있을 경우 hibernateLazyInitializer가 아래와 같이 포함된다.

"xx": {
        "id": 1,
        "hibernateLazyInitializer": {}
}

참조. https://stackoverflow.com/questions/18470438/exception-thrown-when-serializing-hibernate-object-to-json

When Hibernate loads objects from the DB, 
it returns proxied objects which look like your Advertisment or SessionT 
but have more "stuff" in them (to handle their relationship to the session, 
the internal state of lazy loaded collections etc.).

This throws off the Jackson serializer since it relies on introspection to find our the properties of the objects.

이때 jackson.serialization.FAIL_ON_EMPTY_BEANS가 true로 되어 있다면 에러가 발생한다.

No serializer found for class org.hibernate.proxy.pojo.bytebuddy.ByteBuddyInterceptor and no properties discovered to create BeanSerializer (to avoid exception, disable SerializationFeature.FAIL_ON_EMPTY_BEANS)

hibernateLazyInitializer를 무시한다던지 jackson.serialization.FAIL_ON_EMPTY_BEANS를 false로 설정하여 에러를 제거하는 방법도 있지만 근본적인 문제에 대해서 살펴보자.

Entity를 API에 노출하는 것이 과연 옳은 것일까?

한가지 장점이 있다. 매우 편하다..

하지만 그로인해 발생할 수 있는 문제점이 무엇이 있을까?

- 프레젠테이션 계층을 위한 로직이 Entity에 지속적으로 추가된다.(with @Transient)

고객이 항상 하는 이야기가 있다. 이것 추가해주세요.. 저것도 추가해주세요.. 

- API 검증을 위한 로직이 Entity에 지속적으로 추가된다.(@NotNull 등)

- 하나의 Entity가 다양한 API의 요구사항을 담기 어렵다.

- Entity가 변경되면 API도 변경되어야한다. 

결론은 프레젠테이션 영역으로 부터 전달받는 Request,
프레젠테이션으로 전달하는 Response를 따로 정의하자.

- https://stackoverflow.com/questions/18470438/exception-thrown-when-serializing-hibernate-object-to-json

프로젝트에서 Redis를 사용하면서 겪게 되었던 문제와 해결방안에 대해서 정리하고자한다.

가끔씩 Spring boot으로 개발한 API 서버에서 응답을 지나치게 늦게 주는 경우가 있다. 

Redis가 API 서버와 무슨 관련이 있을까? 하고 이야기할 수 있다.

API Server의 세션관리를 Redis로 하고 있었고, 이때 Redis client(lettuce)가 정상 동작하지 않았다.

관련 로그는 아래와 같다.

RedisCommandTimeoutException

io.lettuce.core.RedisCommandTimeoutException: Command timed out after 1 minute(s)
at io.lettuce.core.ExceptionFactory.createTimeoutException(ExceptionFactory.java:51)
at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:114)
at io.lettuce.core.FutureSyncInvocationHandler.handleInvocation(FutureSyncInvocationHandler.java:69)
at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80)
at com.sun.proxy.$Proxy94.set(Unknown Source)

위 예외에 대해서 lettuce 공식 사이트의 Frequently Asked Questions에 아래와 같이 설명하고 있다.

Diagnosis:

1. Check the debug log (log level DEBUG or TRACE for the logger io.lettuce.core.protocol)
2. Take a Thread dump to investigate Thread activity

Cause:

Command timeouts are caused by the fact that a command was not completed within the configured timeout. Timeouts may be caused for various reasons:

1. Redis server has crashed/network partition happened and your Redis service didn’t recover within the configured timeout
2. Command was not finished in time. This can happen if your Redis server is overloaded or if the connection is blocked by a command (e.g. BLPOP 0, long-running Lua script). See also blpop(Duration.ZERO, …) gives RedisCommandTimeoutException.
3. Configured timeout does not match Redis’s performance.
4. If you block the EventLoop (e.g. calling blocking methods in a RedisFuture callback or in a Reactive pipeline). That can easily happen when calling Redis commands in a Pub/Sub listener or a RedisConnectionStateListener.

Action:

Check for the causes above. If the configured timeout does not match your Redis latency characteristics, consider increasing the timeout. Never block the EventLoop from your code.

여러 원인중에서 1번 Redis server의 네트워크 상태가 불안정할 때 발생하다는 부분에 눈길이 갔다.

그 이유는 Hikari를 사용하며 db pool 관리를 할 때 방화벽에서 일정시간이 지난 idle DB 연결을 끊었고, maxLifetime으로 커넥션 갱신해줌으로써 이슈를 해결했던 것이 떠올랐기 때문이다.

가끔 클라우드 업체의 NAT을 사용하여 외부 솔루션 서비스를 사용하다보면 이런 경험을 하게된다.

내가 경험한 이슈의 원인은 이렇다.

서버 - 방화벽 혹은 NAT - 서버  구조에서 

방화벽 혹은 NAT에서 다양한 이유로 유휴 커넥션을 drop 시킨다.

그렇기 때문에 커넥션을 지속적으로 갱신을 하거나 커넥션 검사 후 validation을 하여 사용가능 하지 않으면 커넥션을 재요청을 해야한다.

lettuce는 아무런 설정을 하지 않으면 Redis server와 커넥션 1개를 생성하고 여러 스레드가 공유하도록 한다.

어차피 Redis server는 single thread로 동작을하여 lettuce connection pool을 만들 필요가 없다고 한다. 단, 트랜잭션 처리를 위해서 pool을 형성할 필요성이 있다고 한다.

7.10.1. Is connection pooling necessary?

Lettuce is thread-safe by design which is sufficient for most cases. All Redis user operations are executed single-threaded. Using multiple connections does not impact the performance of an application in a positive way. The use of blocking operations usually goes hand in hand with worker threads that get their dedicated connection. The use of Redis Transactions is the typical use case for dynamic connection pooling as the number of threads requiring a dedicated connection tends to be dynamic. That said, the requirement for dynamic connection pooling is limited. Connection pooling always comes with a cost of complexity and maintenance.

사실 lettuce와 Redis server와의 커넥션을 끊어지는 현상이 없다면 다음과 같은 시도를 하지 않았텐데 한번 시도해보기로 하였다.

spring.redis.lettuce.pool.max-active #기본값 8 
spring.redis.lettuce.pool.max-idle #기본값 8 
spring.redis.lettuce.pool.max-wait #기본값 -1ms, 풀에서 커넥션 얻을때까지 대기 시간, 음수면 무기한 
spring.redis.lettuce.pool.min-idle #기본값 0, time-between-eviction-runs있을때만 유효 
spring.redis.lettuce.pool.time-between-eviction-runs #유휴 커넥션을 제거하는 스레드의 실행 간격

@Configuration
@EnableRedisHttpSession(maxInactiveIntervalInSeconds = 3600 * 12)
@EnableRedisRepositories
public class RedisSessionConfig {
	@Value("${spring.redis.host}")
	private String redisHost;
	@Value("${spring.redis.port}")
	private int redisPort;
	@Value("${spring.redis.lettuce.pool.max-active}")
	private int maxActive;
	@Value("${spring.redis.lettuce.pool.max-idle}")
	private int maxIdle;
	@Value("${spring.redis.lettuce.pool.min-idle}")
	private int minIdle;
	@Value("${spring.redis.lettuce.pool.max-wait}")
	private int maxWait;
	@Value("${spring.redis.lettuce.pool.time-between-eviction-runs}")
	private int timeBetweenEvictionRuns;

	@Bean
	public LettuceConnectionFactory connectionFactory() {
		RedisStandaloneConfiguration config = new RedisStandaloneConfiguration(redisHost.trim(), redisPort);
		GenericObjectPoolConfig poolConfig = new GenericObjectPoolConfig();
		poolConfig.setMaxTotal(maxActive);
		poolConfig.setMaxIdle(maxIdle);
		poolConfig.setMinIdle(minIdle);
		poolConfig.setMaxWaitMillis(maxWait);
		poolConfig.setTimeBetweenEvictionRunsMillis(timeBetweenEvictionRuns);
		LettuceClientConfiguration clientConfig = LettucePoolingClientConfiguration.builder().poolConfig(poolConfig)
				.build();

		LettuceConnectionFactory factory = new LettuceConnectionFactory(config, clientConfig); // Single Mode
		factory.setShareNativeConnection(Boolean.FALSE);
		return factory;
	}

	@Bean
	public RedisTemplate<String, String> redisSessionTemplate() {
		RedisTemplate<String, String> redisTemplate = new RedisTemplate<>();
		redisTemplate.setConnectionFactory(connectionFactory());
		redisTemplate.setKeySerializer(new StringRedisSerializer());
		redisTemplate.setValueSerializer(new StringRedisSerializer());
		return redisTemplate;
	}

}

유휴 커넥션을 지속적으로 갱신하기 위해 min-idle(5), time-between-eviction-runs(10초) 옵션을 활용했다.

한달동안 모니터링하였고, 결과적으로 해당 이슈를 해결되었다. 

아무리 좋은 기능도 인프라 상황에 따라서 사용할 수 없고, 우회 방법을 선택하는 경우였다.

이런 인프라 상황에는 차라리 Jedis를 활용하는 것이 더 맞을 것 같다는 생각이 든다

출처

- https://github.com/redis/jedis/issues/2112

- https://jronin.tistory.com/126

- https://lettuce.io/core/snapshot/reference/#faq.timeout

프로젝트를 하며 지정된 시간 혹은 지정된 시간마다 반복적으로 특정 작업을 처리해야할 때가 있었다.

이를 위해 @Scheduled로 Spring Scheduled Task를 사용하면서 겪었던 문제와 알게된 사실들에 대해서 정리하고자한다.

API 서버에 여러 스케줄러가 운영되고 있고, 이 스케줄러들은 각기 다른 일들을 처리하며 1주일 이상 정상적으로 동작을 하였다. 하지만 갑자기 모든 스케줄러가 동작을 멈추었다...

원인은 스케줄러는 많은데 하나의 thread만 공유하여 사용하기 때문일 것이라고 생각했다. 그래서 우선 thread pool size를 증가시키고, 스케줄러 excution time을 계산하는 등 디버깅해보기로 결정했다. 아래는 이와 관련된 내용을 정리하며 알게된 내용들이다.

첫째, 기본적으로 scheduled task thread pool size는 1이다. 이 말은 여러 scheduler가 하나의 thread를 공유하며 실행된다는 것이다.

2046-05-22 14:04:32.801 [thread name] org.xxx.xxx.xxx: scheduled task is running

로그를 찍어봐도 알 수 있듯이 thread name이 동일하고, 각 스케줄러에 동일하게 출력될 것이다.

둘째, scheduled task thread pool size를 조정하기 위해 spring.task.scheduling.pool.size(spring boot 2.5.0)를 사용했지만 적용이 안된다. 대신에 bean을 등록하여 overriding 하자.

@Bean
public ThreadPoolTaskScheduler taskScheduler(){
	ThreadPoolTaskScheduler taskScheduler = new ThreadPoolTaskScheduler();
	taskScheduler.setPoolSize(10);
	taskScheduler.setThreadNamePrefix("task-scheduler-");
	taskScheduler.initialize();
	return taskScheduler;
}

하지만 풀 사이즈를 조정을 하여도 같은 현상이 발생하였다. 스케줄러 내부 로직의 문제는 아닌 것으로 판단을 하였고, 스케줄러에서 동작하는 API의 실행시간을 디버깅해보기로 마음먹었다.

첫째, 각 스케줄러가 실행되는 시간을 확인하기 위해 AOP method를 활용하자.

thread와 스케줄러를 함께 모니터링하면 특정 스케줄러가 스레드를 독점적으로 사용하고 있는지 확인할 수 있다.

@Aspect
@Component
public class LoggingAspect {
	@Around("@annotation(org.springframework.scheduling.annotation.Scheduled)")
	public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
    	long start = System.currentTimeMillis();
    	try {
      		// monitor threads which runs specific tasks with Thread.currentThread()
        	proceed = joinPoint.proceed();
    	} finally {
        	long executionTime = System.currentTimeMillis() - start;
        	log.info(executionTime)
     	}
    	return proceed;
	}
}

둘째, 스케줄러 내부에서 사용하는 내부 API execution time을 보고, 디버깅에 활용한다.

	@Bean
	public FilterRegistrationBean<OncePerRequestFilter> executionTimeLoggingFilter() {
		return new FilterRegistrationBean<OncePerRequestFilter>() {{
			//setUrlPatterns();
			setOrder(OrderedFilter.REQUEST_WRAPPER_FILTER_MAX_ORDER);
			setFilter(new OncePerRequestFilter() {
				@Override
				protected void doFilterInternal(HttpServletRequest req, HttpServletResponse res, FilterChain chain) throws ServletException, IOException {
					StopWatch watch = new StopWatch();
					watch.start();
					try {
						chain.doFilter(req, res);
					}finally {
						watch.stop();
						long executionTime = watch.getTotalTimeMillis();
						// debugging with executionTime
					}
					
				}
			});
		}};
	}

디버깅 로그를 확인해보니 외부 API가 불규칙적으로 정상 동작하지 않았고, 응답 대기시간이 굉장히 긴 것을 확인하였다.

이러한 현상이 반복이 되자 스케줄러 풀이 정상 동작하지 않게됬을 것이고, 전체 스케줄러가 동자을 멈춘 것이었다.

따라서 해당 외부 API에 타임아웃을 주었고, 외부  업체에 장애에 대한 조치를 요청하였다.

resttemplate의 default timeout은 infinite 였다..timeout을 주도록하자.

HttpComponentsClientHttpRequestFactory httpRequestFactory = new HttpComponentsClientHttpRequestFactory();
httpRequestFactory.setConnectionRequestTimeout(...);
httpRequestFactory.setConnectTimeout(...);
httpRequestFactory.setReadTimeout(...);

return new RestTemplate(httpRequestFactory);

그 후 2주동안 모니터링하였고, 시스템이 정상적으로 돌아가는 것을 확인하였다.

라이브러리에서 제공하는 기본 설정들을 주의깊게 살펴보는 습관을 가져야겠다는 생각이 들었다.

출처

- https://jsonobject.tistory.com/247

- https://howtodoinjava.com/spring-boot2/resttemplate/resttemplate-timeout-example/

- https://stackoverflow.com/questions/29796651/what-is-the-default-scheduler-pool-size-in-spring-boot

- https://mossgreen.github.io/Spring-Scheduled-Tasks-Stop-Working/

- https://stackoverflow.com/questions/29796651/what-is-the-default-scheduler-pool-size-in-spring-boot

- https://jasper-rabbit.github.io/posts/spring-security-architecture-review/