SQLinfo.ru - Все о MySQL

Форум пользователей MySQL

Задавайте вопросы, мы ответим

Вы не зашли.

#1 29.08.2017 16:35:00

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Падение PXC 5.6 после успешного SST

Наблюдаю странную ситуацию при попытке добавить вторую ноду в кластер percona galera.
После длительной заливки файлов посредством xtrabackup-v2 (3,5ТБ данных и около 1 000 000 файлов) и успешно пройденных всех этапов, судя по логу - вторая нода падает с абсолютно неинформативной ошибкой:

2017-08-29 07:24:51 14705 [Note] InnoDB: Using Linux native AIO
2017-08-29 07:24:51 14705 [Note] InnoDB: Using CPU crc32 instructions
2017-08-29 07:24:51 14705 [Warning] InnoDB: innodb_file_io_threads is deprecated. Please use innodb_read_io_threads and innodb_write_io_threads instead
2017-08-29 07:24:51 14705 [Note] InnoDB: Initializing buffer pool, size = 10.0G
2017-08-29 07:24:52 14705 [Note] InnoDB: Completed initialization of buffer pool
2017-08-29 07:24:52 14705 [Note] InnoDB: Highest supported file format is Barracuda.
2017-08-29 08:00:55 14705 [Note] WSREP: Created page /var/lib/mysql/gcache.page.000025 of size 134217728 bytes
2017-08-29 08:22:33 14705 [Note] WSREP: Created page /var/lib/mysql/gcache.page.000026 of size 134217728 bytes
2017-08-29 09:22:21 14705 [Note] WSREP: Created page /var/lib/mysql/gcache.page.000027 of size 134217728 bytes
2017-08-29 10:06:55 14705 [Note] InnoDB: 128 rollback segment(s) are active.
2017-08-29 10:06:55 14705 [Note] InnoDB: Waiting for purge to start
2017-08-29 10:06:55 14705 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.0 started; log sequence number 7347200454611
2017-08-29 10:06:55 14705 [ERROR] Aborting

2017-08-29 10:06:55 14705 [Note] WSREP: Signalling cancellation of the SST request.
2017-08-29 10:06:55 14705 [Note] WSREP: SST request was cancelled
2017-08-29 10:06:55 14705 [Note] WSREP: Closing send monitor...
2017-08-29 10:06:55 14705 [Note] WSREP: Closed send monitor.
2017-08-29 10:06:55 14705 [Note] WSREP: gcomm: terminating thread
2017-08-29 10:06:55 14705 [Note] WSREP: gcomm: joining thread
2017-08-29 10:06:55 14705 [Note] WSREP: gcomm: closing backend
2017-08-29 10:06:57 14705 [Note] WSREP: Service disconnected.
2017-08-29 10:06:57 14705 [Note] WSREP: Waiting to close threads......
2017-08-29 10:06:57 14705 [Note] WSREP: rollbacker thread exiting


Возможно кто-нибудь сталкивался и поможет советом. Логи прилагаю файлами

Отредактированно Stanislav (29.08.2017 16:40:23)


Прикрепленные файлы:
Attachment Icon logs.rar, Размер: 640,385 байт, Скачано: 1,108

Неактивен

 

#2 30.08.2017 20:05:27

paulus
Администратор
MySQL Authorized Developer and DBA
Зарегистрирован: 22.01.2007
Сообщений: 6757

Re: Падение PXC 5.6 после успешного SST

Пока непонятно. Когда снимаете strace, делайте, пожалуйста, -t -s 1024 -f, иначе очень сложно сопоставлять логи. Пока что кажется, что стрейс xtrabackup не соответствует error.log.

Из того, что нарыл:

write(2, "2017-08-29 10:06:55 14705 [Note]"..., 68) = 68
select(0, NULL, NULL, NULL, {0, 50000}) = 0 (Timeout)

Вот тут он пытается ждать

2017-08-29 10:06:55 14705 [Note] InnoDB: Waiting for purge to start

и таймаутится. Это, скорее всего, следствие какой-то причины, которую мы тут не видим.

Неактивен

 

#3 31.08.2017 09:39:07

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Re: Падение PXC 5.6 после успешного SST

Спасибо за ответ. Весь цикл восстановления занимает ~24h. Как сниму новый трейс, сразу выложу.
Сам Xtrabackup насколько я понимаю проходит успешно. Падает сам иннодб при попытке старта.
Кстати, может есть возможность не повторять весь процесс копирования каждый раз?

