vi /etc/sysctl.conf
# Controls IP packet forwarding
net.ipv4.ip_forward = 0
# Controls source route verification
net.ipv4.conf.default.rp_filter = 1
# Do not accept source routing
net.ipv4.conf.default.accept_source_route = 0
# Controls the System Request debugging functionality of the kernel
kernel.sysrq = 0
# Controls whether core dumps will append the PID to the core filename.
# Useful for debugging multi-threaded applications.
kernel.core_uses_pid = 1
# Controls the use of TCP syncookies
net.ipv4.tcp_syncookies = 1
# Disable netfilter on bridges.
#net.bridge.bridge-nf-call-ip6tables = 0
#net.bridge.bridge-nf-call-iptables = 0
#net.bridge.bridge-nf-call-arptables = 0
# Controls the default maxmimum size of a mesage queue
kernel.msgmnb = 65536
# Controls the maximum size of a message, in bytes
kernel.msgmax = 65536
# Controls the maximum shared segment size, in bytes
kernel.shmmax = 68719476736
# Controls the maximum number of shared memory segments, in pages
kernel.shmall = 4294967296
# swap setting
vm.swappiness=0
net.ipv4.tcp_fin_timeout=1
net.ipv4.tcp_tw_reuse=1
net.ipv4.tcp_tw_recycle=1
net.ipv4.tcp_keepalive_time=10
net.ipv4.tcp_keepalive_probes=2
net.ipv4.tcp_keepalive_intvl=2
net.ipv4.tcp_syncookies=1
net.ipv4.tcp_syn_retries=1
net.ipv4.tcp_max_syn_backlog=8192
7. malloc 을 리눅스 OS에 기본설정말고 다른 걸로 바꿔라?
- 뮤택스 락부분에서 개선이 있다고 해서 jemalloc, tcmalloc 둘다 깔아서 써봤는데 별차이 없었다. 그냥 안쓰는 걸로..
explain
select count(*) from TB_AAA T1
INNER JOIN TB_BBB T2
ON T1.SEQ_NO = T2.SEQ_NO
INNER JOIN TB_CCC T3 /* 24GB 파티션 테이블 */
ON T1.SEQ_NO = T3.SEQ_NO
WHERE T1.CHNG_DTTM BETWEEN DATE_FORMAT(CONCAT('202305', '01'),'%Y-%m-%d 00:00:00')
AND DATE_FORMAT(LAST_DAY(CONCAT('202305', '01')),'%Y-%m-%d 23:59:59')
;
value)
1 SIMPLE T2 index IDX_BBB_01 IDX_BBB_01 11 1314006 Using where; Using index
1 SIMPLE T1 eq_ref PRIMARY,IDX_AAA_06 PRIMARY 8 XXX.T2.SEQ_NO 1 Using where
1 SIMPLE T3 ref IDX_CCC_07 IDX_CCC_07 9 XXX.T2.SEQ_NO 1 Using index
# 인덱스 스캔 방법 중 index 란? 인덱스를 처음부터 끝까지 탐색하여 데이터를 찾는 방식 (Index Full scan)
-> index 라고 인덱스 스캔이 잘 된다고 생각하면 안된다 인덱스 스캔을 하는 방식 중에 성능이 매우 떨어지는 방식이다.
update문에서 where 조건절 T1.TB_AAA의 컬럼 CHNG_DTTM은
IDX_AAA_06 이라는 인덱스가 있는데
조건값 '2023-05-01 00:00:00 ~ 2023-05-31 23:59:59' 가 인덱스를 사용할 수 있는 범위에 해당함에도
이것을 옵티마이져가 제대로 활용하지 못하는 것을 알게 되었다.
옵티마이져가 정말 멍청했는지 직접 인덱스를 할당해서 확인해본다.
# TO_BE)
explain
select count(*) from TB_AAA T1 force index (IDX_AAA_06)
INNER JOIN TB_BBB T2
ON T1.SEQ_NO = T2.SEQ_NO
INNER JOIN TB_CCC T3 /* 24GB 파티션 테이블 */
ON T1.SEQ_NO = T3.SEQ_NO
WHERE T1.CHNG_DTTM BETWEEN DATE_FORMAT(CONCAT('202305', '01'),'%Y-%m-%d 00:00:00')
AND DATE_FORMAT(LAST_DAY(CONCAT('202305', '01')),'%Y-%m-%d 23:59:59')
;
value)
1 SIMPLE T1 range IDX_AAA_06 IDX_AAA_06 6 135160 Using index condition
1 SIMPLE T2 ref IDX_BBB_01 IDX_BBB_01 9 XXX.T1.SEQ_NO 1 Using index
1 SIMPLE T3 ref IDX_CCC_07 IDX_CCC_07 9 XXX.T1.SEQ_NO 1 Using index
실행계획으로 보았을 때는 인덱스가 range 스캔으로 풀리는 것으로 보아 더 나은 방식으로 보인다.
하지만 옵티마이져는 최종 sql 실행시 가장 빠른 방식을 스스로 검색해서 실행계획을 세우기 때문에
반드시 위 인덱스 스캔이 더 빠르다고 판단할 수 없다.
실제로 select 문을 실행해 보아야한다.
#1) AS_IS 수행시간 -> 22초
#2) TO_BE 수행시간 -> 16초
음...
실제로 옵티마이져가 제대로 실행계획을 세우지 못한 것을 확인했다.
이번에는 옵티마이져가 영리하지 못했다.
2. 원인분석
그럼 왜 이런 일이 발생한 것일까?
그것은 update를 처리하는 테이블과 join 된 파티션 테이블의 용량이 문제였다
파티션 테이블에 별도의 조건값이 없어 파티션 푸르닝이나
파티션의 인덱스를 제대로 활용하지 못하고
통째로 join을 하다보니
버그인지는 모르겠지만 ( mariadb ver 10.4.18) 옵티마이져가 조건절의 값이 인덱스가 있음에도 제대로 활용하지 못하는 현상이 발생했다.
그럼 24GB나 되는 파티션 테이블을 조인해서 사용도 안하는데
왜 조인했나?
대부분의 화면에서 조회하는 sql은 보통 동적쿼리다.
이것이 DBA 입장에서는 상당히 머리가 아파질 수 있는 부분인데
예를 들어 신규 개발 SQL을 검수할 때 (동적쿼리라면)
서비스환경을 적대적으로 가정하고 그것에 대한 경우의 수를 생각해
실행계획이나 추가인덱스 설정등..SQL을 더 꼼꼼하게 확인해야하는 어려움이 있다.
이번 발생한 슬로우 쿼리 또한
웹페이지에서 조회시 TB_CCC(파티션 테이블)와 관련된 검색조건은 빼고 검색을 해도
조회가 되도록 되어있을 것이다.
3. 해결방법
가장 좋은 해결방법은 TB_CCC(파티션 테이블)에
파티션 푸르닝을 사용할 수 있게 조건값을 추가하거나
아니면 TB_CCC(파티션 테이블)의 용량 자체를 줄여서 옵티마이져가 멍때리지 않고 제대로 역할을 할 수 있게 환경을 만들어 주는 것
여기서 궁금한 게 생겨 테스트를 해봄!
Test)
대용량 테이블(TB_CCC)의 파티션을 삭제하면서 언제쯤 옵티마이져가 정상적으로 조건절의 인덱스 값을 가져다 플랜을 만드는지 확인해 보았다.
월별 파티션을 하나씩 지우면서 플랜을 뜨다보니
TB_CCC의 용량이 24GB에서 22GB로 줄었을 때!
드디어 옵티마이져가 where 조건절의 인덱스 IDX_AAA_06 가져다 실행계획을 세우는 것을 확인함
(아. 그래서 얼마전까지는 발생안했고 이번에 발생했구나...^^;)
explain)
1 SIMPLE T1 range PRIMARY,IDX_AAA_06 IDX_AAA_06 6 134702 Using where; Using index
1 SIMPLE T2 ref IDX_BBB_01 IDX_BBB_01 9 XXX.T1.SEQ_NO 1 Using index
1 SIMPLE T3 ref IDX_CCC_07 IDX_CCC_07 9 XXX.T1.SEQ_NO 1 Using index
TB_CCC(파티션 테이블) 의 조인 컬럼 SEQ_NO 의 인덱스를 메모리에 올려 실행계획을 세울 때
옵티마이져가 판단하는데도 MAX 가 있는 것으로 보임
24GB가 넘어가면서 문제가 생겼는데.. 이것이 22GB 줄었을 때는 옵티마이저가 다시 재정신을 차림
검증은 끝났고
화면에서 파티션 푸르닝 기능을 사용할 수 있는지 개발과 협의해 봐야겠고,
TB_CCC(파티션 테이블)의 데이터 용량은 삭제 주기를 정해서 6개월 이내의 데이터는 삭제하는 것으로 사업부서와 협의해봐야겠다.
force index까지는 사용하지 않고 끝났으면 좋겠다.
4.결론
대용량 파티션 테이블 join 사용법
1) 가능하면 파티션 푸르닝이 포함된 컬럼을 where 조건절에 넣는다.
2) 그것이 안되면 파티션 삭제주기를 정해서 주기적으로 파티션 테이블 용량을 관리한다.
3) 이것도 안될시에는 파티션 테이블을 사용하는 sql을 주기적으로 모니터링하면서 인덱스 스캔이 불가능해지면 forec index로 인덱스를 강제로 할당한다.
#파티션 푸르닝이란? 파티션 프루닝(pruning)은 MySQL 에서 WHEHE 구문에 사용된 조회 조건에 만족한 파티션만 추출하는 기능이다. 최적화 단계에서 필요한 파티션만 골라내고 불필요한 것들은 배제하는 것 입니다. 파티션 프루닝은 SELECT, DELETE, UPDATE 구문에서만 가능합니다.
슬로우 쿼리 로그 파일에는 long_query_time 시스템 변수에 설정한 시간 이상의 시간이 소요된 쿼리가 모두 기록된다. (long_query_time 파라미터는 초단위로 설정하지만 소수점 값으로 설정하면 마이크로 초 단위로 설정 가능함)
ex)
만약 2초이상 걸리는 쿼리를 슬로우쿼리로 보고 파일로 쌓는 구조를 만드려면?
solution)
my.cnf에서 2군데 추가해주면 된다
vi /etc/my.cnf
[mysqld]
slow_query_log_file=/data/mysqldb_logs/slow/mysql-slow-query.log /* 슬로우쿼리가 파일로 들어갈 경로 지정 */
long_query_time=2 /* 몇초 이상의 쿼리를 슬로우 쿼리로 만들지 파라미터 값 지정 */
#슬로우 쿼리 설정여부 확인
mysql> show global variables like 'long_query_time';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 2.000000 |
+-----------------+----------+
1 row in set (0.00 sec)
슬로우 쿼리 로그는 Mysql이 쿼리를 실행한 후, 실제 소요된 시간을 기준으로 슬로우 쿼리 로그에 기록할지 여부를 판단하기 때문에 반드시 쿼리가 정상적으로 실행이 완료되야 슬로우 쿼리로그에 기록될 수 있다.
즉 슬로우 쿼리 록 파일에 기록되는 쿼리는 일단 정상적으로 실행이 완료됐고 실행하는데 걸린 시간이 long_query_time에 정의된 시간보다 많이 걸린 쿼리인 것이다. (ex 장애나서 급하게 kill session_id; 시킨 쿼리는 슬로우 쿼리 로그에 남지 않는다^^;)
log_output 옵션을 이용해서 슬로우 쿼리 로그를 파일로 기록할지 테이블로 기록할지 선택할 수 있다. log_output 옵션을 TABLE로 설정하면 제너럴 로그나 슬로우 쿼리 로그를
mysql DB의 테이블(general_log와 slow_log 테이블)에 저장하며, FILE로 설정하면 로그의 내용을 디스크의 파일로 저장한다.
log_output 옵션을 TABLE로 설정하더라도 mysql DB의 slow_log 테이블과
general_log 테이블은 CSV 스토리지 엔진을 사용하기 때문에 결국 CSV 파일로 저장하는 것과 동일하게 작용한다.
하지만 테이블에 굳이 DB에 슬로우쿼리 로그를 쌓을 이유가 없다
일단 테이블에 쌓는다면 로그를 삭제 할 때도 DB부하가 발생하고
삭제도 마음대로 못함!
그리고 DB부하 발생시 정상적인 쿼리도
처리가 지연되면서 slow query log에 쌓일 텐데 이럴경우 DB 부하가 x2배가 되는 상황을 볼 것이기 때문
괜히 건드리지말고 그냥 default 로 둔다^^
#log_output 옵션 확인
mysql> show global variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output | FILE |
+---------------+-------+
1 row in set (0.00 sec)
2023-01-04 16:14:27 0x7f76a70d3700 InnoDB: Assertion failure in thread 140147585529600 in file trx0trx.ic line 213
InnoDB: Failing assertion: !trx->has_search_latch
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
07:14:27 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
key_buffer_size=33554432
read_buffer_size=2097152
max_used_connections=154
max_threads=1000
thread_count=128
connection_count=128
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 10286111 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x7f73bc69cf00
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f76a70d2e28 thread_stack 0x30000
/data/bin/mysqld(my_print_stacktrace+0x35)[0xf45e05]
/data/bin/mysqld(handle_fatal_signal+0x4a4)[0x7cd464]
/lib64/libpthread.so.0[0x316c40f7e0]
/lib64/libc.so.6(gsignal+0x35)[0x316c0324f5]
/lib64/libc.so.6(abort+0x175)[0x316c033cd5]
/data/bin/mysqld(_Z18ut_print_timestampP8_IO_FILE+0x0)[0x7bc9ce]
/data/bin/mysqld[0x1045499]
/data/bin/mysqld(_Z18close_thread_tableP3THDPP5TABLE+0x288)[0xcc1468]
/data/bin/mysqld(_Z19close_thread_tablesP3THD+0x31b)[0xcc1e6b]
/data/bin/mysqld(_ZN18Prepared_statement7prepareEPKcm+0x728)[0xd3e2f8]
/data/bin/mysqld(_Z19mysqld_stmt_prepareP3THDPKcj+0x106)[0xd3f226]
/data/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xb1d)[0xd18dcd]
/data/bin/mysqld(_Z10do_commandP3THD+0x194)[0xd1a324]
/data/bin/mysqld(handle_connection+0x29c)[0xdea0fc]
/data/bin/mysqld(pfs_spawn_thread+0x174)[0xfbdbf4]
/lib64/libpthread.so.0[0x316c407aa1]
/lib64/libc.so.6(clone+0x6d)[0x316c0e8c4d]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f73bdc4fb10): SELECT DISTINCT CC.* ,
Connection ID (thread ID): 2486689
Status: NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2023-01-04T07:14:27.827525Z mysqld_safe Number of processes running now: 0
2023-01-04T07:14:27.830702Z mysqld_safe mysqld restarted
2023-01-04T16:14:28.009437+09:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2023-01-04T16:14:28.009545+09:00 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2023-01-04T16:14:28.009569+09:00 0 [Note] /data/bin/mysqld (mysqld 5.7.19-log) starting as process 137699 ...
2023-01-04T16:14:28.014665+09:00 0 [Note] InnoDB: PUNCH HOLE support available
2023-01-04T16:14:28.014690+09:00 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2023-01-04T16:14:28.014694+09:00 0 [Note] InnoDB: Uses event mutexes
2023-01-04T16:14:28.014699+09:00 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2023-01-04T16:14:28.014702+09:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2023-01-04T16:14:28.014706+09:00 0 [Note] InnoDB: Using Linux native AIO
2023-01-04T16:14:28.015218+09:00 0 [Note] InnoDB: Number of pools: 1
2023-01-04T16:14:28.015308+09:00 0 [Note] InnoDB: Using CPU crc32 instructions
2023-01-04T16:14:28.017142+09:00 0 [Note] InnoDB: Initializing buffer pool, total size = 96G, instances = 8, chunk size = 128M
2023-01-04T16:14:32.330216+09:00 0 [Note] InnoDB: Completed initialization of buffer pool
2023-01-04T16:14:32.942852+09:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2023-01-04T16:14:32.955591+09:00 0 [Note] InnoDB: Highest supported file format is Barracuda.
2023-01-04T16:14:33.368638+09:00 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 861023653783
2023-01-04T16:14:33.491857+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861028896256
2023-01-04T16:14:33.560747+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861034139136
2023-01-04T16:14:33.634813+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861039382016
2023-01-04T16:14:33.732145+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861044624896
2023-01-04T16:14:33.809235+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861049867776
2023-01-04T16:14:33.882321+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861055110656
2023-01-04T16:14:33.951426+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861060353536
2023-01-04T16:14:34.018926+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861065596416
2023-01-04T16:14:34.087345+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861070839296
2023-01-04T16:14:34.157479+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861076082176
2023-01-04T16:14:34.222135+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861081325056
2023-01-04T16:14:34.289957+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861086567936
2023-01-04T16:14:34.383546+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861091810816
2023-01-04T16:14:34.428047+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861095311315
2023-01-04T16:14:34.428365+09:00 0 [Note] InnoDB: Database was not shutdown normally!
2023-01-04T16:14:34.428373+09:00 0 [Note] InnoDB: Starting crash recovery.
2023-01-04T16:14:34.664412+09:00 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
2023-01-04T16:14:39.164388+09:00 0 [Note] InnoDB: Apply batch completed
2023-01-04T16:14:39.164433+09:00 0 [Note] InnoDB: Last MySQL binlog file position 0 1770351, file name mysql-bin.002910
2023-01-04T16:14:39.376296+09:00 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2023-01-04T16:14:39.376322+09:00 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2023-01-04T16:14:39.376352+09:00 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2023-01-04T16:14:39.380934+09:00 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2023-01-04T16:14:39.381506+09:00 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2023-01-04T16:14:39.381516+09:00 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2023-01-04T16:14:39.382232+09:00 0 [Note] InnoDB: Waiting for purge to start
2023-01-04T16:14:39.432361+09:00 0 [Note] InnoDB: 5.7.19 started; log sequence number 861095311315
2023-01-04T16:14:39.432402+09:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6490ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2023-01-04T16:14:39.433144+09:00 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysqldb_data/ib_buffer_pool
2023-01-04T16:14:39.441399+09:00 0 [ERROR] Function 'federated' already exists
2023-01-04T16:14:39.441413+09:00 0 [Warning] Couldn't load plugin named 'federated' with soname 'ha_federated.so'.
2023-01-04T16:14:39.441750+09:00 0 [Note] Recovering after a crash using /data/mysqldb_logs/binary/mysql-bin
2023-01-04T16:14:39.447539+09:00 0 [Note] Starting crash recovery...
2023-01-04T16:14:39.447569+09:00 0 [Note] Crash recovery finished.
2023-01-04T16:14:39.453180+09:00 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2023-01-04T16:14:39.453197+09:00 0 [Note] Server hostname (bind-address): '*'; port: 3306
2023-01-04T16:14:39.453246+09:00 0 [Note] IPv6 is available.
2023-01-04T16:14:39.453257+09:00 0 [Note] - '::' resolves to '::';
2023-01-04T16:14:39.453273+09:00 0 [Note] Server socket created on IP: '::'.
2023-01-04T16:14:39.475051+09:00 0 [Note] Event Scheduler: Loaded 0 events
2023-01-04T16:14:39.475194+09:00 0 [Note] /data/bin/mysqld: ready for connections.
Version: '5.7.19-log' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)
2023-01-04T16:14:39.475230+09:00 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check.
2023-01-04T16:14:39.475234+09:00 0 [Note] Beginning of list of non-natively partitioned tables
2023-01-04T16:14:39.523762+09:00 0 [Note] End of list of non-natively partitioned tables
2023-01-04T16:15:27.809630+09:00 148 [Note] Start binlog_dump to master_thread_id(148) slave_server(101), pos(mysql-bin.002910, 1792665)
1. mysql.error 로그 분석
이 로그는 InnoDB 스토리지 엔진의 어설션 오류로 인해 2023년 1월 4일 07:14:27 UTC에 MySQL 서버 프로세스가 중단된 것을 보여줍니다 로그는 파일 trx0trx.ic의 line 213의 스레드 140147585529600에서 어설션 오류가 발생했으며 어설션 오류는 !trx-> has_search_latch였습니다. 트랜잭션에 검색 래치가 있기 때문에 어설션에 실패했습니다.
개발파트에서 확인 실제 xml을 보니 실제 이런 구문은 없었고.. 뭔가 부등호가 지맘대로 거기 들어가 붙어있었다
(부등호의 순간이동;;)
원인을 찾아보니 mybatis 를 사용 중인데 수식에 부등호를 쓰면서 (<![CDATA[ ]]>) 처리하지 않고 그대로 사용한 것으로 확인했다.
(<![CDATA[ ]]>) 쓰지 않을거면
< 부등호(<) > 부등호(>)
로 치환해서 써야하는데 그렇게 사용하지 않아서 이상한 쿼리를 끝내지 못하고 결국 프로세스를 재시작하면서 DB가 재시작된 것이다.
근데 저대로면 빌드가 안 되었을텐데... 어떻게 빌드된 파일로 올라갔을까?
(실제로 개발에서 테스트 했을 때도 빌드에러남ㅋㅋ)
3. 해결
문제가 된 query의 부등호 사용 부분을 아래처럼
<![CDATA[
쿼리 내용
]]>
CDATA로 감싸서 처리하고 현재까지 DB 재시작이슈는 발생하지 않았다.
그리고 이번에 발생한 CDATA 이슈에 관해 간략하게 정리한다.
4. CDATA 사용관련 내용정리
MyBatis 사용 시 쿼리문에 비교 연산자와 같이 부등호 처리가 필요할 때가 있다. 하지만 비교 연산자를 사용했을 경우 error를 발생시키는데 그 이유는 비교 연산자인지 괄호인지 구분하지 못하기 때문이다.
비교 연산자를 사용했을 때 MyBatis는 괄호인지 비교 연산자인지 구분하지 못한다. 이런 경우에 CDATA를 사용하면 CDATA 안에 들어가는 문장을 문자열로 인식해 구분할 수 있도록 도와준다.
1) CDATA란?
- (Unparsed) Character Data. 다시말하면 파싱하지 않는 문자 데이터 라는 뜻이다. 파싱하는 문자데이터는 PCDATA 라고 부름
2) CDATA를 사용하는 이유?
CDATA 안에 쿼리를 사용하면쿼리 내용의 괄호나 특수문자를 XML parser로 인식하지 않고 "문자열"로 인식한다
쿼리를 작성할 때, '<', '>', '&'를 사용해야하는 경우가 생기는데 xml에서 그냥 사용할 경우 태그로 인식하는 경우가 종종 있다. 이럴 경우 에러를 뱉어내기 때문에 '태그가 아니라 실제 쿼리에 필요한 코드'라고 알려줘야 한다. 그때 사용하는 것이 <![CDATA[...]]> 이다.
한 마디로 <>(부등호),&(앤드),||(오아) 등을 닫는 부등호가 아니라 문자열로 처리하라는 뜻입니다. 어렵게 말하자면 "XML parser"를 하지 말아라
3) CDATA 사용방법
<![CDATA[
쿼리 내용
]]>
4) CDATA를 안 쓸 때 부등호 처리
” ” : 공백(스페이스 한 칸)을 의미
<
부등호(<)
>
부등호(>)
&
앰퍼샌드(&) 기호
"
쌍따옴표(“)
#
sharp(#)
'
따옴표(‘)
(< 는 Less Than (<, 보다 작은) , > 는 Greater Than (>, 보다 큰) 의 약자라고 한다.)
관련 테이블의 LOCK 까지 발생하여 확인해보니 name_const()로 변환되는 부분에서 문제가 있는 것을 확인하였다.
해결과정까지 가는 건 많은 시간이 소요되었지만 결국 답을 찾았고 관련 기록을 정리한다.
DB ver: mysql 5.7.1x
1. 장애프로시저 확인
CREATE PROCEDURE `xxxx`.`SP_xxxx_LIST`(
in VAR_DATE VARCHAR(20)
)
BEGIN
DECLARE varMonth varchar(6);
set varMonth = DATE_FORMAT(date_sub(now(),interval +1 MONTH),'%Y%m');
update TB_TEMP_TABLE
SET RCP_DT = CDP_DT
where TG_YYMM = varMonth
and CAST_CD in ('xxx','xxx')
and LENGTH(RCP_DT) !=8;
........
2. 원인분석
mysql > show full processlist;
/* 프로시저 중간에 이 부분에서 지연이 발생함을 확인함 */
| 591165 | xxxxadm | 192.168.141.202:49131 | xxxx | Query | 3638 | Updating | update TB_TEMP_TABLE
SET RCP_DT = CDP_DT
where TG_YYMM = NAME_CONST('varMonth',_utf8mb4'202212' COLLATE 'utf8mb4_unicode_ci')
and CAST_CD in ('xxx','xxx')
and LENGTH(RCP_DT) !=8 | 0.000 |
#1. 실행계획 확인
explain
select * from TB_TEMP_TABLE
where TG_YYMM = NAME_CONST('varMonth',_utf8mb4'202212' COLLATE 'utf8mb4_unicode_ci')
and CAST_CD in ('xxx','xxx')
and LENGTH(RCP_DT) !=8;
#result)
1 SIMPLE TB_TEMP_TABLE range IDX_TEMP_TABLE_06 IDX_TEMP_TABLE_06 18 99890358 Using where
TB_TEMP_TABLE 테이블은 대용량 파티션 테이블로 약 80GB 정도의 용량을 갖고 있다. TG_YYMM = '202212' 값이 내부 함수인 NAME_CONST('varMonth',_utf8mb4'202212' COLLATE 'utf8mb4_unicode_ci')에 의해 자동으로 묶였는데 이 부분에서 인덱스 사용을 못하고 있다.
#2. 인덱스가 깨졌는지 확인
explain
select * from TB_TEMP_TABLE
where TG_YYMM = '202212'
and CAST_CD in ('xxx','xxx')
and LENGTH(RCP_DT) !=8;
#result)
1 SIMPLE TB_TEMP_TABLE ref IDX_TEMP_TABLE_04,IDX_TEMP_TABLE_06 IDX_TEMP_TABLE_04 21 const 4752697 Using where
직접 값을 입력했을시 정상적으로 TG_YYMM의 ref 인덱스를 사용하는 것을 확인함, 인덱스는 정상이다.
#3. 실행엔진이 간혹 잘못된 PLAN을 세울수도 있기때문에 인덱스를 강제로 할당테스트
explain
select * from TB_TEMP_TABLE force index (IDX_TEMP_TABLE_04)
where TG_YYMM = NAME_CONST('varMonth',_utf8mb4'202212' COLLATE 'utf8mb4_unicode_ci')
and CAST_CD in ('xxx','xxx')
and LENGTH(RCP_DT) !=8;
#result)
1 SIMPLE TB_TEMP_TABLE ALL 198699556 Using where
실행엔진이 문제인가 싶어 force 인덱스로 강제로 주었는데 아에 full scan해서 쿼리가 끝나지 않음
실행엔진이 멍청한 것도 아니다!
#4. 확인결과
인덱스는 문제없고 procedure내에서 선언한 varchar 타입인 '202212' 값이 NAME_CONST() 로 내부함수로 자동변환해서 읽히는데 이 부분에서 왜 인덱스가 안 타는지 좀 더 확인필요!
3. 해결과정
일단 name_const() 함수에 대해 알아본다.
#1) name_const 함수란?
NAME_CONST( name , value ) 지정된 값을 반환합니다. 결과 집합의 열을 생성 할 때 NAME_CONST() 을 사용하면 지정된 이름이 컬럼에 지정됩니다. 결과 집합 열을 생성하는데 사용하면 NAME_CONST()열이 지정된 이름을 갖게 됩니다. 인수는 상수여야 합니다.
#ex)
mysql> SELECT NAME_CONST('myname', 14);
+--------+
| myname |
+--------+
| 14 |
+--------+
1 row in set (0.00 sec)
같은 의미로 쿼리 안에서 AS 로 컬럼의 닉네임을 거는 것과 동일하다.
mysql> SELECT 14 AS myname;
+--------+
| myname |
+--------+
| 14 |
+--------+
1 row in set (0.00 sec)
이 함수는 저장 프로시저를 복제할 때 내부적으로 사용됩니다. SQL 문에서 명시적으로 사용하는 것은 거의 의미가 없으며 그렇게 사용해서는 안됩니다.
ex) SELECT NAME_CONST('myname', 14) --> name_const() 함수는 mysql 내부에서 사용하는 것으로 user가 굳이 사용할 필요없다는 것
#name_const() 에서 name은 알겠는데 value는 왜 아래처럼 들어가는 것인가?
A character string literal may have an optional character set introducer and COLLATE clause, to designate it as a string that uses a particular character set and collation:
문자열 리터럴 COLLATE에는 특정 문자 집합과 데이터 정렬을 사용하는 문자열로 지정하기 위해 선택적인 문자 집합 소개자와 절이 있을 수 있습니다.
#question) Recently I noticed few queries are taking very long time in execution, checked further and found that MySQL Optimizer is trying to use COLLATE in Where clause and that's causing performance issue, if I run below query without COLLATE then getting quick response from database:
최근 몇 가지 쿼리가 실행에 매우 오랜 시간이 걸리는 것을 확인하고 추가로 확인한 결과 MySQL Optimizer가 Where절에서 COLLATE를 사용하려고 시도하고 있으며 COLLATE 없이 쿼리 아래에서 실행하면 데이터베이스에서 빠른 응답을 받으면 성능 문제가
발생한다는 것을 발견했습니다.
SELECT notification_id FROM notification
WHERE ref_table = 2
AND ref_id = NAME_CONST('v_wall_detail_id',_utf8mb4'c37e32fc-b3b5-11ec-befc-02447a44a47c' COLLATE 'utf8mb4_unicode_ci')
..
Any suggestion, what improvements are needed to make my queries faster? 쿼리 속도를 높이려면 어떤 개선이 필요합니까?
#answer) The table's character set is utf8, so I guess its collation is one of utf8_general_ci or utf8_unicode_ci. 테이블의 문자 집합이 utf8이므로 데이터 정렬이 utf8_general_ci 또는 utf8_unicode_ci 중 하나인 것 같습니다.
You can check this way: 다음과 같이 확인할 수 있습니다.
SELECT collation_name from INFORMATION_SCHEMA.COLUMNS
WHERE table_schema = '...your schema...' AND table_name = 'notification'
AND column_name = 'ref_id';
You are forcing it to compare to a string with a utf8mb4 charset and collation.
An index is a sorted data structure, and the sort order depends on the collation of the column. Using that index means taking advantage of the sort order to look up values rapidly, without examining every row.
When you compared the column to a string with a different collation, MySQL cannot infer that the sort order or string equivalence of your UUID constant is compatible. So it must do string comparison the hard way, row by row.
This is not a bug, this is the intended way for collations to work. To take advantage of the index, you must compare to a string with a compatible collation.
utf8mb4 문자 세트 및 데이터 정렬이 있는 문자열과 비교하도록 강제하고 있습니다. 인덱스는 정렬된 데이터 구조이며 정렬 순서는 열의 데이터 정렬에 따라 다릅니다. 해당 인덱스를 사용한다는 것은 정렬 순서를 활용하여 모든 행을 검사하지 않고 빠르게 값을 조회한다는 의미입니다.
열을 데이터 정렬이 다른 문자열과 비교할 때 MySQL은 정렬 순서 또는 UUID 상수의 문자열 등가가 호환 가능하다고 추론할 수 없습니다. 따라서 문자열 비교를 row 단위의 어려운 방식으로 수행해야 합니다.
이것은 버그가 아니며 데이터 정렬이 작동하도록 의도된 방식입니다. 인덱스를 활용하려면 호환되는 데이터 정렬이 있는 문자열과 비교해야 합니다.
# 1) mysql 의 default character set , cllation 확인 (my.cnf 설정)
mysql> show global variables like '%coll%';
+----------------------+--------------------+
| Variable_name | Value |
+----------------------+--------------------+
| collation_connection | utf8mb4_unicode_ci |
| collation_database | utf8mb4_unicode_ci |
| collation_server | utf8mb4_unicode_ci |
+----------------------+--------------------+
3 rows in set (0.00 sec)
mysql> show global variables like '%char%';
+--------------------------+----------------------------------------------------------+
| Variable_name | Value |
+--------------------------+----------------------------------------------------------+
| character_set_client | utf8mb4 |
| character_set_connection | utf8mb4 |
| character_set_database | utf8mb4 |
| character_set_filesystem | binary |
| character_set_results | utf8mb4 |
| character_set_server | utf8mb4 |
| character_set_system | utf8 ||
+--------------------------+----------------------------------------------------------+
8 rows in set (0.00 sec)
#2) 컬럼 타입 확인
SELECT
CHARACTER_SET_NAME
,COLLATION_NAME
FROM INFORMATION_SCHEMA.`COLUMNS`
WHERE TABLE_NAME = 'TB_TEMP_TABLE'
and COLUMN_NAME = 'TG_YYMM';
----------------------------
utf8 | utf8_general_ci |
----------------------------
빙고!
4. 해결
원인은 TG_YYMM 컬럼은 character set = utf8이고
mysql 의 my.cnf / default character set = utf8mb4 이 차이가 있어서 발생하였다.
프로시저 내에서 선언한 varMonth varchar(6)은 당연히 mysql default 케릭터셋인 utf8mb4 를 쓰고 있다.
where 절에서
utf8 = utf8mb4 를 비교하니
mysql에서
야! varMonth 변수 이거 utf8 아니고 utf8mb4 이야 ."라고
name_const() 함수를 통해 알려주고 있었고
"이러면 인덱스 못쓴다.!" 라고
show processlist를 통해 한번 더 알려주고 있었는데
의미를 제대로 알지 못함..^^;
#수정방법은 2가지고 성능은 1번이 조금 더 좋다.
(내부 함수라도 함수를 한번 덜써서 그런것으로 보임)
1) varMonth 선언할 때 TG_YYMM 컬럼과 동일한 character set 으로 변경
/* DECLARE varMonth varchar(6) 를 아래처럼 utf8로 명시적으로 선언*/
DECLARE varMonth varchar(6) CHARACTER SET utf8 COLLATE utf8_general_ci;
#log)
mysql> show full processlist;
update TB_TEMP_TABLE
SET RCP_DT = CDP_DT
where TG_YYMM = NAME_CONST('varMonth',_utf8'202212' COLLATE 'utf8_general_ci')
and CAST_CD in ('xxx','xxx')
and LENGTH(RCP_DT) !=8;
#실행계획
-> NAME_CONST()를 쓰지만 동일한 utf8이기 때문에 ref 인덱스 스캔을 한다.
2) query 문 안에서 수정
update TB_TEMP_TABLE
SET RCP_DT = CDP_DT
where TG_YYMM = CONVERT(varMonth USING utf8)
and CAST_CD in ('xxx','xxx')
and LENGTH(RCP_DT) !=8;
#log)
mysql> show full processlist;
update TB_TEMP_TABLE
SET RCP_DT = CDP_DT
where TG_YYMM = CONVERT( NAME_CONST('varMonth',_utf8mb4'202212' COLLATE 'utf8mb4_unicode_ci') USING utf8)
and CAST_CD in ('xxx','xxx')
and LENGTH(RCP_DT) !=8
#실행계획
-> NAME_CONST( _utf8mb4 를 쓰지만 다시 convert 함수로 utf8로 변경해서 결국 ref 인덱스 스캔이 된다.
show processlist로 세션 로그를 보면 mysqldump 를 처리하려고 Sending data | SELECT /*!40001 SQL_NO_CACHE */ xxxx, xxxx, xxxxx, xxxx, xxxx ~ 를 수행하자 아래로 백업테이블의 DML query가 전부 LOCK 이걸리는 것을 확인할 수 있다. (insert 와 update 에서 Waiting for table metadata lock)
이것을 모르고 그냥 둔다면 수초 내로 세션이 늘어나면서 DB 세션이 MAX까지 찰것이고, 결국엔 메모리 부족으로 DB가 죽을 수도 있고, 버틴다면 too many connection 에러를 보고 서비스 접속이 어려워질 수 있다.
서비스 DB에서는 굳이 mysqldump를 안하면 제일 좋긴한데 ... 어쩔 수없이 테이블 백업이 필요한 경우라면?
2. LOCK 없이 백업방법
1) 트랜잭션 옵션 --single-transaction 적용방법
innoDB 엔진일 때만 사용가능하다. 이 옵션을 지정하면 백업 대상 MYSQL 서버에 백업을 위해 접속한 세션의 트랜잭션 격리 수준을 REPEATABLE READ 로 변경하고, 백업 시작 직전에 START TRANSACTION 명령을 실행한 뒤 백업을 진행한다. 이 옵션을 이용하면 백업을 수행할 때 InnoDB 스토리지 엔진과 같이 트랜잭션을 지원하는 스토리지 엔진을 사용하는 테이블에 대해서는 START TRANSACTION 구문이 실행된 시점의 일관된 데이터를 백업할 수 있다. (MyISAM 엔진 테이블에서는 사용 x)
이 옵션을 이용해 백업을 수행할 때는 다른 세션에서는 DDL 명령을 실행해서는 안된다. 큰 테이블을 백업해야 한다면 --single-transaction 과 --quick 옵션을 함께 사용하는 것을 권장
#1-1) 대용량 테이블 백업시 --quick 성능 관련 옵션추가 백업 대상 데이터베이스에서 백업할 행 데이터 전체를 한 번에 읽어서 백업한다. 만일 이 옵션을 사용하지 않는다면 행데이터를 백업 파일에 기록하기 전에 메모리에 먼저 버퍼링하고 백업이 수행되므로 백업 소요 시간이 길어질 수 있다. 그러므로 이 옵션은 백업 대상 테이블 크기가 클 때 유용하게 사용.
함수나 프로시저를 실행하는 명령어였다. (그럼 특정테이블에 EXECUTE 권한 넣는 것은 당연히 안되는 것)
그렇다면 특정함수만 권한넣을 수 있는지와 전역권한이라니까
2가지를 한번 테스트 해본다.
테스트시작)
1. 특정테이블에 권한 추가
mysql> GRANT SELECT, INSERT, UPDATE, DELETE, CREATE, DROP, INDEX, ALTER, EXECUTE ON xxxxDB.TB_TEMP_BACKUP TO 'testapp'@'%';
ERROR 1144 (42000): Illegal GRANT/REVOKE command; please consult the manual to see which privileges can be used
/* EXECUTE 때문에 안됨
xxxxDB.TB_TEMP_BACKUP (DB스키마명.테이블명)
*/
mysql> GRANT SELECT, INSERT, UPDATE, DELETE, CREATE, DROP, INDEX, ALTER ON xxxxDB.TB_TEMP_BACKUP to 'testapp'@'%';
Query OK, 0 rows affected (0.04 sec)
mysql> flush privileges;
Query OK, 0 rows affected (0.04 sec)
/* EXECUTE 빼고는 특정테이블에 권한할당이 가능한 것을 확인함 */
2. EXECUTE 권한 테스트
2-1) 특정 함수에 권한 추가
mysql> GRANT EXECUTE ON xxxxDB.fn_xxxxxxxx to 'testapp'@'%';
ERROR 1144 (42000): Illegal GRANT/REVOKE command; please consult the manual to see which privileges can be used
/* 함수인데 왜 할당이 안되는것일까? */
mysql> GRANT EXECUTE ON FUNCTION xxxxDB.fn_xxxxxxxx to 'testapp'@'%';
Query OK, 0 rows affected (0.03 sec)
/* 실행대상이 ON FUNCTION 임을 명시해줘야 함 */
mysql> flush privileges;
Query OK, 0 rows affected (0.03 sec)
2-2) 전역권한 추가
mysql> GRANT EXECUTE ON xxxxDB.* to 'testapp'@'%';
Query OK, 0 rows affected (0.04 sec)
/* 전역권한이라 DB스키마명만 명시하고 나머지를 *로 주면 권한추가가 가능하다는 것을 확인함 */
mysql> flush privileges;
Query OK, 0 rows affected (0.04 sec)
데이터 타입을 선언할 때 int, bigint가 뭔지는 알겠는데 뒤에 () 괄호에 대해 애매하다는 얘기가 있어서 이번에 정리한다.
1. 결론
()는 자리수를 선언하는 것이다. (10)이면 10자리, (20)이면 20자리까지 넣겠다는 의미 하지만 int나 bigint에서 괄호 ()안에 숫자는 Zerofill 이라는 옵션을 추가로 사용할 때만 의미가 있고 그것이 아니라면 큰 의미없다.
2. 이유
괄호안의 숫자는 디스플레이 너비 속성 display width attribute 즉, 자릿수를 나타내는데 zorefill 속성을 사용할 경우 자릿수 만큼 유효숫자 0을 채우는 것이다. 자릿수를 지정하지 않았을 경우에는 INT의 기본값은 11, BIGINT의 기본값은 20으로 자릿수가 자동 설정된다.
예컨대 INT(3)으로 zerofill속성을 사용해 id컬럼을 생성하면
id값으로 1, 2, 3, … 998, 999, 1000, 1001을 저장했을 때,
데이터베이스에는 001, 002, 003, … 998, 999, 1000, 1001로 기록이 된다.
즉, 숫자형뒤의 괄호안의 숫자만큼 자릿수에 유효숫자가 채워진다. 그리고 괄호안의 숫자를 넘는 자릿수의 수에 대해서는 상관없이 기록이되고, 숫자형이 허용하는 범위까지 값을 저장할 수 있다.
헷갈리면 안되는 것이 괄호안의 숫자가 자릿수를 규정하는 것은 아니라는 것이다. 즉, zerofill 속성을 사용하지 않는 경우라면 괄호안의 숫자는 의미가 없다. 그리고 zerofill 속성을 사용하는 것은 양수에만 가능하므로, 자동으로 unsigned속성이 적용된다.
3. 테스트
괄호안에 별다른 선언을 하지 않으면 default가 int(11), bigint(20)이 된다고 한다. 그럼 만약 int(11)을 초과해서 int(20)을 선언한다면 이것은 문제가 될까?
#테이블 생성
CREATE TABLE TMP_LOAD_20220816 (
x INT(20) NOT NULL,
y INT(20) ZEROFILL NOT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COMMENT='zerofill 테스트';
#데이터 insert
INSERT INTO TMP_LOAD_20220816 (x,y) VALUES
(1, 1),
(12, 12),
(123, 123),
(1234, 1234),
(123456789, 123456789);
commit;
#데이터 확인
SELECT x, y FROM TMP_LOAD_20220816;
result)
-> int(20)으로 선언한 대로라면 00000000000123456789 이렇게 출력될것이라고 생각했지만 int의 최대허용범위는 10자리이므로 그 이상은 출력하지 않았다.
별의미가 없다.
#번외 테스트
#int형 최대치로 넣어보기
INSERT INTO TMP_LOAD_20220816 (x,y) VALUES
(2147483647, 4294967295);
commit;
SELECT x, y FROM TMP_LOAD_20220816;
result)
-> zerofill 일때 unsigned로 자동변환이라고 하여 실제로 값을 넣어보니
최대허용치 4294967295 까지 insert 되는것을 확인함
# unsigned 최대치에서 1만 더 올려볼까? 4294967295-> 4294967296
INSERT INTO TMP_LOAD_20220816 (x,y) VALUES
(2147483647, 4294967296);
SQL Error [1264] [22001]: Data truncation: Out of range value for column 'y' at row 1
Data truncation: Out of range value for column 'y' at row 1
Data truncation: Out of range value for column 'y' at row 1
컬럼에 약 43억 이상의 수가 들어간다면 int보단 bigint를 선언하는 것이 좋겠다.
# 큰의미는 없지만 int(10) vs int(11) 보통 혼용하는데 둘 중 뭘 써야할까?
-> 괄호 ()에 아무런 선언을 하지 않으면 mysql default 옵션은 int(11) 이다.
#int는 10자리로 알고있는데 왜 default는 11자리 일까? -> 음수까지 표현하기 위함
mysql 8.0.17부터 Zerofill 속성은 사용되지 않는다 zerofill속성이 제외되면 LPAD()함수를 사용하여 원하는 자릿수만큼 0으로 채우거나, 형식이 지정된 숫자를 CHAR형 컬럼에 저장하면 된다. 혼란만 가중시키는 옵션이라 걍 제거하고 LPAD() 함수 쓰도록 유도하는 것으로 보인다.
