|
Задавайте вопросы, мы ответим
Вы не зашли.
Наблюдаю странную ситуацию при попытке добавить вторую ноду в кластер 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)
Неактивен
Пока непонятно. Когда снимаете 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
и таймаутится. Это, скорее всего, следствие какой-то причины, которую мы тут не видим.
Неактивен
Спасибо за ответ. Весь цикл восстановления занимает ~24h. Как сниму новый трейс, сразу выложу.
Сам Xtrabackup насколько я понимаю проходит успешно. Падает сам иннодб при попытке старта.
Кстати, может есть возможность не повторять весь процесс копирования каждый раз?
Отредактированно Stanislav (31.08.2017 09:43:31)
Неактивен
Насколько я знаю, нет. Ну то есть можно попробовать сэмулировать ситуацию как-то хитро. Все переналивки, насколько я помню галеру, живут в обычных шелл-скриптах. Можно первую переналивку просто закомментировать и надеяться, что позиции не передаются отдельно мимо файлов (вот это не уверен, но почему не попробовать?).
А на тех же серверах, но на какой-нибудь маленькой базе не воспроизводится? Это с кодом связано или с самим набором данных?
Неактивен
На маленьких базах не воспроизводится. Проблемы начинаются гдето с 1,3-1,7 ТБ размера и более 600К таблиц..
Хитро эмулировать боязно. При любой ошибке вторая нода утягивает на дно за собой первую, а старт занимает часы..
Неактивен
Присоединение 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.
Есть смысл логи прикладывать?
Неактивен
Прикладываю свежие логи с -t -s 1024 -f
видно что какой-то таймаут был, но как обычно, без подробностей
Отредактированно Stanislav (02.09.2017 11:27:26)
Неактивен
вот этот кусок из трейса соответствует
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
Неактивен
Так, давайте тогда выливать еще мысли, пока ничего не вижу.
Из странного:
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. Стрейсы на этот раз вообще не информативные — только куски строк 
Давайте попробуем тогда адскую диагностику 
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' '' '
Ну и да, если на маленьких датасетах не воспроизводится, придется искать долго
Неактивен
По моему разумению, все накатки 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----
Неактивен
Вот смущает, что он пустой.
Вообще, идей очень мало, но строчка с IST didn't contain all write sets намекает на то, что данные недопередались. Размер http://galeracluster.com/documentation- … cache-size нормальный? Туда влезают все транзакции? Может, вкрутить его побольше и посмотреть, поможет ли?
Неактивен
Ну и сразу — я не вижу, в чем проблема, пытаемся отгадать вместе
Неактивен
Размер кеша вкрутил до 300ГБ, безрезультатно, хотя была большая надежда. Тоесть, могу ошибаться, но мне кажется мускуль тупо не стартует на наборе данных. Дважды перепроверил - все скрипты отрабатывают и данные допереливаются. Более того, если отрубить галеру или сказать ноде бутсрапнуться - то она почти всегда взлетает. Я планирую отделить прод и вынести два серва с набором данных на другие сервера, ибо ионогда джоинер тащит в могилу мастер-ноду, а старт медленный. Еще Никак не могу уловить, почему каждый раз мускуль говорит, что иннодб потушен некорректно и начинает перечитвать все файло. innodb_fast_shutdown - не помогает. Даже на мастер ноде, которая тушится 100% нормально.
Неактивен
Не понял про некорректность.
Я правильно услышал, что штатный рестарт без синка всё равно считается некорректным? Если да — какой таймаут стоит на service mysql stop? Штатные инитскрипты бывают очень жесткими (типа подождал минуту, а потом придет с девяткой). Можно простым тестом проверить — kill <pid> должен корректно остановить mysql без каких-либо таймаутов.
Если некорректность при переналивке, то это нормальное состояние — xtrabackup копирует изменяющиеся файлы, а потом докатывает изменения, тут должно быть всё хорошо.
Неактивен
Возможно, я не до точно выразился. Иногда, когда джоинер после стягивания реплики , пытается зацепитьяс - на мастере в логах вываливается что-то про cert failure(точно уже не найду) и мастер нода после этого тушится автоматом по внутреннему событию. Так вот, После этого старт мастер ноды всегда с ошибкой not shut down properly - и как следствие, перечитвает всю базу.
Неактивен
Скорее всего, это какой-то внутренний чек, который убивает демона сразу (чтобы не портить данные), а при старте тогда проигрываются журналы, как и при любом другом неудачном падении.
Но это никак, к сожалению, не решает проблему. Не представляю, как тут помочь, если честно. Пока всё указывает на то, что большой объем, и оно спотыкается об него. Можно смотреть в сторону шардирования или других технологий. В 5.7 оракловцы сделали InnoDB cluster. Та же идея, что в галере, но другая реализация. Но — 5.7, как минимум, вам нужно будет сначала на нее перейти. Плюс сам кластер протестировать — непонятно, будет ли он жить нормально.
Неактивен
Решил попробовать перейти на 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 исправит.
Неактивен
То есть всё-таки бага софта? Отлично, что починилось
Неактивен
