Почему падает mysql?

Question

[erwrwewe]

Здравствуйте, mysql перезапустился. Почему такое произошло подскажите пожалуйста.
Вот лог на момент падения и конфиг (на сервере 32 ГБ оперативки).
Перед падением росла загрузка процессора был некий пик (но не при каждом пике он падает). Падения происходят периодически. На сервере довольно много постоянных cron скриптов которые нагружают mysql ну и собственно сам сайт.
Описал что смог.

лог

200722 17:10:24 mysqld_safe Number of processes running now: 0
200722 17:10:24 mysqld_safe mysqld restarted
2020-07-22 17:10:24 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2020-07-22 17:10:24 0 [Note] /usr/sbin/mysqld (mysqld 5.6.45-log) starting as process 7257 ...
2020-07-22 17:10:24 7257 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 9202)

2020-07-22 17:10:24 7257 [Warning] Buffered warning: Changed limits: max_connections: 214 (requested 1000)

2020-07-22 17:10:24 7257 [Warning] Buffered warning: Changed limits: table_open_cache: 400 (requested 4096)

2020-07-22 17:10:24 7257 [Note] Plugin 'FEDERATED' is disabled.
innodb_open_files should not be greater than the open_files_limit.
2020-07-22 17:10:24 7257 [Note] InnoDB: Using atomics to ref count buffer pool pages
2020-07-22 17:10:24 7257 [Note] InnoDB: The InnoDB memory heap is disabled
2020-07-22 17:10:24 7257 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-07-22 17:10:24 7257 [Note] InnoDB: Memory barrier is not used
2020-07-22 17:10:24 7257 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-07-22 17:10:24 7257 [Note] InnoDB: Using Linux native AIO
2020-07-22 17:10:24 7257 [Note] InnoDB: Using CPU crc32 instructions
2020-07-22 17:10:24 7257 [Note] InnoDB: Initializing buffer pool, size = 20.0G
2020-07-22 17:10:25 7257 [Note] InnoDB: Completed initialization of buffer pool
2020-07-22 17:10:25 7257 [Note] InnoDB: Highest supported file format is Barracuda.
2020-07-22 17:10:25 7257 [Note] InnoDB: Log scan progressed past the checkpoint lsn 12026815000558
2020-07-22 17:10:25 7257 [Note] InnoDB: Database was not shutdown normally!
2020-07-22 17:10:25 7257 [Note] InnoDB: Starting crash recovery.
2020-07-22 17:10:25 7257 [Note] InnoDB: Reading tablespace information from the .ibd files...
2020-07-22 17:10:25 7257 [Note] InnoDB: Restoring possible half-written data pages
2020-07-22 17:10:25 7257 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 12026820242944
InnoDB: Doing recovery: scanned up to log sequence number 12026825485824
InnoDB: Doing recovery: scanned up to log sequence number 12026830728704
...........................
InnoDB: Doing recovery: scanned up to log sequence number 12027916004864
InnoDB: Doing recovery: scanned up to log sequence number 12027916058495
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 134396318464
2020-07-22 17:10:44 7257 [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
InnoDB: Apply batch completed
2020-07-22 17:11:38 7257 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2020-07-22 17:11:38 7f864c326700 InnoDB: Rolling back trx with id 134396318144, 1 rows to undo
2020-07-22 17:11:38 7257 [Note] InnoDB: Waiting for purge to start
2020-07-22 17:11:38 7257 [Note] InnoDB: Rollback of trx with id 134396318144 completed
2020-07-22 17:11:38 7f864c326700 InnoDB: Rollback of non-prepared transactions completed
2020-07-22 17:11:38 7257 [Note] InnoDB: 5.6.45 started; log sequence number 12027916058495
2020-07-22 17:11:38 7257 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2020-07-22 17:11:38 7257 [Note] - '127.0.0.1' resolves to '127.0.0.1';
2020-07-22 17:11:38 7257 [Note] Server socket created on IP: '127.0.0.1'.
2020-07-22 17:11:38 7257 [Warning] 'proxies_priv' entry '@ [e-mail]' ignored in --skip-name-resolve mode.
2020-07-22 17:11:38 7257 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type char(77), found type char(141).
2020-07-22 17:11:38 7257 [ERROR] Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
2020-07-22 17:11:38 7257 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.45-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Server (GPL)

конфиг.

[mysqld]
innodb_log_file_size = 2G
#innodb_log_buffer_size = 2M
max_connections	= 1000

innodb_buffer_pool_size     = 20G
innodb_buffer_pool_instances = 16
innodb_flush_log_at_trx_commit = 2

query_cache_size = 0

max_allowed_packet          = 16M
key_buffer_size             = 16M

#slow_query_log              = /var/log/mysql/mysql-slow555.log
slow_query_log=1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time             = 2

expire_logs_days            = 10
max_binlog_size             = 100M

skip-name-resolve			= 1
tmp_table_size=2560M
max_heap_table_size=2560M
table_open_cache = 4096
innodb_open_files = 4096
innodb_read_io_threads = 8
innodb_write_io_threads = 8
innodb_thread_concurrency = 24


collation-server = utf8_general_ci
character-set-server = utf8
local-infile=0
innodb_file_per_table = 1
pid-file = /var/run/mysqld/mysqld.pid
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0
ft_min_word_len = 1
innodb_ft_min_token_size=1
bind-address = 127.0.0.1
# Settings user and group are ignored when systemd is used.
# If you need to run mysqld under a different user or group,
# customize your systemd unit file for mariadb according to the
# instructions in http://fedoraproject.org/wiki/Systemd

[mysqld_safe]
log-error=/var/log/mariadb/mariadb.log
#pid-file=/var/run/mariadb/mariadb.pid

#
# include all files from the config directory
#
!includedir /etc/my.cnf.d

Comments

[ScriptKiddo]

Своп есть на сервере?

[erwrwewe]

ScriptKiddo, Файл подкачки (swap) 5119 MiB

[Everything_is_not_so_bad]

Длинные логи стоит обрамлять в тег spoiler.
Что в /var/log/mariadb/mariadb.log ?

[erwrwewe]

Роман Мирр, https://izap24.ru/mariadb.log

Answer 1

[Vitaly Karasik]

1) Покажите нам /var/log/messages
2) это сервер для mysql или там еще что-то бежит?

