[MySQL] MySQL 오류 로그 이해

[MySQL] MySQL 오류 로그 이해

 

l  Version : MySQL

 

시스템을 운영할 때, 오류를 완벽히 피하기는 거의 불가능에 가깝다고 생각한다. 그렇다면 문제가 발생하였을 때, 문제의 원인을 빠르게 파악하고 해결하기 위해서 가장 먼저 하는 행동은 무엇일까? 정답은 각종 로그를 확인하는 것이다. 이번 포스트에서는 MySQL 오류 로그를 통해 어떠한 정보를 확인할 수 있는지 알아본다. 이 글에서는 오류 로그는 5.6버전을 설명하고 있지만, 이후 버전에서도 충분히 활용할 수 있다고 판단된다. 모든 오류 내용을 다루지는 않지만 예제에서 확인할 수 있는 몇 가지 정보를 공유한다.

 

MySQL 오류 로그에는 MySQL 상태 및 활동과 관련한 다양한 정보가 기록되어 있다. 정상적인 MySQL 시작, 종료에 대한 기록 및 운영 중에 발생하는 오류들, 그리고 설정 문제로 인한 오류 등 다양한 문제에 대한 정보를 포함하고 있다.

 

MySQL오류 로그는 일반적은 경우 아래 위치에 기록된다.

/var/log/mysql/error.log

 

만약 해당 위치에 로그 파일이 없다면 my.cnf 에서 log_error 파라메터의 정의된 위치에서 오류 로그가 기록되는 것을 확인할 수 있다.

 

[Error log on MySQL – clean startup and shutdown]

MySQL의 클린 스타트가 어떻게 시작되는지 알아본다. 정상적인 상태를 알고 있다면, 나중에 이상징후가 있을 때 좀 더 쉽게 문제를 찾을 수 있다. MySQL이 시작될 때 처음에는 모든 플러그인이 시작된다. 잘못된 경우 이 단계에서 오류가 표시된다.

2015-10-26 19:35:20 13762 [Note] Plugin 'FEDERATED' is disabled.

 

다음으로 InnoDB 초기화와 관련된 중요한 부분을 볼 수 있다.

2015-10-26 19:35:20 13762 [Note] InnoDB: Using atomics to ref count buffer pool pages 2015-10-26 19:35:20 13762 [Note] InnoDB: The InnoDB memory heap is disabled 2015-10-26 19:35:20 13762 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-10-26 19:35:20 13762 [Note] InnoDB: Memory barrier is not used 2015-10-26 19:35:20 13762 [Note] InnoDB: Compressed tables use zlib 1.2.8 2015-10-26 19:35:20 13762 [Note] InnoDB: Using Linux native AIO 2015-10-26 19:35:20 13762 [Note] InnoDB: Using CPU crc32 instructions 2015-10-26 19:35:20 13762 [Note] InnoDB: Initializing buffer pool, size = 512.0M 2015-10-26 19:35:21 13762 [Note] InnoDB: Completed initialization of buffer pool 2015-10-26 19:35:21 13762 [Note] InnoDB: Highest supported file format is Barracuda. 2015-10-26 19:35:21 13762 [Note] InnoDB: 128 rollback segment(s) are active. 2015-10-26 19:35:21 13762 [Note] InnoDB: Waiting for purge to start 2015-10-26 19:35:21 13762 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 710963181

 

다음 단계에서는 인증 플러그인이 시작된다.

2015-10-26 19:35:21 13762 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work. 2015-10-26 19:35:21 13762 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.

 

마지막에는 구성된 IP 및 포트에 MySQL을 바인딩하는 방법에 대한 정보가 표시된다. 이벤트 스케줄러도 초기화 된다. 마지막으로 MySQL이 올바르게 시작되었음을 나타내는 ‘ready for connections’ 메시지가 표시된다.

