문제점 및 증상
MariaDB의 데이터 폴더를 그대로 복사하여, 새로운 서버에서 구동하려고 했으나 다음과 같은 로그와 함께 MariaDB 서비스가 정상적으로 실행되지 않았습니다.
systemctl start mariadb
Job for mariadb.service failed because a timeout was exceeded. See "systemctl status mariadb.service" and "journalctl -xe" for details.
systemctl status mariadb
mariadb.service - MariaDB 10.3.12 database server
Loaded: loaded (/usr/lib/systemd/system/mariadb.service; enabled; vendor preset: disabled)
Drop-In: /etc/systemd/system/mariadb.service.d
migrated-from-my.cnf-settings.conf
Active: failed (Result: timeout) since 2020-01-07 16:02:15 KST; 10min ago
Docs: man:mysqld(8)
https://mariadb.com/kb/en/library/systemd/
Process: 8314 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=0/SUCCESS)
Process: 8270 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= || VAR=`/usr/bin/galera_recovery`; [ $? -eq 0 ] && systemctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=exited, status=0/SUCCESS)
Process: 8267 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
Main PID: 8314 (code=exited, status=0/SUCCESS)
Status: "MariaDB server is down"
1 07 16:02:13 DB mysqld[8314]: 2020-01-07 16:02:13 0 [Note] InnoDB: Starting shutdown...
1 07 16:02:13 DB mysqld[8314]: 2020-01-07 16:02:13 0 [Note] InnoDB: Dumping buffer pool(s) to /home/mariadb/mysql/ib_buffer_pool
1 07 16:02:13 DB mysqld[8314]: 2020-01-07 16:02:13 0 [Note] InnoDB: Instance 0, restricted to 2048 pages due to innodb_buf_pool_dump_pct=25
1 07 16:02:13 DB mysqld[8314]: 2020-01-07 16:02:13 0 [Note] InnoDB: Buffer pool(s) dump completed at 200107 16:02:13
1 07 16:02:14 DB mysqld[8314]: 2020-01-07 16:02:14 0 [Note] InnoDB: Shutdown completed; log sequence number 9571071424; transaction id 4674429
1 07 16:02:14 DB mysqld[8314]: 2020-01-07 16:02:14 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
1 07 16:02:15 DB mysqld[8314]: 2020-01-07 16:02:15 0 [Note] /usr/sbin/mysqld: Shutdown complete
1 07 16:02:15 DB systemd[1]: Failed to start MariaDB 10.3.12 database server.
1 07 16:02:15 DB systemd[1]: Unit mariadb.service entered failed state.
1 07 16:02:15 DB systemd[1]: mariadb.service failed.
원인 분석
"/var/log/messages" 파일에서 MariaDB 관련 부분의 로그만 확인해 보면 다음과 같습니다.
Jan 7 16:58:05 DB systemd: Starting MariaDB 10.3.12 database server...
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] Using unique option prefix 'skip_name_resolv' is error-prone and can break in the future. Please use the full name 'skip_name_resolve' instead.
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] /usr/sbin/mysqld (mysqld 10.3.12-MariaDB-log) starting as process 16211 ...
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] InnoDB: Using Linux native AIO
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] InnoDB: Uses event mutexes
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] InnoDB: Number of pools: 1
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] InnoDB: Using SSE2 crc32 instructions
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] InnoDB: Completed initialization of buffer pool
Jan 7 16:58:05 DB mysqld: 2020-01-07 16:58:05 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
Jan 7 16:59:35 DB systemd: mariadb.service start operation timed out. Terminating.
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] InnoDB: Waiting for purge to start
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] InnoDB: 10.3.12 started; log sequence number 9571071433; transaction id 4673479
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] InnoDB: Loading buffer pool(s) from /home/mariadb/mysql/ib_buffer_pool
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] Plugin 'FEEDBACK' is disabled.
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] InnoDB: Buffer pool(s) load completed at 200107 16:59:43
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] Server socket created on IP: '::'.
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Warning] 'proxies_priv' entry '@% root@webbuilderdb' ignored in --skip-name-resolve mode.
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] Reading of all Master_info entries succeded
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] Added new Master_info '' to hash table
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] /usr/sbin/mysqld: ready for connections.
Jan 7 16:59:43 DB mysqld: Version: '10.3.12-MariaDB-log' socket: '/var/lib/mysql/mysql.sock' port: 16033 MariaDB Server
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] Event Scheduler: Purging the queue. 85 events
Jan 7 16:59:49 DB mysqld: 2020-01-07 16:59:49 0 [Note] InnoDB: FTS optimize thread exiting.
Jan 7 16:59:49 DB mysqld: 2020-01-07 16:59:49 0 [Note] InnoDB: Starting shutdown...
Jan 7 16:59:49 DB mysqld: 2020-01-07 16:59:49 0 [Note] InnoDB: Dumping buffer pool(s) to /home/mariadb/mysql/ib_buffer_pool
Jan 7 16:59:49 DB mysqld: 2020-01-07 16:59:49 0 [Note] InnoDB: Instance 0, restricted to 2048 pages due to innodb_buf_pool_dump_pct=25
Jan 7 16:59:49 DB mysqld: 2020-01-07 16:59:49 0 [Note] InnoDB: Buffer pool(s) dump completed at 200107 16:59:49
Jan 7 16:59:51 DB mysqld: 2020-01-07 16:59:51 0 [Note] InnoDB: Shutdown completed; log sequence number 9571071442; transaction id 4674429
Jan 7 16:59:51 DB mysqld: 2020-01-07 16:59:51 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Jan 7 16:59:51 DB mysqld: 2020-01-07 16:59:51 0 [Note] /usr/sbin/mysqld: Shutdown complete
Jan 7 16:59:51 DB systemd: Failed to start MariaDB 10.3.12 database server.
위 로그 중에서 다음 부분으로 봤을 때, MariaDB 서비스가 실행되고 있는 중에 강제로 중단을 시켜서 서비스가 정상적으로 실행되지 않았습니다.
Jan 7 16:59:43 DB mysqld: 2020-01-07 16:59:43 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
로그를 좀 더 자세히 살펴보니, 위와 같이 서비스 중단을 발생시키는 원인은 다음과 같았습니다.
Jan 7 16:59:35 DB systemd: mariadb.service start operation timed out. Terminating.
즉, 시스템이 느리거나 로딩해야할 데이터베이스가 너무 많아서 지정된 시간동안 서비스가 완전하게 실행되지 못하자 time-out이 발생하며 systemd 에서 MariaDB 서비스를 강제로 종료(shutdown)시킨 것이었습니다.
조치 내용
MariaDB에 대한 추가 설정 파일을 다음과 같이 작성하여 MariaDB 서비스에 대한 time-out 시간을 제거하여 정상적으로 서비스가 실행되도록 하였습니다.
vi /etc/systemd/system/mariadb.service.d/homedir.conf
[Service]
ProtectHome=false
TimeoutStartSec=0
다음과 같이 서비스 설정을 다시 읽어 들인 후, MariaDB 서비스를 시작하였습니다.
systemctl daemon-reload
systemctl start mariadb