MariaDB самоубилась

Автор PeterBumblebee, 18 августа 2015, 00:55:35

« назад - далее »

0 Пользователи и 1 гость просматривают эту тему.

PeterBumblebee

Всем привет.
Стоит свеженький сервер со свеженьким ПО, сегодня произошёл неприятный инцидент.
MariaDB вдруг решила лечь отдохнуть.
Всё, что записалось в /var/log/mysql/error.log:

Цитировать150817 17:10:27 mysqld_safe Number of processes running now: 0
150817 17:10:27 mysqld_safe mysqld restarted
150817 17:10:29 [Note] /usr/sbin/mysqld (mysqld 10.0.20-MariaDB-0+deb8u1) starting as process 21853 ...
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 128909312 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 96681984 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 72499200 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 54362112 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 40771584 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 30572544 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 22929408 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 17178624 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 12877824 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 9658368 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 7225344 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 5406720 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 4055040 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 3022848 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 2260992 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 1695744 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 1253376 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 933888 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 688128 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 516096 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 368640 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 1998848 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 1499136 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 1105920 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 811008 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 589824 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 442368 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 319488 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 221184 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 147456 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 98304 bytes)
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 73728 bytes)
150817 17:10:30 [ERROR] mysqld: Not enough memory to allocate 8 pagecache pages
150817 17:10:30 [ERROR] Plugin 'Aria' init function returned error.
150817 17:10:30 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 33512 bytes)
150817 17:10:30 [ERROR] Out of memory for plugin 'InnoDB'.
150817 17:10:30 [ERROR] mysqld: Out of memory (Needed 768 bytes)
150817 17:10:30 [ERROR] Failed to initialize plugins.
150817 17:10:30 [ERROR] Aborting

150817 17:10:30 [Note] /usr/sbin/mysqld: Shutdown complete

150817 17:10:30 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

Если это произошло один раз, то произойдёт и в дальнейшем.
У кого-нибудь есть какие-нибудь мысли, куда копать?
Who the hell cares?

ogost

вариантов 2:
1. утечка памяти. возможно какое-то приложение делает большие запросы/не закрывает сессии. ищите баги в приложении.
2. памяти мало. нагуглено: тыц

PeterBumblebee

Сегодня опять повторилось, поставил performance_schema = off, посмотрим, что будет.

Пытался сделать автоподнятие, раз в минуту кроном запускать скрипт:
#!/bin/sh

SERVICE='mysql'

if service $SERVICE status > /dev/null
then
    echo "$SERVICE is OK"
else
    echo "$SERVICE is dead!"
    echo "$SERVICE is dead!" | mail -s "$SERVICE down!" xx@xxx.xx
    service mysql start
fi


Но это не помогло, в момент лежания выполнил service mysql status:
Цитировать● mysql.service - LSB: Start and stop the mysql database server daemon
   Loaded: loaded (/etc/init.d/mysql)
   Active: active (exited) since Mon 2015-08-17 19:42:33 MSK; 5 days ago
  Process: 6682 ExecStop=/etc/init.d/mysql stop (code=exited, status=0/SUCCESS)
  Process: 6716 ExecStart=/etc/init.d/mysql start (code=exited, status=0/SUCCESS)

Aug 17 19:42:32 xxx.xx /etc/init.d/mysql[6742]: 150817 19:42:32 mysqld_safe Can't log to error log and syslog at the same time.  Remove all --log-... effect.
Aug 17 19:42:33 xxx.xx mysql[6716]: Starting MariaDB database server: mysqld.
Aug 17 19:42:33 xxx.xx systemd[1]: Started LSB: Start and stop the mysql database server daemon.
Aug 17 19:42:33 xxx.xx /etc/mysql/debian-start[6944]: Checking for insecure root accounts.
Hint: Some lines were ellipsized, use -l to show in full.
я так понимаю, else в этом случае не выполнился.

service mysql start тоже не дал результата
помог только service mysql restart