Comments

[erwrwewe]

1. взял срез за 22 июля и до времени падения: https://izap24.ru/messages.txt
2. Все в одном выделенный сервер isp сайт база сфинкс.

Кстати раньше проблема с сервером была он перезагружался. Какая то проблема по железу была.

[Vitaly Karasik]

1) Я не вижу в логе каких-то проблем. Много "CPU6: Core temperature above threshold, cpu clock throttled", можно спросить у хостера нормально ли это. Но по-моему ничего страшного.
2)

Все в одном выделенный сервер

советую посмотреть графики мониторинга, особенно память
3) 5.6.45 довольно старая версия, сделайте бэкап и поднимите до последней 5.6.49.

Но в целом ответ - увы, не знаю почему. Может, железо - но это надо сервер останавливать и гонять тесты.

[erwrwewe]

Vitaly Karasik, Понял спасибо, попрошу обновить. График по памяти был стабильный, если достаточно того что в ISP рисует. По перегреву там и раньше какая то проблема была, устраняли они.

Answer 2

[Everything_is_not_so_bad]

"Normal shutdown" случается по причинам:
1. запуск команды mysqladmin .... shutdown. Это можно проверить командой history | grep mysqladmin | grep shutdown
Если вывод не пуст, то видно что за пользователь.
Источник: https://dba.stackexchange.com/a/40627
2. процесс mysqld получает сигнал SIGTERM

Также, возможно, не был выполнен апгрейд с предыдущей версии.
mysql_upgrade -u root -p
https://mariadb.com/kb/en/incorrect-definition-of-...

Вероятно также что некорректно завершена установка MariaDB.

Comments

[erwrwewe]

1. пусто ну или "999 history | grep mysqladmin | grep shutdown"
2.

