spring batch BATCH_STEP_EXECUTION update 쿼리 로그를 확인한다.

jinwook han·2020년 8월 29일

스프링 batch의 BATCH_STEP_EXECUTION 테이블의 version 필드 업데이트 쿼리를 확인하고 싶다.

먼저 mysql 쿼리 로그를 활성화하고, 그 후 update 쿼리 로그를 확인한다.

mysql 쿼리 활성화

1. docker cli에 접속한다.

현재 pc에 docker로 mysql이 실행되고 있다.
docker dashboard를 통해, mysql이 들어있는 container의 cli로 들어간다.

2. mysql에 접속한다.

mysql -u root -p

root 계정으로 접속했다.

3. mysql query log를 활성화한다.

먼저 query log 활성화 상태를 본다.

show variables like 'general%';

결과:

general_log는 쿼리 로그 활성화 여부고, general_log_file은 쿼리 로그 파일 경로다.

general_log를 ON으로 만든다.

set global general_log=on;

set global로 한다. 그냥 set을 하면 다시 입력하라고 나온다.

BATCH_STEP_EXECUTION update 쿼리 로그 확인

1. 배치를 실행한다.

2. query log를 확인한다.

mysql 변수 중 general_log_file를 확인한다.
general_log_file에 query log 파일 경로가 있다.

결과

....
2020-08-29T05:04:19.437486Z	302 Query	UPDATE BATCH_STEP_EXECUTION set START_TIME = '2020-08-29 14:04:19', END_TIME = null, STATUS = 'STARTED', COMMIT_COUNT = 8, READ_COUNT = 80, FILTER_COUNT = 0, WRITE_COUNT = 80, EXIT_CODE = 'EXECUTING', EXIT_MESSAGE = '', VERSION = 9, READ_SKIP_COUNT = 0, PROCESS_SKIP_COUNT = 0, WRITE_SKIP_COUNT = 0, ROLLBACK_COUNT = 0, LAST_UPDATED = '2020-08-29 14:04:19' where STEP_EXECUTION_ID = 65 and VERSION = 8
		
2020-08-29T05:04:19.483982Z	302 Query	UPDATE BATCH_STEP_EXECUTION set START_TIME = '2020-08-29 14:04:19', END_TIME = null, STATUS = 'STARTED', COMMIT_COUNT = 9, READ_COUNT = 90, FILTER_COUNT = 0, WRITE_COUNT = 90, EXIT_CODE = 'EXECUTING', EXIT_MESSAGE = '', VERSION = 10, READ_SKIP_COUNT = 0, PROCESS_SKIP_COUNT = 0, WRITE_SKIP_COUNT = 0, ROLLBACK_COUNT = 0, LAST_UPDATED = '2020-08-29 14:04:19' where STEP_EXECUTION_ID = 65 and VERSION = 9
		
2020-08-29T05:04:19.522695Z	302 Query	UPDATE BATCH_STEP_EXECUTION set START_TIME = '2020-08-29 14:04:19', END_TIME = null, STATUS = 'STARTED', COMMIT_COUNT = 10, READ_COUNT = 100, FILTER_COUNT = 0, WRITE_COUNT = 100, EXIT_CODE = 'EXECUTING', EXIT_MESSAGE = '', VERSION = 11, READ_SKIP_COUNT = 0, PROCESS_SKIP_COUNT = 0, WRITE_SKIP_COUNT = 0, ROLLBACK_COUNT = 0, LAST_UPDATED = '2020-08-29 14:04:19' where STEP_EXECUTION_ID = 65 and VERSION = 10
		
2020-08-29T05:04:19.564558Z	302 Query	UPDATE BATCH_STEP_EXECUTION set START_TIME = '2020-08-29 14:04:19', END_TIME = null, STATUS = 'STARTED', COMMIT_COUNT = 11, READ_COUNT = 110, FILTER_COUNT = 0, WRITE_COUNT = 110, EXIT_CODE = 'EXECUTING', EXIT_MESSAGE = '', VERSION = 12, READ_SKIP_COUNT = 0, PROCESS_SKIP_COUNT = 0, WRITE_SKIP_COUNT = 0, ROLLBACK_COUNT = 0, LAST_UPDATED = '2020-08-29 14:04:19' where STEP_EXECUTION_ID = 65 and VERSION = 11
		
2020-08-29T05:04:19.588156Z	302 Query	UPDATE BATCH_STEP_EXECUTION set START_TIME = '2020-08-29 14:04:19', END_TIME = null, STATUS = 'STARTED', COMMIT_COUNT = 12, READ_COUNT = 111, FILTER_COUNT = 0, WRITE_COUNT = 111, EXIT_CODE = 'EXECUTING', EXIT_MESSAGE = '', VERSION = 13, READ_SKIP_COUNT = 0, PROCESS_SKIP_COUNT = 0, WRITE_SKIP_COUNT = 0, ROLLBACK_COUNT = 0, LAST_UPDATED = '2020-08-29 14:04:19' where STEP_EXECUTION_ID = 65 and VERSION = 12
		
2020-08-29T05:04:19.606927Z	301 Query	UPDATE BATCH_STEP_EXECUTION set START_TIME = '2020-08-29 14:04:19', END_TIME = '2020-08-29 14:04:19', STATUS = 'COMPLETED', COMMIT_COUNT = 12, READ_COUNT = 111, FILTER_COUNT = 0, WRITE_COUNT = 111, EXIT_CODE = 'COMPLETED', EXIT_MESSAGE = '', VERSION = 14, READ_SKIP_COUNT = 0, PROCESS_SKIP_COUNT = 0, WRITE_SKIP_COUNT = 0, ROLLBACK_COUNT = 0, LAST_UPDATED = '2020-08-29 14:04:19' where STEP_EXECUTION_ID = 65 and VERSION = 13

query log 파일에 있는 쿼리 로그 중,
1. 특정 step_execution_id가 where절에 들어가고,
2. BATCH_STEP_EXECUTION를 업데이트를 하고,
3. version 필드를 업데이트하는 쿼리 로그만 뽑았다.

결과 해석

처음 insert된 step execution은 version값이 0이다.
첫번째 커밋: version 1, commit_count 0로 업데이트한다.
n 번째 커밋: version n, commit_count n-1로 업데이트한다.
마지막 커밋: commit_count는 업데이트되지 않는다. version이 1 증가하여 업데이트된다. status도 completed로 바뀐다.
커밋이 끝난 후, BATCH_STEP_EXECUTION의 version과 commit_count의 차이는 2가 된다. version이 commit_count보다 2 크다.

성공한 STEP_EXECUTION commit_count의 version의 차이는 항상 2다. 위 해석으로 차이가 왜 2인지 설명할 수 있을 것 같다.