2015-10-26 19:35:21 13762 [Note] Server hostname (bind-address): '*'; port: 33306 2015-10-26 19:35:21 13762 [Note] IPv6 is available. 2015-10-26 19:35:21 13762 [Note]   - '::' resolves to '::'; 2015-10-26 19:35:21 13762 [Note] Server socket created on IP: '::'. 2015-10-26 19:35:21 13762 [Warning] 'proxies_priv' entry '@ root@ip-172-30-4-23' ignored in --skip-name-resolve mode. 2015-10-26 19:35:21 13762 [Note] Event Scheduler: Loaded 2 events 2015-10-26 19:35:21 13762 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.6.26-74.0'  socket: '/var/run/mysqld/mysqld.sock'  port: 33306  Percona Server (GPL), Release 74.0, Revision 32f8dfd

 

종료 프로세스의 경우 아래와 같은 로그가 기록된다. 이 메시지의 내용은 종료하는데 있어서 매우 중요한 정보를 나타낸다.

2015-10-26 19:35:13 12955 [Note] /usr/sbin/mysqld: Normal shutdown

 

MySQL은 다양한 방법으로 중지될 수 있다. 사용자는 init 스크립트를 사용할 수 있고, ‘mysqladmin’을 사용하여 SHUTDOWN 명령을 실행할 수 있으며, 데이터베이스 종료를 시작하는 SIGTERM을 MySQL로 보낼 수도 있다. MySQL 인스턴스가 종료된 원인을 조사할 경우 이러한 메시지는 항상 누군가(또는 무언가) 완전한 종료를 실행했음을 나타난다.

 

아래 메시지는 크래시가 발생하지도 않았으며 MySQL도 종료되지 않았다. MySQL은 나머지 연결을 닫고 강제로 종료한다.

2015-10-26 19:35:13 12955 [Note] Giving 12 client threads a chance to die gracefully 2015-10-26 19:35:13 12955 [Note] Event Scheduler: Purging the queue. 2 events 2015-10-26 19:35:13 12955 [Note] Shutting down slave threads 2015-10-26 19:35:15 12955 [Note] Forcefully disconnecting 6 remaining clients 2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 37  user: 'cmon' 2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 53  user: 'cmon' 2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 38  user: 'cmon' 2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 39  user: 'cmon' 2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 44  user: 'cmon' 2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 47  user: 'cmon'

 

그리고 MySQL에서는 활성화된 모든 플러그인을 종료한다.  

2015-10-26 19:35:15 12955 [Note] Binlog end 2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'partition' 2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA' 2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'ARCHIVE' ...

 

아래 내용은 종료되는 플러그인 중 InnoDB에 관한 것으로 빠른 종료가 활성화된 상태에서도 바쁜 서버에서는 완전한 InnoDB 종료에 시간이 걸릴 수 있다.

2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'MyISAM' 2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'MRG_MYISAM' 2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'CSV' 2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'MEMORY' 2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'sha256_password' 2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'mysql_old_password' 2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'mysql_native_password' 2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'binlog' 2015-10-26 19:35:17 12955 [Note] /usr/sbin/mysqld: Shutdown complete

 

종료 프로세스는 ‘Shutdown complete’라는 메시지와 함께 종료된다.

 

 

[Configuration errors]

my.cnf를 편집하는 과정에서 변수명에 대한 오타 또는 설정에 대한 리밋값 오류가 있을 수 있다. MySQL은 시작될 때, 구성 파일을 구문 분석한다. 오류가 발생하면 실행이 거부된다.