Лог немного изменился:
Открыть содержимое (спойлер)
150823 13:49:15 mysqld_safe Number of processes running now: 0
150823 13:49:15 mysqld_safe mysqld restarted
150823 13:49:15 [Note] /usr/sbin/mysqld (mysqld 10.0.20-MariaDB-0+deb8u1) starting as process 15214 ...
150823 13:49:16 [ERROR] mysqld: Out of memory (Needed 128909312 bytes)
150823 13:49:16 [ERROR] mysqld: Out of memory (Needed 96681984 bytes)
150823 13:49:16 [ERROR] mysqld: Out of memory (Needed 72499200 bytes)
150823 13:49:16 [ERROR] mysqld: Out of memory (Needed 54362112 bytes)
150823 13:49:16 [ERROR] mysqld: Out of memory (Needed 40771584 bytes)

150823 13:49:20 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
150823 13:49:24 [ERROR] Plugin 'Aria' init function returned error.
150823 13:49:24 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
150823 13:49:24 [Note] InnoDB: Using mutexes to ref count buffer pool pages
150823 13:49:24 [Note] InnoDB: The InnoDB memory heap is disabled
150823 13:49:24 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
150823 13:49:24 [Note] InnoDB: Memory barrier is not used
150823 13:49:24 [Note] InnoDB: Compressed tables use zlib 1.2.8
150823 13:49:24 [Note] InnoDB: Using Linux native AIO
150823 13:49:24 [Note] InnoDB: Not using CPU crc32 instructions
2015-08-23 13:49:24 7f3f50a9b780  InnoDB: Assertion failure in thread 139909912967040 in file ut0mem.cc line 105
InnoDB: Failing assertion: ret || !assert_on_error
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.
150823 13:49:24 [ERROR] 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.

To report this bug, see http://kb.askmonty.org/en/reporting-bugs

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.

Server version: 10.0.20-MariaDB-0+deb8u1
key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 352317 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x0
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 = 0x0 thread_stack 0x30000
(my_addr_resolve failure: fork)
/usr/sbin/mysqld(my_print_stacktrace+0x2e) [0xbf1f6e]
/usr/sbin/mysqld(handle_fatal_signal+0x392) [0x72e3c2]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0) [0x7f3f506868d0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37) [0x7f3f4f231107]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148) [0x7f3f4f2324e8]
/usr/sbin/mysqld() [0xa4ffc0]
/usr/sbin/mysqld() [0x9b8cfe]
/usr/sbin/mysqld() [0x9bce48]
/usr/sbin/mysqld() [0xa29f67]
/usr/sbin/mysqld() [0x96e0a5]
/usr/sbin/mysqld(ha_initialize_handlerton(st_plugin_int*)+0x5e) [0x73040e]
/usr/sbin/mysqld() [0x5cd245]
/usr/sbin/mysqld(plugin_init(int*, char**, int)+0x4a0) [0x5ce440]
/usr/sbin/mysqld() [0x5281a5]
/usr/sbin/mysqld(mysqld_main(int, char**)+0x4fe) [0x52dbfe]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5) [0x7f3f4f21db45]
/usr/sbin/mysqld() [0x523611]
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.
150823 13:49:50 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
[свернуть]
Who the hell cares?

PeterBumblebee

