프로그래밍/Spring & Maven/Scheduled debugging

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

이를 위해 @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/