2015-10-27 11:20:05 18858 [Note] Plugin 'FEDERATED' is disabled. 2015-10-27 11:20:05 18858 [Note] InnoDB: Using atomics to ref count buffer pool pages 2015-10-27 11:20:05 18858 [Note] InnoDB: The InnoDB memory heap is disabled 2015-10-27 11:20:05 18858 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-10-27 11:20:05 18858 [Note] InnoDB: Memory barrier is not used 2015-10-27 11:20:05 18858 [Note] InnoDB: Compressed tables use zlib 1.2.8 2015-10-27 11:20:05 18858 [Note] InnoDB: Using Linux native AIO 2015-10-27 11:20:05 18858 [Note] InnoDB: Using CPU crc32 instructions 2015-10-27 11:20:05 18858 [Note] InnoDB: Initializing buffer pool, size = 512.0M 2015-10-27 11:20:05 18858 [Note] InnoDB: Completed initialization of buffer pool 2015-10-27 11:20:05 18858 [Note] InnoDB: Highest supported file format is Barracuda. 2015-10-27 11:20:05 18858 [Note] InnoDB: 128 rollback segment(s) are active. 2015-10-27 11:20:05 18858 [Note] InnoDB: Waiting for purge to start 2015-10-27 11:20:06 18858 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 773268083 2015-10-27 11:20:06 18858 [ERROR] /usr/sbin/mysqld: unknown variable '--max-connections=512' 2015-10-27 11:20:06 18858 [ERROR] Aborting

 

위 로그를 살펴보면 max_connections 변수와 관련하여 변수에 대한 오타가 있음을 확인할 수 있다. MySQL은 my.cnf에서 ‘-‘ 접두사를 허용하지 않음으로 ‘ps’ 출력 또는 MySQL 설명서에서 설정을 복사하는 경우 이 부분을 주의하기 바란다.

 

아래 내용은 변수 오타가 아닌 잘못된 구성의 문제로, 서버에 메모리를 과도하게 할당했을 때 발생한 오류이다.

2015-10-27 11:24:41 31325 [Note] Plugin 'FEDERATED' is disabled. 2015-10-27 11:24:41 31325 [Note] InnoDB: Using atomics to ref count buffer pool pages 2015-10-27 11:24:41 31325 [Note] InnoDB: The InnoDB memory heap is disabled 2015-10-27 11:24:41 31325 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-10-27 11:24:41 31325 [Note] InnoDB: Memory barrier is not used 2015-10-27 11:24:41 31325 [Note] InnoDB: Compressed tables use zlib 1.2.8 2015-10-27 11:24:41 31325 [Note] InnoDB: Using Linux native AIO 2015-10-27 11:24:41 31325 [Note] InnoDB: Using CPU crc32 instructions 2015-10-27 11:24:41 31325 [Note] InnoDB: Initializing buffer pool, size = 512.0G InnoDB: mmap(70330089472 bytes) failed; errno 12 2015-10-27 11:24:41 31325 [ERROR] InnoDB: Cannot allocate memory for the buffer pool 2015-10-27 11:24:41 31325 [ERROR] Plugin 'InnoDB' init function returned error. 2015-10-27 11:24:41 31325 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. 2015-10-27 11:24:41 31325 [ERROR] Unknown/unsupported storage engine: InnoDB 2015-10-27 11:24:41 31325 [ERROR] Aborting

 

메시지를 살펴보면 이 호스트에서 불가능했던 512G의 메모리를 할당하려고 시도하였고 오류가 발생한 것을 확인할 수 있다. MySQL을 시작하려면 InnoDB가 필요한데, InnoDB 초기화 오류로 인해 MySQL이 시작되지 않았다.

 

 

[Permission errors]

아래 로그를 살펴보면 MySQL은 ‘permission denied’ 오류로 인해 바이너리 로그에 대한 인덱스 파일을 찾을 수 없다. 이 경우 MySQL의 하드 스톱 원인 이기도 하다. 바이너리 로그를 읽고 쓸 수 있어야 한다.

/usr/sbin/mysqld: File './binlog.index' not found (Errcode: 13 - Permission denied) 2015-10-27 11:31:40 11469 [ERROR] Aborting

 

아래 메시지는 또 다른 권한 문제로 ibdata1 파일과 관련되어 있다. 이는 InnoDB가 내부 데이터(InnoDB 사전 및 기본적으로 실행 취소 로그)를 저장하는데 사용되는 공유 시스템 테이블 스페이스이다. MySQL 5.6의 기본 설정인 innodb_file_per_table을 사용하더라도 InnoDB에서는 초기화를 위해 이 파일이 필요하다.