Всё равно опять всё обвалилось  :(

Цитировать150908 18:55:57 mysqld_safe Number of processes running now: 0
150908 18:55:57 mysqld_safe mysqld restarted
150908 18:55:57 [Note] /usr/sbin/mysqld (mysqld 10.0.20-MariaDB-0+deb8u1) starting as process 16042 ...
150908 18:55:57 [ERROR] mysqld: Out of memory (Needed 128909312 bytes)
150908 18:55:57 [ERROR] mysqld: Out of memory (Needed 96681984 bytes)
150908 18:56:02 [ERROR] mysqld: Out of memory (Needed 524280 bytes)
150908 18:56:02 [ERROR] mysqld: Out of memory (Needed 524280 bytes)
150908 18:56:02 [ERROR] mysqld: Aria engine: End of redo phase failed

150908 18:56:02 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
150908 18:56:02 [ERROR] Plugin 'Aria' init function returned error.
150908 18:56:02 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
150908 18:56:02 [Note] InnoDB: Using mutexes to ref count buffer pool pages
150908 18:56:02 [Note] InnoDB: The InnoDB memory heap is disabled
150908 18:56:02 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
150908 18:56:02 [Note] InnoDB: Memory barrier is not used
150908 18:56:02 [Note] InnoDB: Compressed tables use zlib 1.2.8
150908 18:56:02 [Note] InnoDB: Using Linux native AIO
150908 18:56:02 [Note] InnoDB: Not using CPU crc32 instructions
150908 18:56:05 [Note] InnoDB: Initializing buffer pool, size = 128.0M
InnoDB: mmap(137363456 bytes) failed; errno 12
150908 18:56:05 [ERROR] InnoDB: Cannot allocate memory for the buffer pool
150908 18:56:05 [ERROR] Plugin 'InnoDB' init function returned error.
150908 18:56:05 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
150908 18:56:06 [Note] Plugin 'FEEDBACK' is disabled.
150908 18:56:06 [ERROR] Unknown/unsupported storage engine: InnoDB
150908 18:56:06 [ERROR] Aborting

150908 18:56:06 [Note] /usr/sbin/mysqld: Shutdown complete

150908 18:56:19 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

Переписал скрипт автоподнятия:
#!/bin/sh

if [[ "$(service mysql status)" =~ "active (running)" ]]
then
    echo "mysql is OK"
else
    echo "mysql is dead!"
    service mysql restart
fi
Who the hell cares?

agentgoblin

Цитата: PeterBumblebee от 08 сентября 2015, 19:39:07150908 18:55:57 [ERROR] mysqld: Out of memory (Needed 128909312 bytes)
Цитата: PeterBumblebee от 08 сентября 2015, 19:39:07150908 18:56:05 [ERROR] InnoDB: Cannot allocate memory for the buffer pool
Не хватает памяти, Карл. В даном случае автоподнятие - это лишь костыль. Ищите, что жрёт память, как советовали ранее. Все краши во всех логах в этом треде начинаются с сообщения о нехватке памяти, проблема очевидна.

PeterBumblebee

Цитата: agentgoblin от 17 сентября 2015, 07:05:17Ищите, что жрёт память, как советовали ранее. Все краши во всех логах в этом треде начинаются с сообщения о нехватке памяти, проблема очевидна.
Я немного не понимаю. База падает, а при чём тут mysqld_safe? Он её пытается перезагрузить зачем-то, но не выходит, так как нехватает памяти.
Вроде же так всё происходит, судя по логам.
А зачем он её перезагружает? Потому что она вылетает из-за нехватки памяти?
Но если она вылетает, то память ведь должна освободиться при этом?
Ничего не понимаю  ???
Who the hell cares?

ogost

mysqld_safe - это грубо говоря скрипт, запускающий mysqld и смотрящий за его состоянием. если mysqld завершился аварийно, то mysqld_safe делает попытку запустить его снова. в случае неудачи прекращает попытки реанимировать mysqld.

судя по вашим логам, в некоторый момент mysqld_safe решает, что mysql завершился аварийно:
Цитата: PeterBumblebee от 08 сентября 2015, 19:39:07150908 18:55:57 mysqld_safe Number of processes running now: 0
и пытается его запустить снова:
Цитата: PeterBumblebee от 08 сентября 2015, 19:39:07150908 18:55:57 mysqld_safe mysqld restarted
150908 18:55:57 [Note] /usr/sbin/mysqld (mysqld 10.0.20-MariaDB-0+deb8u1) starting as process 16042 ...
и тут нежданчик в виде нехватки памяти:
Цитата: PeterBumblebee от 08 сентября 2015, 19:39:07150908 18:55:57 [ERROR] mysqld: Out of memory (Needed 128909312 bytes)
и тут mysqld_safe решает, что пускай оно идет лесом и отключается.

в режиме диванного аналитега предлагаю снова два варианта:
1. mysqld_safe ошибочно считает, что mysqld завершился аварийно и запускает вторую копию mysqld, заведомо натыкаясь на нехватку памяти. крайне маловероятный сценарий.
2. mysqld действительно падает аварийно из-за нехватки памяти (всю память съели другие процессы), и mysqld_safe пытается заново запустить mysql, и опять же заведомо натыкается на нехватку памяти - её ведь съели другие процессы! это уже звучит более правдоподобно.
можете накидать скрипт, который мониторит кто сколько памяти скушал, это позволит уточнить источник проблемы.