спасибо, попрошу обновить!

Answer 3

[erwrwewe]

так мне написали (см ниже), это зря я выделил mysql 20 гб. или проблема в скриптах , ПО или действительно просто мало памяти?

На сервере наблюдается нехватка RAM для работы процессов, в следствии чего на сервере запускается OOM-Killer, который убивает в том числе и процесс MySQL.

[Tue Jun 23 09:47:49 2020] Out of memory: Kill process 5832 (mysqld) score 936 or sacrifice child
[Tue Jun 23 09:47:49 2020] Out of memory: Kill process 6098 (fail2ban-server) score 2 or sacrifice child
[Wed Jun 24 18:32:13 2020] Out of memory: Kill process 4693 (mysqld) score 933 or sacrifice child
[Thu Jun 25 12:33:23 2020] Out of memory: Kill process 23869 (mysqld) score 922 or sacrifice child
[Thu Jun 25 12:44:23 2020] Out of memory: Kill process 17637 (mysqld) score 920 or sacrifice child
[Thu Jun 25 12:59:26 2020] Out of memory: Kill process 20952 (mysqld) score 917 or sacrifice child
[Thu Jun 25 12:59:26 2020] Out of memory: Kill process 12356 (memcached) score 1 or sacrifice child
[Sun Jun 28 07:46:07 2020] Out of memory: Kill process 9685 (mysqld) score 879 or sacrifice child
[Sun Jun 28 07:46:07 2020] Out of memory: Kill process 25098 (php) score 47 or sacrifice child
[Mon Jun 29 14:09:39 2020] Out of memory: Kill process 12205 (mysqld) score 832 or sacrifice child
[Mon Jun 29 14:09:39 2020] Out of memory: Kill process 1791 (mysqld) score 832 or sacrifice child
[Mon Jun 29 14:09:39 2020] Out of memory: Kill process 15558 (php) score 47 or sacrifice child
[Tue Jun 30 09:32:40 2020] Out of memory: Kill process 2405 (mysqld) score 831 or sacrifice child
[Sat Jul 4 12:49:32 2020] Out of memory: Kill process 6789 (mysqld) score 848 or sacrifice child
[Thu Jul 9 00:47:03 2020] Out of memory: Kill process 15942 (mysqld) score 893 or sacrifice child
[Thu Jul 9 23:39:33 2020] Out of memory: Kill process 7737 (mysqld) score 778 or sacrifice child
[Thu Jul 9 23:39:33 2020] Out of memory: Kill process 17524 (php) score 47 or sacrifice child
[Wed Jul 15 08:51:41 2020] Out of memory: Kill process 1842 (mysqld) score 786 or sacrifice child
[Wed Jul 15 08:51:41 2020] Out of memory: Kill process 2071 (mysqld) score 786 or sacrifice child
[Fri Jul 17 15:14:54 2020] Out of memory: Kill process 5116 (mysqld) score 826 or sacrifice child
[Fri Jul 17 15:14:54 2020] Out of memory: Kill process 5124 (mysqld) score 826 or sacrifice child
[Wed Jul 22 17:10:02 2020] Out of memory: Kill process 12167 (mysqld) score 805 or sacrifice child
[Wed Jul 22 17:10:02 2020] Out of memory: Kill process 15936 (php) score 15 or sacrifice child

Необходимо либо оптимизировать работу ПО на сервере для меньшего потребления памяти, либо переходить на более мощный сервер.

Comments

[Everything_is_not_so_bad]

А что за логи? И почему они не были приложены к вопросу изначально?

это зря я выделил mysql 20 гб. или проблема в скриптах , ПО или действительно просто мало памяти?

Запустить mysqltuner и последовать его советам по настройке конфигурации.

Необходимо либо оптимизировать работу ПО на сервере для меньшего потребления памяти, либо переходить на более мощный сервер.

Обычно виновато криво написанное приложение.

[erwrwewe]

Роман Мирр, не знаю, админы сервера показали.

mysqltuner говорит innodb_buffer_pool_size (>= 64.3G) if possible.