2015-10-27 11:32:46 13601 [Note] Plugin 'FEDERATED' is disabled. 2015-10-27 11:32:46 13601 [Note] InnoDB: Using atomics to ref count buffer pool pages 2015-10-27 11:32:46 13601 [Note] InnoDB: The InnoDB memory heap is disabled 2015-10-27 11:32:46 13601 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-10-27 11:32:46 13601 [Note] InnoDB: Memory barrier is not used 2015-10-27 11:32:46 13601 [Note] InnoDB: Compressed tables use zlib 1.2.8 2015-10-27 11:32:46 13601 [Note] InnoDB: Using Linux native AIO 2015-10-27 11:32:46 13601 [Note] InnoDB: Using CPU crc32 instructions 2015-10-27 11:32:46 13601 [Note] InnoDB: Initializing buffer pool, size = 512.0M 2015-10-27 11:32:46 13601 [Note] InnoDB: Completed initialization of buffer pool 2015-10-27 11:32:46 13601 [ERROR] InnoDB: ./ibdata1 can't be opened in read-write mode 2015-10-27 11:32:46 13601 [ERROR] InnoDB: The system tablespace must be writable! 2015-10-27 11:32:46 13601 [ERROR] Plugin 'InnoDB' init function returned error. 2015-10-27 11:32:46 13601 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. 2015-10-27 11:32:46 13601 [ERROR] Unknown/unsupported storage engine: InnoDB 2015-10-27 11:32:46 13601 [ERROR] Aborting

 

아래 로그는 시스템 스키마(mysql 스키마)와 관련된 권한 문제이다. 로그를 보면 InnoDB는 이 스키마에서 테이블을 열 수 있는 액세스 권한이 없다고 표시한다. 이경우 MySQL이 멈추게 되며 심각한 문제임을 알 수 있다.

015-10-27 11:35:21 17826 [Note] Plugin 'FEDERATED' is disabled. /usr/sbin/mysqld: Can't find file: './mysql/plugin.frm' (errno: 13 - Permission denied) 2015-10-27 11:35:21 17826 [ERROR] Can't open the mysql.plugin table. Please run mysql_upgrade to create it. 2015-10-27 11:35:21 17826 [Note] InnoDB: Using atomics to ref count buffer pool pages 2015-10-27 11:35:21 17826 [Note] InnoDB: The InnoDB memory heap is disabled 2015-10-27 11:35:21 17826 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-10-27 11:35:21 17826 [Note] InnoDB: Memory barrier is not used 2015-10-27 11:35:21 17826 [Note] InnoDB: Compressed tables use zlib 1.2.8 2015-10-27 11:35:21 17826 [Note] InnoDB: Using Linux native AIO 2015-10-27 11:35:21 17826 [Note] InnoDB: Using CPU crc32 instructions 2015-10-27 11:35:21 17826 [Note] InnoDB: Initializing buffer pool, size = 512.0M 2015-10-27 11:35:21 17826 [Note] InnoDB: Completed initialization of buffer pool 2015-10-27 11:35:21 17826 [Note] InnoDB: Highest supported file format is Barracuda. 2015-10-27 11:35:21 7fa02e97d780  InnoDB: Operating system error number 13 in a file operation. InnoDB: The error means mysqld does not have the access rights to InnoDB: the directory. 2015-10-27 11:35:21 17826 [ERROR] InnoDB: Could not find a valid tablespace file for 'mysql/innodb_index_stats'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadict.html for how to resolve the issue. 2015-10-27 11:35:21 17826 [ERROR] InnoDB: Tablespace open failed for '"mysql"."innodb_index_stats"', ignored. 2015-10-27 11:35:21 7fa02e97d780  InnoDB: Operating system error number 13 in a file operation. InnoDB: The error means mysqld does not have the access rights to InnoDB: the directory. 2015-10-27 11:35:21 17826 [ERROR] InnoDB: Could not find a valid tablespace file for 'mysql/innodb_table_stats'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadict.html for how to resolve the issue. 2015-10-27 11:35:21 17826 [ERROR] InnoDB: Tablespace open failed for '"mysql"."innodb_table_stats"', ignored. 2015-10-27 11:35:21 7fa02e97d780  InnoDB: Operating system error number 13 in a file operation. InnoDB: The error means mysqld does not have the access rights to InnoDB: the directory.

 

 

