HyunJun 기술 블로그

스프링 프레임워크 batch scheduler 로그 파일 삭제하기 본문

Spring Framework

스프링 프레임워크 batch scheduler 로그 파일 삭제하기

공부 좋아 2023. 5. 16. 21:10
728x90
반응형

1. 배치와 스케줄러란?

스프링 배치는 데이터의 일괄처리를 할 수 있게 해 주는 프레임워크이고, 스케줄러는 일정한 시간 간격 또는 일정한 시각에 특정 로직이 동작할 수 있게 해주는 기능입니다.

 

  • batch -> 데이터의 일괄 처리
  • scheduler -> 특정 시간에 동작
  • 여기서 잠깐, 그렇다면 데이터의 일괄 처리를 할 때 batch는 어떻게 동작을 시켜줘야 할까요?
  • 거의 대부분 배치 처리는 스케줄러와 같이 쓰이고 이때 쓰이는 스케줄러가 Spring Scheduler, Quartz 등입니다.
    -> 결론은 배치 처리는 스케줄러에 의해 실행된다라고 보셔도 될 것 같습니다.
  • 그러면 batch와 scheduler를 사용하여 로그 각각 데이터에 대해서 특정 기간이 지났을 때 삭제되는 로직을 구현해 보도록 하겠습니다.

2. 구현

스프링 스케줄러에는 일반 스케줄러와 쿼츠 스케줄러가 존재합니다. 로그 파일 삭제에는 단순 스케줄러만으로도 구현을 할 수 있으므로 일반 스케줄러로 진행하도록 하겠습니다. 로그 엔티티와 Database 연동 부분에 관해서는 이전 글을 참조해 주세요.

 

 

 

 

2-1. Scheduler

build.gradle

/*배치 의존성*/
implementation 'org.springframework.boot:spring-boot-starter-batch'

Spring Scheduler의 경우 Spring Boot Starter 의존성 안에 포함되어 있습니다.

 

 

 

 

 

Application

@EnableScheduling
@EnableBatchProcessing
@SpringBootApplication
public class MyLogApplication {
    public static void main(String[] args) {
        SpringApplication.run(MyLogApplication.class, args);
    }

}

스케줄링과, 배치프로세싱을 적용해 줍니다.

 

 

 

 

config 패키지 안에 2개의 자바 파일을 만들게요

 

 

 

 

BatchScheduler

@Slf4j
@Component
public class BatchScheduler {

	// 5초에 한번
    @Scheduled(cron = "0/5 * * * * *")
    public void test() {
        log.info("test");
    }

}

위와 같이 @Scheduled와 cron만 사용해도 스케줄러가 동작하게 되고 5초에 한 번씩 test()가 동작합니다.

하지만 이번 시간의 목표는 배치 처리를 하기 위해서 스케줄러를 동작시키는 것이었죠?

 

 

 

 

cron 표현식은 아래의 그림을 참고해 주세요.

출처: https://madplay.github.io/post/a-guide-to-cron-expression

 

2-2. Spring Batch

application.yml

  batch:
    jdbc:
      initialize-schema: always # batch 스키마 자동 생성
    job:
      enabled: false            # 시작과 동시에 실행되는것 방지, 직접 Job을 등록하여 사용한다.

 

스프링 배치를 구현하기 위해서는 데이터베이스에 배치 관련 스키마가 정의되어 있어야 합니다.

initialize-schema: always를 입력해 주면 테이블을 자동으로 생성해 줍니다.

 

 

 

 

 

간단하게 구조만 알고 가보자면 하나의 작업을 의미하는 Job과 Job에서 이루어지는 단계인 Step이 있습니다.

출처: https://docs.spring.io/spring-batch/docs/current/reference/html/domain.html#domainLanguageOfBatch

 

 

 

 

조금 전의 기본 스케줄링 기능만 있는 스케줄러가 아닌 배치처리를 하기 위해서의 스케줄러로 코드를 변경했습니다.

@Slf4j
@Component
@RequiredArgsConstructor
public class BatchScheduler {

    private final JobLauncher jobLauncher;
    private final BatchConfig batchConfig;

    @Scheduled(cron = "0/5 * * * * *")// 5초에 한번
    public void runJob() {

        // job parameter 설정
        Map<String, JobParameter> confMap = new HashMap<>();
        confMap.put("time", new JobParameter(System.currentTimeMillis()));
        JobParameters jobParameters = new JobParameters(confMap);

        try {
            jobLauncher.run(batchConfig.job(), jobParameters);
        } catch (JobExecutionAlreadyRunningException | JobInstanceAlreadyCompleteException
                 | JobParametersInvalidException | org.springframework.batch.core.repository.JobRestartException e) {
            log.error(e.getMessage());
        }
    }
}
  • 서론에 배치처리는 스케줄러에 의해 실행된다고 했죠?
  • 예시 코드 기준 5초에 한 번씩 실행되는 runJob() 메서드를 분석해 볼까요?
  • jobLauncher.run()을 실행할 때 job의 로직 즉, 배치처리 부분인 batchConfig.job()과 jobParameters를 전달합니다.
  • jobParameters는 time이라는 이름으로 현재 시간을 저장하여 전달합니다.

 

 