Отредактированно Stanislav (31.08.2017 09:43:31)

Неактивен

 

#4 31.08.2017 12:28:49

paulus
Администратор
MySQL Authorized Developer and DBA
Зарегистрирован: 22.01.2007
Сообщений: 6757

Re: Падение PXC 5.6 после успешного SST

Насколько я знаю, нет. Ну то есть можно попробовать сэмулировать ситуацию как-то хитро. Все переналивки, насколько я помню галеру, живут в обычных шелл-скриптах. Можно первую переналивку просто закомментировать и надеяться, что позиции не передаются отдельно мимо файлов (вот это не уверен, но почему не попробовать?).

А на тех же серверах, но на какой-нибудь маленькой базе не воспроизводится? Это с кодом связано или с самим набором данных?

Неактивен

 

#5 31.08.2017 13:42:39

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Re: Падение PXC 5.6 после успешного SST

На маленьких базах не воспроизводится. Проблемы начинаются гдето с 1,3-1,7 ТБ размера и более 600К таблиц..
Хитро эмулировать боязно. При любой ошибке вторая нода утягивает на дно за собой первую, а старт занимает часы..

Неактивен

 

#6 01.09.2017 12:27:48

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Re: Падение PXC 5.6 после успешного SST

Присоединение strace под конец процесса привело к падению...
170901 07:27:41 >> log scanned up to (7389423472252)
170901 07:27:42 >> log scanned up to (7389423556002)
innobackupex: Error writing file 'UNOPENED' (Errcode: 32 - Broken pipe)
xb_stream_write_data() failed.
innobackupex: Error writing file 'UNOPENED' (Errcode: 32 - Broken pipe)
[01] xtrabackup: Error: xtrabackup_copy_datafile() failed.
[01] xtrabackup: Error: failed to copy datafile.



Есть смысл логи прикладывать?

Неактивен

 

#7 02.09.2017 11:23:16

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Re: Падение PXC 5.6 после успешного SST

Прикладываю свежие логи с -t -s 1024 -f
видно что какой-то таймаут был, но как обычно, без подробностей

Отредактированно Stanislav (02.09.2017 11:27:26)


Прикрепленные файлы:
Attachment Icon 3_1.zip, Размер: 43,802 байт, Скачано: 1,135

Неактивен

 

#8 02.09.2017 14:43:57

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Re: Падение PXC 5.6 после успешного SST

вот этот кусок из трейса соответствует
2017-09-02 03:53:24 17707 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.0 started; log sequence number 7400309372985
2017-09-02 03:53:24 17707 [ERROR] Aborting

https://gyazo.com/9a294b65cedf8595c234218a3d1b0edd

Неактивен

 

#9 05.09.2017 00:08:04

paulus
Администратор
MySQL Authorized Developer and DBA
Зарегистрирован: 22.01.2007
Сообщений: 6757

Re: Падение PXC 5.6 после успешного SST

Так, давайте тогда выливать еще мысли, пока ничего не вижу.

Из странного:
1. В логе joiner вижу, что где-то не подставилась переменная ${DATA}. Вот сомнительные строки:

WSREP_SST: [INFO] Evaluating innobackupex --no-version-check --use-memory=20G --apply-log $rebuildcmd ${DATA} &>${DATA}/innobackup.prepare.log (2017-09-01 23:57:26)
(cut)
rm: cannot remove ‘/var/lib/mysql//innobackup.prepare.log’: No such file or directory

2. Из этого же лога следует, что у Вас два компьютера в кластере, это плохо с точки зрения устойчивости, добавьте хотя бы одного арбитра (это не решит нашу проблему, но повысит выживаемость кластера).

3. Стрейсы на этот раз вообще не информативные — только куски строк sad


Давайте попробуем тогда адскую диагностику smile
https://github.com/percona/percona-xtra … ckup-v2.sh

Это башскрипт, его можно залогировать. Можно попробовать залогировать простым set -x, можно добавить какой-то еще диагностики. Я очень хочу убедиться, что DATA выставляется в правильное значение. После этого я бы попробовал «налить вручную» — запустить донорскую и джоинерскую команду лапами — просто посмотреть, докатится ли xtrabackup, и какие ошибки появятся в процессе:

2017-09-01 13:39:54 2692439 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.11.6:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix ''   '' --gtid 'af81d29b-8a9a-11e7-92d4-962488332acf:16744965''
2017-09-01 13:39:51 17707 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.11.6' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --parent '17707'  '' '