[Out of memory errors]

MySQL 서버의 메모리 부족과 관련된 또 다른 자주 발생하는 문제로, 다양하게 나타나지만 가장 흔하게 접하게 되는 메시지는 아래와 같다.

Killed 151027 12:18:58 mysqld_safe Number of processes running now: 0

 

mysqld_safe는 mysqld를 모니터링하고 종료되면 다시 시작하는 ‘angel’ 프로세스이다. MySQL에는 해당되지만 Galera 노드에서는 해당되지 않는다. 이 경우 MySQL을 다시 시작하지는 않지만 다음 순서가 표시된다.

Killed 151027 12:18:58 mysqld_safe Number of processes running now: 0 151027 12:18:58 mysqld_safe WSREP: not restarting wsrep node automatically 151027 12:18:58 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended

 

메모리 문제가 나타날 수 있는 또 다른 방법은 오류 로그의 다음 메시지를 통해서이다.

InnoDB: mmap(3145728 bytes) failed; errno 12 InnoDB: mmap(3145728 bytes) failed; errno 12

 

이 경우 ‘perror’ 유틸리티를 사용하여 오류 코드를 확인하면, 정확히 무슨 일이 일어났는지 알 수 있다.

$ perror 12 OS error code  12:  Cannot allocate memory

 

메모리 문제가 의심되거나 예상치 못한 MySQL 크래시가 발생하는 경우 dmesg를 실행하여 더 많은 데이터를 얻을 수도 있다. 아래와 같은 출력이 표시되면 OOM Killer가 MySQL을 종료하여 문제가 발생한 것임을 확인할 수 있다.

[ 4165.802544] Out of memory: Kill process 8143 (mysqld) score 938 or sacrifice child [ 4165.808329] Killed process 8143 (mysqld) total-vm:5101492kB, anon-rss:3789388kB, file-rss:0kB [ 4166.226410] init: mysql main process (8143) killed by KILL signal [ 4166.226437] init: mysql main process ended, respawning

 

 

[InnoDB crashes]

대부분의 경우 InnoDB는 매우 견고하고 내구성이 뛰어난 스토리지 엔진이다. 하지만 어떤 상황에서는 데이터가 손상될 수 있다. 일반적으로 잘못된 구성(예: 이중 쓰기 버퍼 비활성화) 또는 일종의 하드웨어 결함(메모리 모듈 결함, 불안정한 I/O 계층)과 관련이 있다. 이러한 경우 InnoDB가 크래시 될 수 있다. InnoDB 버그로 인해서도 크래시가 발생할 수도 있다. 흔한 일은 아니지만 가끔씩 발생한다. 크래시 원인에 관계없이 오류 로그는 일반적으로 비슷한 방식으로 표시된다. 실제 사례를 살펴보자.

2015-10-13 15:08:06 7f53f0658700  InnoDB: Assertion failure in thread 139998492198656 in file btr0pcur.cc line 447 InnoDB: Failing assertion: btr_page_get_prev(next_page, mtr) == buf_block_get_page_no(btr_pcur_get_block(cursor))

 