이때, time이라는 파라미터는 왜 전달하고 역할은 무엇인 걸까요?

jobParameters에 currentTimeMillis를 제거하고, "1"이라는 고정 값을 파라미터로 넣어보았습니다.

그랬더니 아래와 같은 에러가 발생하네요..?

2023-05-17 13:10:35,083 ERROR c.e.l.config.BatchScheduler [scheduling1] - A job instance already exists and iscomplete for parameters={time=1}.  If you want to run this job again, change the parameters.

 

에러를 해석해 보니, 작업 인스턴스가 이미 존재하고 time=1 파라미터에 대해 이미 완료되었습니다. 이 작업을 다시 실행하려면 매개변수를 변경해달라고 하네요.

 

잡이 실행되는 잡 인스턴스의 경우 매번 실행마다 다른 파라미터 고유값을 넣어 주어야 잡 인스턴스가 실행되게 됩니다.

(기본 옵션으로는 완료된 파라미터에 대해서는 재실행이 불가능)

 

이번에는 다시 매번 다르게 입력되는 currentTimeMillis를 입력해 보았습니다. 그랬더니 아래와 같이 성공 로그가 발생했습니다.

2023-05-17 13:15:45,172 INFO  o.s.b.c.l.support.SimpleJobLauncher [scheduling1] - Job: [SimpleJob: [name=job]] launched with the following parameters: [{time=1684296945003}]

 

 

이러한 이유는 Job Instance가 중복 실행되는 것을 막기 위함입니다.

물론 Job Parameter가 동일할 때 실행될 수 있게 구현할 수 있지만 이 글에서는 언급하지 않겠습니다.

 

 

 

 

다음으로 실제적으로 Job의 로직이 포함된 코드를 보겠습니다.

@Slf4j
@Configuration
@RequiredArgsConstructor
public class BatchConfig {
    private final JobBuilderFactory jobBuilderFactory;
    private final StepBuilderFactory stepBuilderFactory;
    private final LogRepository logRepository;

    @Bean
    public Job job() {

        Job job = jobBuilderFactory.get("job")
                .start(step())
                .build();

        return job;
    }

    @Bean
    public Step step() {
        return stepBuilderFactory.get("step")
                .tasklet((contribution, chunkContext) -> {

                    // 생성된 시각이 일주일이 넘은 로그 목록을 가지고 온다.
                    List<Log> logList = logRepository.selectLogs();

                    if (logList.size() > 0 && logList != null) {
                        for (Log entity : logList) {
                            /*해당 로그를 삭제한다.*/
                            logRepository.deleteById(entity.getId());
                        }
                    }
                    return RepeatStatus.FINISHED;
                })
                .build();
    }

}
  • job을 .start하고 있으며 매개변수로 step을 넘겨줘서 step을 실행한다.
  • step에서는 nativeQuery를 사용하여 생성된 시각이 일주일이 넘은 로그들을 가지고 온다.
  • 삭제한다.

 

LogRepository

@Repository
public interface LogRepository extends JpaRepository<Log, Long> {
    @Query(value = "SELECT * FROM log WHERE log.created_at <= DATE_SUB(NOW(6), INTERVAL 30 SECOND)", nativeQuery = true)
    List<Log> selectLogs();
}

 

쿼리

"SELECT * FROM log WHERE log.created_at <= DATE_SUB(NOW(6), INTERVAL 30 SECOND)"

 

  • log.created_at는 로그에 저장된 해당 로그의 생성 시간입니다.  
  • DATE_SUB(NOW(6), INTERVAL 30 SECOND)는 DATE_SUB는 날짜 간의 빼기 연산을 해주는 함수이고, NOW(6)는 현재 날짜와 시간을 .6자리까지 표현해 줍니다. 마지막으로, INTERVAL 30 SECOND는 NOW(6)에서 30초를 뺍니다.
  • 결론적으로, 로그 생성 날짜 <= 현재 시간 - 30초의 결과는 로그의 생성 날짜가 30초 이상이 지났다는 것을 의미하고
  • SECOND 부분을 HOUR, DAY, MONTH, YEAR 등으로 활용해서 해당 로그가 생성된 기간이 N을 넘어간다면 해당 로그를 가지고 와서 삭제한다든지 하는 부분으로 활용할 수 있습니다.

 

3. 결과 확인

마지막으로, 스케줄러를 1분에 한 번씩 실행하고, 5분이 지난 로그는 삭제하도록 테스트해 볼게요.

 

 

 

로그의 생성 시간이 5분이 지난 로그들을 조회한다.

@Repository
public interface LogRepository extends JpaRepository<Log, Long> {
    @Query(value = "SELECT * FROM log WHERE log.created_at <= DATE_SUB(NOW(6), INTERVAL 5 MINUTE)", nativeQuery = true)
    List<Log> selectLogs();
}

 

 

 

 

1분에 한 번 스케줄러를 동작시킨다.

@Slf4j
@Component
@RequiredArgsConstructor
public class BatchScheduler {

    private final JobLauncher jobLauncher;
    private final BatchConfig batchConfig;

    @Scheduled(cron = "0 1 * * * *")// 1분에 한번
    public void runJob() {

        // job parameter 설정
        Map<String, JobParameter> confMap = new HashMap<>();
        confMap.put("time", new JobParameter(System.currentTimeMillis()));
        JobParameters jobParameters = new JobParameters(confMap);

        try {
            jobLauncher.run(batchConfig.job(), jobParameters);
        } catch (JobExecutionAlreadyRunningException | JobInstanceAlreadyCompleteException
                 | JobParametersInvalidException | org.springframework.batch.core.repository.JobRestartException e) {
            log.error(e.getMessage());
        }
    }
}

 

 

아래와 같이 에러 로그를 발생시킨 후 Database에서 error 로그를 확인

 

 

프로그램을 실행 후, 약 5분 뒤, 로그파일에 찍힌 로그를 불러와 보았습니다.

2023-05-17 15:18:21,909 ERROR c.e.l.TestController - 에러 로그1
2023-05-17 15:18:21,980 ERROR c.e.l.TestController - 에러 로그2
2023-05-17 15:18:22,009 ERROR c.e.l.TestController - 에러 로그3
2023-05-17 15:18:22,037 ERROR c.e.l.TestController - 에러 로그4
2023-05-17 15:18:22,070 ERROR c.e.l.TestController - 에러 로그5
2023-05-17 15:19:00,324 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] launched with the following parameters: [{time=1684304340007}]
2023-05-17 15:19:00,504 INFO  o.s.b.core.job.SimpleStepHandler - Executing step: [step]
2023-05-17 15:19:00,722 INFO  o.s.batch.core.step.AbstractStep - Step: [step] executed in 217ms
2023-05-17 15:19:00,837 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] completed with the following parameters: [{time=1684304340007}] and the following status: [COMPLETED] in 467ms
2023-05-17 15:20:00,449 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] launched with the following parameters: [{time=1684304400007}]
2023-05-17 15:20:00,659 INFO  o.s.b.core.job.SimpleStepHandler - Executing step: [step]
2023-05-17 15:20:00,811 INFO  o.s.batch.core.step.AbstractStep - Step: [step] executed in 151ms
2023-05-17 15:20:00,927 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] completed with the following parameters: [{time=1684304400007}] and the following status: [COMPLETED] in 431ms
2023-05-17 15:21:00,608 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] launched with the following parameters: [{time=1684304460005}]
2023-05-17 15:21:00,797 INFO  o.s.b.core.job.SimpleStepHandler - Executing step: [step]
2023-05-17 15:21:00,936 INFO  o.s.batch.core.step.AbstractStep - Step: [step] executed in 139ms
2023-05-17 15:21:01,054 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] completed with the following parameters: [{time=1684304460005}] and the following status: [COMPLETED] in 397ms
2023-05-17 15:22:00,432 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] launched with the following parameters: [{time=1684304520004}]
2023-05-17 15:22:00,587 INFO  o.s.b.core.job.SimpleStepHandler - Executing step: [step]
2023-05-17 15:22:00,716 INFO  o.s.batch.core.step.AbstractStep - Step: [step] executed in 129ms
2023-05-17 15:22:00,832 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] completed with the following parameters: [{time=1684304520004}] and the following status: [COMPLETED] in 345ms
2023-05-17 15:23:00,471 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] launched with the following parameters: [{time=1684304580006}]
2023-05-17 15:23:00,642 INFO  o.s.b.core.job.SimpleStepHandler - Executing step: [step]
2023-05-17 15:23:00,803 INFO  o.s.batch.core.step.AbstractStep - Step: [step] executed in 160ms
2023-05-17 15:23:00,913 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] completed with the following parameters: [{time=1684304580006}] and the following status: [COMPLETED] in 399ms
2023-05-17 15:24:00,506 INFO  o.s.b.c.l.support.SimpleJobLauncher - Job: [SimpleJob: [name=job]] launched with the following parameters: [{time=1684304640000}]
2023-05-17 15:24:00,706 INFO  o.s.b.core.job.SimpleStepHandler - Executing step: [step]
2023-05-17 15:24:00,800 INFO  c.e.l.config.BatchConfig - 로그 삭제: 1
2023-05-17 15:24:00,809 INFO  c.e.l.config.BatchConfig - 로그 삭제: 2
2023-05-17 15:24:00,810 INFO  c.e.l.config.BatchConfig - 로그 삭제: 3
2023-05-17 15:24:00,810 INFO  c.e.l.config.BatchConfig - 로그 삭제: 4
2023-05-17 15:24:00,810 INFO  c.e.l.config.BatchConfig - 로그 삭제: 5

15:18:21쯤에 찍힌 에러 5개가 15:24:00에 삭제된 것을 확인할 수 있네요!

 

728x90
반응형
저작자표시 비영리 변경금지
'Spring Framework' Related Articles more
Comments