Uploaded image for project: 'Percona Server for MySQL'
  1. Percona Server for MySQL
  2. PS-4465

Slave crashes after START SLAVE on Percona Server 5.7.10-3


    • Type: Bug
    • Status: Done
    • Priority: High
    • Resolution: Cannot Reproduce
    • Affects Version/s: 5.7.10-3
    • Fix Version/s: None
    • Component/s: None
    • Labels:



      A simple  START SLAVE crashes down a slave. 

      Stack different from LP #1385508: Slave thread crashes on 'START SLAVE;"

      Master : percona server 5.7.10-3-log, Debian GNU/Linux 8.6 (jessie), Linux 3.14.32-xxxx-grs-ipv6-64 x86_64

      Slave: percona server 5.7.10-3-log, Debian GNU/Linux 8.6 (jessie), Linux 3.14.32-xxxx-grs-ipv6-64 x86_64


      1) mysqladmin shutdown on the slave raises an error on the SQL thread:

      2018-05-04T10:00:38.440360Z 55 [ERROR] Slave SQL for channel '': Fatal error: ... Slave SQL Thread stopped with incomplete event group having non-transactional changes. If the group consists solely of row-based events, you can try to restart the slave with --slave-exec-mode=IDEMPOTENT, which ignores duplicate key, key not found, and similar errors (see documentation for details). Error_code: 1593
      2018-05-04T10:00:38.440395Z 55 [Note] Slave SQL thread for channel '' exiting, replication stopped in log 'mysql-bin-log.001962' at position 828182926
      2018-05-04T10:00:38.459634Z 54 [Note] Slave I/O thread killed while reading event for channel ''
      2018-05-04T10:00:38.459657Z 54 [Note] Slave I/O thread exiting for channel '', read up to log 'mysql-bin-log.001962', position 828233915
      2018-05-04T10:00:38.485249Z 0 [Note] Giving 0 client threads a chance to die gracefully
      2018-05-04T10:00:38.485275Z 0 [Note] Shutting down slave threads
      2018-05-04T10:00:38.486575Z 0 [Note] Forcefully disconnecting 0 remaining clients
      2018-05-04T10:00:38.486666Z 0 [Note] Event Scheduler: Purging the queue. 0 events
      2018-05-04T10:00:38.494984Z 0 [Note] Binlog end
      2018-05-04T10:00:38.571873Z 0 [Note] Shutting down plugin 'ngram'
      2018-05-04T10:00:38.571958Z 0 [Note] Shutting down plugin 'partition'
      2018-05-04T10:00:38.571965Z 0 [Note] Shutting down plugin 'ARCHIVE'
      2018-05-04T10:00:38.571969Z 0 [Note] Shutting down plugin 'FEDERATED'
      2018-05-04T10:00:38.571976Z 0 [Note] Shutting down plugin 'BLACKHOLE'
      2018-05-04T10:00:38.571988Z 0 [Note] Shutting down plugin 'MyISAM'
      2018-05-04T10:00:38.572001Z 0 [Note] Shutting down plugin 'CSV'
      2018-05-04T10:00:38.572005Z 0 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
      2018-05-04T10:00:38.572025Z 0 [Note] Shutting down plugin 'INNODB_SYS_VIRTUAL'
      2018-05-04T10:00:38.572242Z 0 [Note] Shutting down plugin 'INNODB_CHANGED_PAGES'
      2018-05-04T10:00:38.572247Z 0 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
      2018-05-04T10:00:38.572251Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
      2018-05-04T10:00:38.572255Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
      2018-05-04T10:00:38.572258Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
      2018-05-04T10:00:38.572262Z 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
      2018-05-04T10:00:38.572267Z 0 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
      2018-05-04T10:00:38.572271Z 0 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
      2018-05-04T10:00:38.572273Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
      2018-05-04T10:00:38.572276Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
      2018-05-04T10:00:38.572278Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
      2018-05-04T10:00:38.572280Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
      2018-05-04T10:00:38.572282Z 0 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
      2018-05-04T10:00:38.572284Z 0 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
      2018-05-04T10:00:38.572287Z 0 [Note] Shutting down plugin 'INNODB_FT_DELETED'
      2018-05-04T10:00:38.572289Z 0 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
      2018-05-04T10:00:38.572291Z 0 [Note] Shutting down plugin 'INNODB_METRICS'
      2018-05-04T10:00:38.572294Z 0 [Note] Shutting down plugin 'INNODB_TEMP_TABLE_INFO'
      2018-05-04T10:00:38.572296Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
      2018-05-04T10:00:38.572298Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
      2018-05-04T10:00:38.572300Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
      2018-05-04T10:00:38.572303Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
      2018-05-04T10:00:38.572305Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
      2018-05-04T10:00:38.572307Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
      2018-05-04T10:00:38.572310Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM'
      2018-05-04T10:00:38.572313Z 0 [Note] Shutting down plugin 'INNODB_CMP_RESET'
      2018-05-04T10:00:38.572315Z 0 [Note] Shutting down plugin 'INNODB_CMP'
      2018-05-04T10:00:38.572318Z 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
      2018-05-04T10:00:38.572321Z 0 [Note] Shutting down plugin 'INNODB_LOCKS'
      2018-05-04T10:00:38.572323Z 0 [Note] Shutting down plugin 'INNODB_TRX'
      2018-05-04T10:00:38.572326Z 0 [Note] Shutting down plugin 'XTRADB_RSEG'
      2018-05-04T10:00:38.572328Z 0 [Note] Shutting down plugin 'XTRADB_INTERNAL_HASH_TABLES'
      2018-05-04T10:00:38.572331Z 0 [Note] Shutting down plugin 'XTRADB_READ_VIEW'
      2018-05-04T10:00:38.572333Z 0 [Note] Shutting down plugin 'InnoDB'
      2018-05-04T10:00:38.609524Z 0 [Note] InnoDB: FTS optimize thread exiting.
      2018-05-04T10:00:38.609712Z 0 [Note] InnoDB: Starting shutdown...
      2018-05-04T10:00:38.709986Z 0 [Note] InnoDB: Dumping buffer pool(s) to /data/db_repo2/data/ib_buffer_pool
      2018-05-04T10:00:38.730573Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 180504 12:00:38
      2018-05-04T10:00:40.802573Z 0 [Note] InnoDB: Shutdown completed; log sequence number 74886665142
      2018-05-04T10:00:40.805952Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      2018-05-04T10:00:40.805966Z 0 [Note] Shutting down plugin 'MRG_MYISAM'
      2018-05-04T10:00:40.806059Z 0 [Note] Shutting down plugin 'MEMORY'
      2018-05-04T10:00:40.806074Z 0 [Note] Shutting down plugin 'sha256_password'
      2018-05-04T10:00:40.806079Z 0 [Note] Shutting down plugin 'mysql_native_password'
      2018-05-04T10:00:40.806218Z 0 [Note] Shutting down plugin 'binlog'
      2018-05-04T10:00:40.847954Z 0 [Note] mysqld: Shutdown complete

      2) Restart of the slave:

      180504 12:00:53 mysqld_safe Starting mysqld daemon with databases from /data/db_repo2/data
      2018-05-04T10:00:53.511380Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
      2018-05-04T10:00:53.516407Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
      2018-05-04T10:00:53.516444Z 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
      2018-05-04T10:00:53.522458Z 0 [Note] /home/products/mysql/bin//mysqld (mysqld 5.7.10-3) starting as process 14325 ...
      2018-05-04T10:00:53.564160Z 0 [Warning] ignore-builtin-innodb is ignored and will be removed in future releases.
      2018-05-04T10:00:53.564764Z 0 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See http://dev.mysql.com/doc/refman/5.7/en/innodb-file-format.html
      2018-05-04T10:00:53.564825Z 0 [Note] InnoDB: PUNCH HOLE support available
      2018-05-04T10:00:53.564832Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2018-05-04T10:00:53.564836Z 0 [Note] InnoDB: Uses event mutexes
      2018-05-04T10:00:53.564841Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
      2018-05-04T10:00:53.564846Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
      2018-05-04T10:00:53.564849Z 0 [Note] InnoDB: Using Linux native AIO
      2018-05-04T10:00:53.565068Z 0 [Note] InnoDB: Number of pools: 1
      2018-05-04T10:00:53.565232Z 0 [Note] InnoDB: Using CPU crc32 instructions
      2018-05-04T10:00:53.571434Z 0 [Note] InnoDB: Initializing buffer pool, total size = 4G, instances = 8, chunk size = 128M
      2018-05-04T10:00:53.785614Z 0 [Note] InnoDB: Completed initialization of buffer pool
      2018-05-04T10:00:53.821188Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2018-05-04T10:00:53.851441Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
      2018-05-04T10:00:54.073600Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      2018-05-04T10:00:54.073670Z 0 [Note] InnoDB: Setting file '/data/db_repo2/data/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      2018-05-04T10:00:54.086724Z 0 [Note] InnoDB: File '/data/db_repo2/data/ibtmp1' size is now 12 MB.
      2018-05-04T10:00:54.087584Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
      2018-05-04T10:00:54.087596Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
      2018-05-04T10:00:54.087833Z 0 [Note] InnoDB: Waiting for purge to start
      2018-05-04T10:00:54.138006Z 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.10-3 started; log sequence number 74886665142
      2018-05-04T10:00:54.138180Z 0 [Note] InnoDB: Loading buffer pool(s) from /data/db_repo2/data/ib_buffer_pool
      2018-05-04T10:00:54.138244Z 0 [Note] InnoDB: not started
      2018-05-04T10:00:54.138353Z 0 [ERROR] Function 'innodb' already exists
      2018-05-04T10:00:54.138361Z 0 [ERROR] Couldn't load plugin named 'innodb' with soname 'ha_innodb_plugin.so'.
      2018-05-04T10:00:54.204868Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
      2018-05-04T10:00:54.204889Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
      2018-05-04T10:00:54.227879Z 0 [Warning] CA certificate ca.pem is self signed.
      2018-05-04T10:00:54.227933Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
      2018-05-04T10:00:54.267408Z 0 [Note] Server hostname (bind-address): '*'; port: 9996
      2018-05-04T10:00:54.267452Z 0 [Note] IPv6 is available.
      2018-05-04T10:00:54.267460Z 0 [Note] - '::' resolves to '::';
      2018-05-04T10:00:54.267465Z 0 [Note] Server socket created on IP: '::'.
      2018-05-04T10:01:00.870530Z 0 [Note] Event Scheduler: Loaded 0 events
      2018-05-04T10:01:00.870697Z 0 [Note] /home/products/mysql/bin//mysqld: ready for connections.
      Version: '5.7.10-3' socket: '/data/mysql/database2/socket/db_repo.sock' port: 9996 Percona Server (GPL), Release 3, Revision 63dafaf

      3) Starting the slave manually:

      2018-05-04T10:03:17.119991Z 9 [Note] Slave I/O thread for channel '': connected to master 'repl@srv1.alldb.fr:6669',replication started in log 'mysql-bin-log.001962' at position 829455439
      2018-05-04T10:03:29.140087Z 10 [Warning] Slave SQL for channel '': If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
      2018-05-04T10:03:29.143850Z 10 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'mysql-bin-log.001962' at position 828182926, relay log '/data/mysql/database2/log/db_repo-relay-bin.000008' position: 828183147
      10:03:29 UTC - mysqld got signal 11 ;
      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.
      Attempting to collect some information that could help diagnose the problem.
      As this is a crash and something is definitely wrong, the information
      collection process might fail.
      Please help us make Percona Server better by reporting any
      bugs at http://bugs.percona.com/key_buffer_size=33554432
      It is possible that mysqld could use up to
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 112382 K bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.Thread pointer: 0x784c8480e000
      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 = 784db5515980 thread_stack 0x40000
      /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x784dc09d162d]Trying to get some variables.
      Some pointers may be invalid and cause the dump to abort.
      Query (0): Connection ID (thread ID): 10
      Status: NOT_KILLEDYou may download the Percona Server operations manual by visiting
      http://www.percona.com/software/percona-server/. You may find information
      in the manual which will help you identify the cause of the crash.

      This system is in production for us this is critical



        Smart Checklist


            Issue Links



                • Assignee:
                  dbaffaleuf David BAFFALEUF
                • Votes:
                  0 Vote for this issue
                  4 Start watching this issue


                  • Created: