접속기록 배치가 느린 이유 (1편) - 문제 진단과 병목 분석

[Jenkins] 배치 작업 실패: access-log-batch
원인: Build timed out (3시간 초과)
실행 시간: 3시간 12분

@Configuration
public class BatchJobConfiguration {

    @Bean
    public Job userAccessLogJob(JobRepository jobRepository,
                                 Step step1,
                                 Step step2) {
        return new JobBuilder("userAccessLogJob", jobRepository)
            .start(step1)
            .next(step2)
            .build();
    }
}

// 1. Tasklet 방식
@Bean
public Step taskletStep(JobRepository jobRepository,
                        PlatformTransactionManager transactionManager) {
    return new StepBuilder("taskletStep", jobRepository)
        .tasklet((contribution, chunkContext) -> {
            // 작업 로직
            return RepeatStatus.FINISHED;
        }, transactionManager)
        .build();
}

// 2. Chunk 방식
@Bean
public Step chunkStep(JobRepository jobRepository,
                      PlatformTransactionManager transactionManager,
                      ItemReader<User> reader,
                      ItemProcessor<User, UserDto> processor,
                      ItemWriter<UserDto> writer) {
    return new StepBuilder("chunkStep", jobRepository)
        .<User, UserDto>chunk(1000, transactionManager)
        .reader(reader)
        .processor(processor)
        .writer(writer)
        .build();
}

@Configuration
@RequiredArgsConstructor
public class AccessLogBatchConfig {

    private final JobRepository jobRepository;
    private final PlatformTransactionManager transactionManager;

    @Bean
    public Job accessLogJob() {
        return new JobBuilder("accessLogJob", jobRepository)
            .start(dailyAccessStep())      // 1. 일별 접속 통계
            .next(weeklyAccessStep())      // 2. 주별 접속 통계
            .next(monthlyAccessStep())     // 3. 월별 접속 통계
            .next(deviceTypeStep())        // 4. 디바이스별 통계
            .next(channelAccessStep())     // 5. 채널별 접속 통계
            .build();
    }

    @Bean
    public Step dailyAccessStep() {
        return new StepBuilder("dailyAccessStep", jobRepository)
            .<AccessLog, DailyAccessStat>chunk(1000, transactionManager)
            .reader(accessLogReader())
            .processor(dailyAccessProcessor())
            .writer(dailyAccessWriter())
            .build();
    }

    // 나머지 Step들도 유사한 구조...
}

@Slf4j
@Component
public class StepTimingListener implements StepExecutionListener {

    @Override
    public void beforeStep(StepExecution stepExecution) {
        log.info("=== Step 시작: {} ===", stepExecution.getStepName());
    }

    @Override
    public ExitStatus afterStep(StepExecution stepExecution) {
        long duration = stepExecution.getEndTime().getTime()
                      - stepExecution.getStartTime().getTime();

        log.info("=== Step 종료: {} ===", stepExecution.getStepName());
        log.info("실행 시간: {} 분", duration / 1000 / 60);
        log.info("읽은 데이터: {} 건", stepExecution.getReadCount());
        log.info("쓴 데이터: {} 건", stepExecution.getWriteCount());

        return stepExecution.getExitStatus();
    }
}

// Step에 리스너 등록
@Bean
public Step dailyAccessStep() {
    return new StepBuilder("dailyAccessStep", jobRepository)
        .<AccessLog, DailyAccessStat>chunk(1000, transactionManager)
        .reader(accessLogReader())
        .processor(dailyAccessProcessor())
        .writer(dailyAccessWriter())
        .listener(stepTimingListener)  // 리스너 추가
        .build();
}

=== 배치 시작: 2023-10-14 02:00:00 ===

=== Step 시작: dailyAccessStep ===
실행 시간: 42분
읽은 데이터: 5,230만 건
쓴 데이터: 180만 건

=== Step 시작: weeklyAccessStep ===
실행 시간: 38분
읽은 데이터: 5,230만 건
쓴 데이터: 95만 건

=== Step 시작: monthlyAccessStep ===
실행 시간: 35분
읽은 데이터: 5,230만 건
쓴 데이터: 42만 건

=== Step 시작: deviceTypeStep ===
실행 시간: 29분
읽은 데이터: 5,230만 건
쓴 데이터: 220만 건