Ну и да, если на маленьких датасетах не воспроизводится, придется искать долго sad

Неактивен

 

#10 07.09.2017 13:42:57

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Re: Падение PXC 5.6 после успешного SST

По моему  разумению, все накатки xtrabackup завершились успешно. Поэтому я сделал следующее - посмотрел в логи uuid и seqno и запустил джоинер вот так: mysqld --wsrep_start_position=37dcf7ea-9256-11e7-8b69-6b7118e1f24a:218432
а перед этим заполнил grastate.dat. Он почемуто постоянно пустой после попытки репликации.

И вот что получил в логе:
---skipped---
2017-09-07 07:41:15 29880 [Warning] InnoDB: innodb_file_io_threads is deprecated. Please use innodb_read_io_threads and innodb_write_io_threads instead
2017-09-07 07:41:15 29880 [Note] InnoDB: Initializing buffer pool, size = 10.0G
2017-09-07 07:41:16 29880 [Note] InnoDB: Completed initialization of buffer pool
2017-09-07 07:41:17 29880 [Note] InnoDB: Highest supported file format is Barracuda.
2017-09-07 07:42:41 29880 [Note] WSREP: gcomm/src/gmcast.cpp:check_liveness():1188: (25f0dfc9, 'tcp://0.0.0.0:4567') turning message relay requesting off
2017-09-07 09:47:13 29880 [Note] InnoDB: 128 rollback segment(s) are active.
2017-09-07 09:47:13 29880 [Note] InnoDB: Waiting for purge to start
2017-09-07 09:47:13 29880 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.0 started; log sequence number 7475454621728
2017-09-07 09:47:13 29880 [ERROR] Aborting

2017-09-07 09:47:13 29880 [Note] WSREP: Signalling cancellation of the SST request.
2017-09-07 09:47:13 29880 [Note] WSREP: galera/src/replicator_str.cpp:sst_received():70: SST request was cancelled
2017-09-07 09:47:14 29880 [ERROR] WSREP: galera/src/ist.cpp:run():473: IST didn't contain all write sets, expected last: 533476 last received: 218433
2017-09-07 09:47:14 29880 [Note] WSREP: gcs/src/gcs_sm.cpp:gcs_sm_close():76: Closing send monitor...
2017-09-07 09:47:14 29880 [Note] WSREP: gcs/src/gcs_sm.cpp:gcs_sm_close():106: Closed send monitor.
2017-09-07 09:47:14 29880 [Note] WSREP: gcs/src/gcs_gcomm.cpp:close():297: gcomm: terminating thread
2017-09-07 09:47:14 29880 [Note] WSREP: gcs/src/gcs_gcomm.cpp:close():300: gcomm: joining thread
2017-09-07 09:47:14 29880 [Note] WSREP: gcs/src/gcs_gcomm.cpp:close():304: gcomm: closing backend
2017-09-07 09:47:15 29880 [Note] WSREP: Service disconnected.
2017-09-07 09:47:15 29880 [Note] WSREP: Waiting to close threads......
2017-09-07 09:47:15 29880 [Note] WSREP: rollbacker thread exiting
2017-09-07 09:47:20 29880 [Note] WSREP: Some threads may fail to exit.
2017-09-07 09:47:20 29880 [Note] Binlog end
2017-09-07 09:47:21 29880 [Note] Shutting down plugin 'partition'
2017-09-07 09:47:21 29880 [Note] Shutting down plugin 'BLACKHOLE'
----skipped----

Неактивен

 

#11 11.09.2017 12:56:36

paulus
Администратор
MySQL Authorized Developer and DBA
Зарегистрирован: 22.01.2007
Сообщений: 6757

Re: Падение PXC 5.6 после успешного SST

Вот смущает, что он пустой.

Вообще, идей очень мало, но строчка с IST didn't contain all write sets намекает на то, что данные недопередались. Размер http://galeracluster.com/documentation- … cache-size нормальный? Туда влезают все транзакции? Может, вкрутить его побольше и посмотреть, поможет ли?

Неактивен

 

#12 11.09.2017 12:57:11

paulus
Администратор
MySQL Authorized Developer and DBA
Зарегистрирован: 22.01.2007
Сообщений: 6757

Re: Падение PXC 5.6 после успешного SST