InnoDB 코드는 온전성 검사로 가득 차 있다. 어설션은 매우 빈번하며, 그 중 하나가 실패하면 InnoDB는 의도적으로 MySQL을 크래시 시킨다. 처음에는 실패한 어설션의 정확한 위치에 대한 정보가 표시된다. 이는 정확히 무슨 일이 일어났는지에 대한 정보를 제공한다. MySQL 소스 코드는 인터넷에서 확인할 수 있으며 특정 버전과 관련된 코드를 다운로드하는 것은 매우 쉽다. MySQL 코드는 적절하게 문서화되어 있으며 최소한 어떤 종류의 활동이 문제를 유발하는지 파악하는 것은 문제가 되지 않는다.

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.6/en/forcing-innodb-recovery.html InnoDB: about forcing recovery.

 

InnoDB 로깅 정보에는 InnoDB 복구 프로세스에 대한 정보가 있다. 어떤 상황에서는 MySQL을 시작하고 InnoDB 데이터를 덤프할 수 있다. 이는 "거의 최후의 수단"으로 사용된다. 한 단계 더 나아가면 16진수 편집기를 사용하여 InnoDB 파일을 파헤치게 된다.

13:08:06 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. We will try our best to scrape up some info that will hopefully help diagnose the problem, but since we have already crashed, something is definitely wrong and this may fail. Please help us make Percona Server better by reporting any bugs at http://bugs.percona.com/   key_buffer_size=67108864 read_buffer_size=131072 max_used_connections=36 max_threads=514 thread_count=27 connection_count=26 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 269997 K  bytes of memory Hope that's ok; if not, decrease some variables in the equation.

 

다음 단계에서는 일부 상태 카운터가 기록된 것을 볼 수 있다. 이는 구성에 대한 몇 가지 아이디어를 제공할 것으로 예상된다. 너무 많은 리소스를 사용하도록 MySQL을 구성했을 수도 있다. 이 데이터를 검토하면 역추적에 도달하게 된다. 이 정보는 스택을 안내하고 크래시가 발생했을 때 어떤 종류의 호출이 실행되었는지 보여준다. 이 특별한 경우에 정확히 무슨 일이 일어났는지 확인해 보자.

Thread pointer: 0xa985960 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 = 7f53f0657d40 thread_stack 0x40000 /usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8cd37c] /usr/sbin/mysqld(handle_fatal_signal+0x461)[0x6555a1] /lib64/libpthread.so.0(+0xf710)[0x7f540f978710] /lib64/libc.so.6(gsignal+0x35)[0x7f540dfd4625] /lib64/libc.so.6(abort+0x175)[0x7f540dfd5e05] /usr/sbin/mysqld[0xa0277b] /usr/sbin/mysqld[0x567f88] /usr/sbin/mysqld[0x99afde] /usr/sbin/mysqld[0x8eb926] /usr/sbin/mysqld(_ZN7handler11ha_rnd_nextEPh+0x5d)[0x59a6ed] /usr/sbin/mysqld(_Z13rr_sequentialP11READ_RECORD+0x20)[0x800cd0] /usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyy+0xc88)[0x8128c8] /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1bc5)[0x6d6d15] /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5a8)[0x6dc228] /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x108c)[0x6dda4c] /usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x162)[0x6ab002] /usr/sbin/mysqld(handle_one_connection+0x40)[0x6ab0f0] /usr/sbin/mysqld(pfs_spawn_thread+0x143)[0xaddd73] /lib64/libpthread.so.0(+0x79d1)[0x7f540f9709d1] /lib64/libc.so.6(clone+0x6d)[0x7f540e08a8fd]

 

MySQL이 DELETE 명령을 실행할 때 문제가 발생한 것을 볼 수 있다. 레코드를 순차적으로 읽고 전체 테이블 스캔을 수행했다(handler read_rnd_next).

InnoDB: Failing assertion: btr_page_get_prev(next_page, mtr) == buf_block_get_page_no(btr_pcur_get_block(cursor))

 

InnoDB가 버퍼 풀 스캔을 수행할 때 충돌이 발생했음을 알 수 있다(btr_pcur_move_to_next_page 메소드에서 어설션이 트리거됨).