=== Step 시작: channelAccessStep ===
실행 시간: 33분
읽은 데이터: 5,230만 건
쓴 데이터: 340만 건

=== 배치 종료: 2023-10-14 04:57:00 ===
총 실행 시간: 2시간 57분

// 현재 구조
.start(dailyAccessStep())      // 42분 대기
.next(weeklyAccessStep())      // 38분 대기
.next(monthlyAccessStep())     // 35분 대기
.next(deviceTypeStep())        // 29분 대기
.next(channelAccessStep())     // 33분 대기
// 총 177분 (약 3시간)

// 각 Step의 Reader
@Bean
public JdbcPagingItemReader<AccessLog> accessLogReader() {
    return new JdbcPagingItemReaderBuilder<AccessLog>()
        .name("accessLogReader")
        .dataSource(dataSource)
        .queryProvider(queryProvider())
        .selectClause("SELECT *")
        .fromClause("FROM access_log")
        .whereClause("WHERE log_date = :targetDate")
        .sortKeys(Map.of("id", Order.ASCENDING))
        .pageSize(1000)
        .rowMapper(new BeanPropertyRowMapper<>(AccessLog.class))
        .build();
}

// 1. 일별 통계 → daily_access_stat 테이블에 저장
// 2. 주별 통계 → weekly_access_stat 테이블에 저장
// 3. 월별 통계 → monthly_access_stat 테이블에 저장
// 4. 디바이스 통계 → device_type_stat 테이블에 저장
// 5. 채널 통계 → channel_access_stat 테이블에 저장

각 Step이 서로 다른 데이터를 수정하는가?
→ 예. 서로 다른 테이블에 저장

트랜잭션 충돌 가능성이 없는가?
→ 예. 각각 독립적인 트랜잭션

공유 자원(파일, 캐시 등)을 사용하지 않는가?
→ 예. DB만 사용

실행 순서가 중요하지 않은가?
→ 예. 순서 무관

서버 리소스(CPU, 메모리)가 충분한가?
→ 예. CPU는 여유로움 (각 Step이 순차 실행 중일 때 CPU 20% 미만)

@Bean
public Job parallelJob() {
    Flow flow1 = new FlowBuilder<Flow>("flow1")
        .start(dailyAccessStep())
        .build();

    Flow flow2 = new FlowBuilder<Flow>("flow2")
        .start(weeklyAccessStep())
        .build();

    return new JobBuilder("parallelJob", jobRepository)
        .start(flow1)
        .split(new SimpleAsyncTaskExecutor())  // 병렬 실행
        .add(flow2)
        .end()
        .build();
}

@Async
public void executeStep1() {
    // Step 실행
}

@Async
public void executeStep2() {
    // Step 실행
}

ForkJoinPool customPool = new ForkJoinPool(5);  // 5개 스레드
List<Runnable> tasks = List.of(
    () -> executeStep(dailyAccessStep),
    () -> executeStep(weeklyAccessStep),
    () -> executeStep(monthlyAccessStep),
    () -> executeStep(deviceTypeStep),
    () -> executeStep(channelAccessStep)
);

customPool.submit(() ->
    tasks.parallelStream().forEach(Runnable::run)
).join();

customPool.shutdown();

# application.yml
spring:
  datasource:
    hikari:
      maximum-pool-size: 10 # 현재 설정

spring:
  datasource:
    hikari:
      maximum-pool-size: 20

.<AccessLog, DailyAccessStat>chunk(1000, transactionManager)

-- 기존 쿼리
SELECT *
FROM access_log
WHERE log_date = '2023-10-14'
ORDER BY id
LIMIT 1000 OFFSET ?

SHOW INDEX FROM access_log;

EXPLAIN SELECT * FROM access_log WHERE log_date = '2023-10-14';

+----+-------------+------------+------+---------------+------------------+---------+-------+----------+-------------+
| id | select_type | table      | type | possible_keys | key              | key_len | ref   | rows     | Extra       |
+----+-------------+------------+------+---------------+------------------+---------+-------+----------+-------------+
|  1 | SIMPLE      | access_log | ref  | idx_log_date  | idx_log_date     | 3       | const | 52300000 | Using where |
+----+-------------+------------+------+---------------+------------------+---------+-------+----------+-------------+