티스토리 뷰
인포믹스 online.log 파일에서 체크포인트 수행시 발생하는 메시지 관련해 테스트한 내용을 공유드립니다.
인포믹스 버전은 12.10.FC12였고 메시지는 아래와 같은 형식으로 표시되었습니다.
16:20:40 Physical Logging while in Critical Section: Number of pages logged in critcal section: 20 Remaining Phyical Log: 11665210
메시지로 볼때 한 트랜잭션내에서 많은 건수를 처리하는 것이 아닌가 추측되었는데요. 먼저 해당 메시지가 발생하는 시간대의 쿼리들을 확인해보았습니다. 몇가지 의심되는 쿼리를 찾았지만 특정짓기가 어려웠는데, 팀에서 logical log 파일에서 해당 시각의 트랜잭션 이력을 찾았고 해당시각의 트랜잭션중 truncate 로 인해 유발된 것임을 확인해 주셨습니다.
이에 유사한 규모의 테이블을 truncate 했을때 동일한 현상이 발생하는지 테스트해보았습니다.
아래와 같이 약 5 GB 의 더미 데이터를 입력하고 인덱스도 하나 만들었습니다.
$ oncheck -pt demo:bigtable
TBLspace Report for demo:bigtable
Physical Address 6:12
Creation date 06/23/2022 21:54:32
TBLspace Flags 902 Row Locking
TBLspace contains VARCHARS
TBLspace use 4 bit bit-maps
Maximum row size 107
Number of special columns 5
Number of keys 0
Number of extents 1
Current serial value 1
Current SERIAL8 value 1
Current BIGSERIAL value 1
Current REFID value 1
Pagesize (k) 2
First extent size 400000
Next extent size 320000
Number of pages allocated 2880000
Number of pages used 2778371
Number of data pages 2777681
Number of rows 50000000
Partition partnum 6291465
Partition lockid 6291465
Extents
Logical Page Physical Page Size Physical Pages
0 6:975383 2880000 2880000
Index bigtable_idx1 fragment partition datadbs in DBspace datadbs
Physical Address 6:13
Creation date 06/24/2022 14:37:56
TBLspace Flags 802 Row Locking
TBLspace use 4 bit bit-maps
Maximum row size 107
Number of special columns 0
Number of keys 1
Number of extents 1
Current serial value 1
Current SERIAL8 value 1
Current BIGSERIAL value 1
Current REFID value 1
Pagesize (k) 2
First extent size 179439
Next extent size 17943
Number of pages allocated 179439
Number of pages used 128715
Number of data pages 0
Number of rows 0
Partition partnum 6291466
Partition lockid 6291465
Last Lookup/Scan No Record
Extents
Logical Page Physical Page Size Physical Pages
0 6:3855383 179439 179439테스트용 스크립트는 체크포인트와 truncate table이 동시에 실행되도록 백그라운드로 실행되도록 준비했습니다.
$ cat test.sh
onmode -c &
dbaccess demo truncate.sql &스크립트 실행은 약 2초 정도 소요되었고 online.log 에는 아래와 같이 동일한 메시지가 발생되었습니다.
09:52:31 Physical Logging while in Critical Section: Number of pages logged in critcal section: 40 Remaining Phyical Log: 16139
09:52:31 Physical Logging while in Critical Section: Number of pages logged in critcal section: 80 Remaining Phyical Log: 16099
09:52:31 Physical Logging while in Critical Section: Number of pages logged in critcal section: 120 Remaining Phyical Log: 16059
09:52:32 Physical Logging while in Critical Section: Number of pages logged in critcal section: 160 Remaining Phyical Log: 16019
09:52:32 Physical Logging while in Critical Section: Number of pages logged in critcal section: 200 Remaining Phyical Log: 15979
09:52:32 Physical Logging while in Critical Section: Number of pages logged in critcal section: 240 Remaining Phyical Log: 15939
09:52:32 Physical Logging while in Critical Section: Number of pages logged in critcal section: 280 Remaining Phyical Log: 15897
09:52:32 Physical Logging while in Critical Section: Number of pages logged in critcal section: 320 Remaining Phyical Log: 15857
09:52:32 Physical Logging while in Critical Section: Number of pages logged in critcal section: 360 Remaining Phyical Log: 15817
09:52:33 Physical Logging while in Critical Section: Number of pages logged in critcal section: 400 Remaining Phyical Log: 15777
09:52:33 Physical Logging while in Critical Section: Number of pages logged in critcal section: 440 Remaining Phyical Log: 15737
09:52:33 Physical Logging while in Critical Section: Number of pages logged in critcal section: 480 Remaining Phyical Log: 15697
09:52:33 Physical Logging while in Critical Section: Number of pages logged in critcal section: 520 Remaining Phyical Log: 15655
09:52:33 Checkpoint Completed: duration was 2 seconds.
09:52:33 Sat Jun 25 - loguniq 2036, logpos 0x3a6048, timestamp: 0x18f8e672 Interval: 17469해당 시각의 트랜잭션 로그를 onlog로 열어보니 truncate 가 완료된 후 checkpoint가 수행되었음을 확인할 수 있습니다.
$ onlog -n 2036 > onlog.2036
$ vi onlog.2036
addr len type xid id link
...
3a4018 56 BEGIN 21 2036 0 06/25/2022 09:52:30 113 informix
3a4050 48 PTRUNCATE 21 0 3a4018 60000a 1
3a4080 48 PTRUNCATE 21 0 3a4050 600009 1
3a40b0 204 HUPBEF 21 0 3a4080 40011d b02 137
3a417c 204 HUPAFT 21 0 3a40b0 40011d b02 137
3a4248 316 HUPBEF 21 0 3a417c 40011f 2501 251
3a4384 316 HUPAFT 21 0 3a4248 40011f 2501 251
3a44c0 352 HUPBEF 21 0 3a4384 40016e 301 286
3a4620 352 HUPAFT 21 0 3a44c0 40016e 301 286
addr len type xid id link
3a4780 332 HUPBEF 21 0 3a4620 40016e 302 265
3a50e8 332 HUPAFT 21 0 3a4780 40016e 302 265
3a5234 204 HUPBEF 21 0 3a50e8 40011d b02 137
3a5300 204 HUPAFT 21 0 3a5234 40011d b02 137
3a53cc 56 BEGCOM 21 0 3a5300
3a6018 48 TRUNCATE 21 0 3a53cc 600009 1
3a6048 68 CKPOINT 1 2036 0 1
begin xid id addr user
2036 21 2036 3a6018 informix
3a7018 44 HA 1 0 3a6048 CKPTEND 17469
3a7044 40 SYNC 1 0 3a7018
3a8018 48 TRUNCATE 21 0 3a6018 60000a 1
3a8048 56 COMMIT 21 0 3a8018 06/25/2022 09:52:33IBM Community에 해당 메시지가 정보성인지, 오류에 의한 것인지 조언을 구했는데 Art Kagel , John Lengyel 의 답변으로 정보성 메시지임을 알게 되었습니다. 12.10.FC15 버전부터는 내부 계산에 의해 physical log가 부족한 상황에서만 해당 메시지가 표시되도록 수정되었다고 합니다.
Art의 설명을 요약해보면 truncate 실행이 critical sections 에 머무는 동안은 checkpoint가 수행될 수 없는데, 이는 일반적인 현상이고 오류는 아니라는 거지요. 참고로 LOB 데이터가 포함된 테이블의 경우 truncate나 drop이 오래 걸립니다. truncate가 critical sections에서 수행되는 동안 physical log가 기록되다가 overflow 되면 그 기간 동안의 트랜잭션은 recover, rollback 될 수 없는 위험이 있습니다. 물론 truncate 작업이 오래 걸리지 않고, physical log가 충분한 경우라면 그런 상황은 발생하지 않겠죠. 말 그래도 일반적인 상황인거죠.
기본적으로는 physical log가 충분한 크기로 구성되어 있어야 하고, critical section에 머무는 truncate나 drop, alter 등의 관리 작업을 실행할 때는 수행시간이 길게 예상되는 트랜잭션은 실행을 피하는게 좋을 것 같습니다.
John의 언급을 보면 이 메시지가 나타다더라도 사용자가 뭔가 조치를 할 수 있는 것은 별로 없지만, 지원팀에서는 원인 파악에 도움이 될거라는군요. 버전이 바뀌면 로그에 새로운 메시지가 발견되곤 하는데 이 메시지가 그런 경우인 것 같습니다.
- Total
- Today
- Yesterday