Trying to get some variables. Some pointers may be invalid and cause the dump to abort. Query (a991d40): DELETE FROM cmon_stats WHERE cid = 2 AND ts < 1444482484 Connection ID (thread ID): 5 Status: NOT_KILLED

 

마지막으로 어떤 스레드가 어설션을 트리거했는지 확인할 수 있다(때로는 항상 로깅 되지는 않음). 이 경우에는 실제로 일종의 문제를 일으킨 DELETE 쿼리였음을 확인할 수 있다.

You may download the Percona Server operations manual by visiting http://www.percona.com/software/percona-server/. You may find information in the manual which will help you identify the cause of the crash. 151013 15:08:06 mysqld_safe Number of processes running now: 0

 

일반적으로 MySQL은 오류 로그와 관련하여 매우 장황하다. 하지만 상황이 너무 잘못되어 MySQL이 실제로 많은 정보를 수집할 수 없는 경우도 있다. 이는 여전히 뭔가 매우 잘못되었다는 매우 명확한 표시를 제공한다(신호 11). 아래 사례를 살펴보자.

22:31:40 UTC - mysqld got signal 11 ; 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. We will try our best to scrape up some info that will hopefully help diagnose the problem, but since we have already crashed, something is definitely wrong and this may fail. Please help us make Percona XtraDB Cluster better by reporting any bugs at https://bugs.launchpad.net/percona-xtradb-cluster   key_buffer_size=33554432 read_buffer_size=131072 max_used_connections=10 max_threads=202 thread_count=9 connection_count=7 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 113388 K  bytes of memory Hope that's ok; if not, decrease some variables in the equation.   Thread pointer: 0x1fb7050 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... Segmentation fault (core dumped) 150119 23:48:08 mysqld_safe Number of processes running now: 0

 

로그를 살펴보면 MySQL이 크래시 했다는 명확한 정보가 있다. 하지만 추가 정보는 없다. 분할 오류는 진단 메시지에 기록될 수도 있다. 이 특별한 경우 dmesg는 다음을 반환했다.

[370591.200799] mysqld[5462]: segfault at 51 ip 00007fe624e3e688 sp 00007fe4f4099c30 error 4 in libgcc_s.so.1[7fe624e2f000+16000]

 

많은 내용이 포함된 것은 아니지만 이미 보고된 경우 이러한 정보는 매우 유용할 수 있다. 오류 로그에 기록된 정보만으로 문제를 해결하는 것이 항상 가능한 것은 아니다. 하지만 데이터베이스의 문제 디버깅을 시작하기에는 확실히 좋은 장소이다. 매우 일반적이고 단순한 구성 오류가 발생하는 경우 오류 로그에서 찾을 수 있는 정보만으로도 원인을 찾아내고 해결책을 찾는 데 충분하다. 심각한 MySQL 충돌에 대해 이야기하고 있다면 상황은 확실히 다르다. 대부분의 경우 문제를 스스로 해결할 수 없을 것이다. 반면에 이 데이터는 범인을 식별하고 이를 다루는 기존 버그 보고서를 찾는 데 충분할 수 있다. 이러한 버그 보고서에는 많은 토론과 팁 또는 해결 방법이 포함되어 있다. 아마도 그 중 하나를 구현할 수 있을 것이다. 해당 버그가 xyz 버전에서 수정되었다는 정보도 유용하다. 이를 확인하고 문제가 해결되면 업그레이드 계획을 세울 수 있다. 최악의 경우에는 스스로 버그 보고서를 작성할 수 있을 만큼 충분한 데이터가 있어야 한다.

 

 

[참고자료]

l  Understanding the MySQL Error Log : https://severalnines.com/blog/understanding-mysql-error-log/

 

 

 

2023-10-11 / Sungwook Kang / http://sungwookkang.com

 

MySQL, ErrorLog, 오류로그, ErrorMessage, MySQL Error,