500 잘못된 검사 방법 [DB Lock 편]
최근 일부 API에 500개가 나왔는데 오늘은 날씨가 맑아서 원인을 확인할 수 있어서 그곳에 가는 과정을 적어 보려고 합니다.
※ DB의 Lock 때문에 제목이 스포일러되었습니다.
계기
모니터링 및 사용자의 문의를 통해 특정 API가 HTTP 응답 코드에서 500을 반환한 것 같습니다.
그러나 이 API 자체가 로그를 남기지 않는 등 어디서 어떤 이유로 500이 됐는지 알 수 없다.
1) 먼저 구하다
1단계에서는 우선 다른 처리를 통해 다시 시도하여 구한다.
2) 먼저 오류 확인
FW 출력의 로그와 가져온 새 버전은 어느 정도 원인을 축소시켰다.
FW 로그
ERROR - 2019-06-07 02:19:37 --> Query error: Lock wait timeout exceeded; try restarting transaction
New Relic
APM > 해당 어플리케이션 > EVENTS-Errors
이 메시지의 링크에서 실제 노드가 접근 로그와 일치하는 것을 발견했습니다.
이 밖에 우리는 특정한 처리가 아닌 공공 부분 (insert 장소) 에서 오류가 발생했다는 것을 확보했다.
3) 원인 조사
정기적으로 showprocesslist를 저장하지만 이것만으로는 목표 잠금과 주 잠금을 정확하게 확정할 수 없기 때문에 잠시 다음 처리를 썼습니다.
※ 지금 생각해보면 책상 두 개가 함께 있으면 좋겠다
investigation.sh#!/bin/bash -u
while [ 1 ]; do
mysql --default-character-set=utf8 --verbose \
-h <endpoint> \
-u <user> -p<pass> -D information_schema \
-e"set session time_zone = 'asia/tokyo'; select now(); select * from innodb_trx\G select * from innodb_lock_waits; select now();" >> /path/to/log/$( date +%Y%m%d_investigation.log )
sleep 300
done
나는 줄곧 이 처리에서 기록을 얻으려고 했지만, 떨어질 때를 고려하여cron은 다음과 같이 설정했다.flock --timeout=1flock을 사용하는ver는 0의 설정을 지원하지 않기 때문에 다중 시작을 간단하게 억제하기 위해 사용됩니다.
crontab*/5 * * * * flock --timeout=1 /path/to/lock /path/to/script/investigation.sh
4) 질의 확인
레코드
다음 로그를 받았습니다:.--------------
set session time_zone = 'asia/tokyo'
--------------
--------------
select now()
--------------
now()
2019-06-07 11:42:35
--------------
select * from innodb_trx
--------------
*************************** 1. row ***************************
trx_id: 25511719128
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719128:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4979812
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 2. row ***************************
trx_id: 25511719119
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719119:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4980011
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 3. row ***************************
trx_id: 25511719100
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719100:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4979976
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 4. row ***************************
trx_id: 25511719086
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719086:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4979714
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 5. row ***************************
trx_id: 25511716742
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:08
trx_requested_lock_id: 25511716742:44:952896:791
trx_wait_started: 2019-06-07 02:42:08
trx_weight: 3
trx_mysql_thread_id: 4979817
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 6. row ***************************
trx_id: 25511667859
trx_state: RUNNING
trx_started: 2019-06-07 02:40:38
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 557234
trx_mysql_thread_id: 4974505
trx_query: delete from table_A where a_date < DATE_ADD(NOW(),INTERVAL -180 DAY) and status = 1 order by id limit 500
trx_operation_state: fetching rows
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 556894
trx_lock_memory_bytes: 376
trx_rows_locked: 49379043
trx_rows_modified: 340
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
--------------
select * from innodb_lock_waits
--------------
requesting_trx_id requested_lock_id blocking_trx_id blocking_lock_id
25511719128 25511719128:44:952896:791 25511667859 25511667859:44:952896:791
25511719119 25511719119:44:952896:791 25511667859 25511667859:44:952896:791
25511719100 25511719100:44:952896:791 25511667859 25511667859:44:952896:791
25511719086 25511719086:44:952896:791 25511667859 25511667859:44:952896:791
25511716742 25511716742:44:952896:791 25511667859 25511667859:44:952896:791
--------------
select now()
--------------
now()
2019-06-07 11:42:35
질의 확인
innodb_lock_waits 방면에서 잠금을 요청한 사무는 모두 5개다.
트랜잭션 ID
#!/bin/bash -u
while [ 1 ]; do
mysql --default-character-set=utf8 --verbose \
-h <endpoint> \
-u <user> -p<pass> -D information_schema \
-e"set session time_zone = 'asia/tokyo'; select now(); select * from innodb_trx\G select * from innodb_lock_waits; select now();" >> /path/to/log/$( date +%Y%m%d_investigation.log )
sleep 300
done
*/5 * * * * flock --timeout=1 /path/to/lock /path/to/script/investigation.sh
--------------
set session time_zone = 'asia/tokyo'
--------------
--------------
select now()
--------------
now()
2019-06-07 11:42:35
--------------
select * from innodb_trx
--------------
*************************** 1. row ***************************
trx_id: 25511719128
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719128:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4979812
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 2. row ***************************
trx_id: 25511719119
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719119:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4980011
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 3. row ***************************
trx_id: 25511719100
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719100:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4979976
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 4. row ***************************
trx_id: 25511719086
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719086:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4979714
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 5. row ***************************
trx_id: 25511716742
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:08
trx_requested_lock_id: 25511716742:44:952896:791
trx_wait_started: 2019-06-07 02:42:08
trx_weight: 3
trx_mysql_thread_id: 4979817
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 6. row ***************************
trx_id: 25511667859
trx_state: RUNNING
trx_started: 2019-06-07 02:40:38
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 557234
trx_mysql_thread_id: 4974505
trx_query: delete from table_A where a_date < DATE_ADD(NOW(),INTERVAL -180 DAY) and status = 1 order by id limit 500
trx_operation_state: fetching rows
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 556894
trx_lock_memory_bytes: 376
trx_rows_locked: 49379043
trx_rows_modified: 340
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
--------------
select * from innodb_lock_waits
--------------
requesting_trx_id requested_lock_id blocking_trx_id blocking_lock_id
25511719128 25511719128:44:952896:791 25511667859 25511667859:44:952896:791
25511719119 25511719119:44:952896:791 25511667859 25511667859:44:952896:791
25511719100 25511719100:44:952896:791 25511667859 25511667859:44:952896:791
25511719086 25511719086:44:952896:791 25511667859 25511667859:44:952896:791
25511716742 25511716742:44:952896:791 25511667859 25511667859:44:952896:791
--------------
select now()
--------------
now()
2019-06-07 11:42:35
innodb_trx쪽에서 보면 기다리는 쪽은 모두insert, 막는 쪽은 delete이다.불필요한 데이터를 삭제하고 전체적인 처리를 줄여서 필요한 데이터의 로그인을 막다니...
5) 수정
아직 완성되지는 않았지만 삭제 조회를 보낸 측의 처리를 어떻게 처리하는가는 가능하다.
부기
검색을 삭제하는 데 explain을 찾으면 대체적으로 색인을 사용하기 때문에 왜 잠겼을까 생각합니다. 아마도 이 근처의 행동일 것입니다.
Conclusion
Reference
이 문제에 관하여(500 잘못된 검사 방법 [DB Lock 편]), 우리는 이곳에서 더 많은 자료를 발견하고 링크를 클릭하여 보았다 https://qiita.com/terra_yucco/items/095af445637921e340ec텍스트를 자유롭게 공유하거나 복사할 수 있습니다.하지만 이 문서의 URL은 참조 URL로 남겨 두십시오.
우수한 개발자 콘텐츠 발견에 전념
(Collection and Share based on the CC Protocol.)
좋은 웹페이지 즐겨찾기