Ну и сразу — я не вижу, в чем проблема, пытаемся отгадать вместе smile

Неактивен

 

#13 20.09.2017 18:05:59

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Re: Падение PXC 5.6 после успешного SST

Размер кеша вкрутил до 300ГБ, безрезультатно, хотя была большая надежда.  Тоесть, могу ошибаться, но мне кажется мускуль тупо не стартует на наборе данных. Дважды перепроверил - все скрипты отрабатывают и данные допереливаются. Более того, если отрубить галеру или сказать ноде бутсрапнуться - то она почти всегда взлетает. Я планирую отделить прод и вынести два серва с набором данных на другие сервера, ибо ионогда джоинер тащит в могилу мастер-ноду, а старт медленный. Еще Никак не могу уловить, почему каждый раз мускуль говорит, что иннодб потушен некорректно и начинает перечитвать все файло. innodb_fast_shutdown - не помогает. Даже на мастер ноде, которая тушится 100% нормально.

Неактивен

 

#14 20.09.2017 19:18:28

paulus
Администратор
MySQL Authorized Developer and DBA
Зарегистрирован: 22.01.2007
Сообщений: 6757

Re: Падение PXC 5.6 после успешного SST

Не понял про некорректность.

Я правильно услышал, что штатный рестарт без синка всё равно считается некорректным? Если да — какой таймаут стоит на service mysql stop? Штатные инитскрипты бывают очень жесткими (типа подождал минуту, а потом придет с девяткой). Можно простым тестом проверить — kill <pid> должен корректно остановить mysql без каких-либо таймаутов.

Если некорректность при переналивке, то это нормальное состояние — xtrabackup копирует изменяющиеся файлы, а потом докатывает изменения, тут должно быть всё хорошо.

Неактивен

 

#15 21.09.2017 11:41:37

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Re: Падение PXC 5.6 после успешного SST

Возможно, я не до точно выразился. Иногда, когда джоинер после стягивания реплики , пытается зацепитьяс - на мастере в логах вываливается что-то про cert failure(точно уже не найду) и мастер нода после этого тушится автоматом по внутреннему событию. Так вот, После этого старт мастер ноды всегда с ошибкой  not shut down properly - и как следствие, перечитвает всю базу.

Неактивен

 

#16 21.09.2017 22:31:26

paulus
Администратор
MySQL Authorized Developer and DBA
Зарегистрирован: 22.01.2007
Сообщений: 6757

Re: Падение PXC 5.6 после успешного SST

Скорее всего, это какой-то внутренний чек, который убивает демона сразу (чтобы не портить данные), а при старте тогда проигрываются журналы, как и при любом другом неудачном падении.

Но это никак, к сожалению, не решает проблему. Не представляю, как тут помочь, если честно. Пока всё указывает на то, что большой объем, и оно спотыкается об него. Можно смотреть в сторону шардирования или других технологий. В 5.7 оракловцы сделали InnoDB cluster. Та же идея, что в галере, но другая реализация. Но — 5.7, как минимум, вам нужно будет сначала на нее перейти. Плюс сам кластер протестировать — непонятно, будет ли он жить нормально.

Неактивен

 

#17 16.10.2017 13:01:48

Stanislav
Участник
Зарегистрирован: 29.08.2017
Сообщений: 11

Re: Падение PXC 5.6 после успешного SST

Решил попробовать перейти на percona-galera-5.7. Скачал сразу самую последнюю версию, предварительно вычистив два из трех серверов от старых скриптов/бинарей. Поправил в wsrep_sst_xtrabackp-v2 параметр в функции wait_for_listen : for i in {1..300}
и mysql-systemd : statup_sleep=9000
и все взлетело. вплоть до 2ТБ и 1М файлов ни разу синхронизация чистой ноды не упала. Если интересно, могу приложить свои конфиги.

P.S. столкнулся с https://bugs.launchpad.net/percona-server/+bug/1653764 при попытке интенсивной записи на две ноды одновременно через haproxy. Возможно innodb_adaptive_hash_index=0 исправит.

Неактивен

 

#18 17.10.2017 02:31:24

paulus
Администратор
MySQL Authorized Developer and DBA
Зарегистрирован: 22.01.2007
Сообщений: 6757

Re: Падение PXC 5.6 после успешного SST

То есть всё-таки бага софта? Отлично, что починилось smile

Неактивен

 

Board footer

Работает на PunBB
© Copyright 2002–2008 Rickard Andersson