Uploaded image for project: 'Percona XtraDB Cluster'
  1. Percona XtraDB Cluster
  2. PXC-1993

LP #1703127: Crash and corruption after enabling innodb_undo_log_truncate

    Details

    • Type: Bug
    • Status: Done
    • Priority: Low
    • Resolution: Incomplete
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None
    • Labels:

      Description

      **Reported in Launchpad by Ivan Vanyushkin last update 10-09-2017 04:17:29

      Environment: Percona XtraDB 5.7.18-15, upgraded from Percona XtraDB 5.6.36-82.0.
      I've run:

      SET GLOBAL innodb_undo_log_truncate=ON;
      SET GLOBAL innodb_purge_rseg_truncate_frequency=5;

      Relevant settings:

      innodb_undo_directory = /var/lib/mysql/innodb_log
      innodb_undo_tablespaces = 4
      innodb_undo_logs = 35

      After UNDO log truncation started, DB has crashed with corruption, log:

      2017-07-07T14:12:20.781878Z 0 [Warning] WSREP: Node is not a cluster node. Disabling pxc_strict_mode
      2017-07-07T14:12:20.781891Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.18-15-57-log) starting as process 619335 ...
      2017-07-07T14:12:21.495640Z 0 [Note] InnoDB: PUNCH HOLE support available
      2017-07-07T14:12:21.495650Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2017-07-07T14:12:21.495654Z 0 [Note] InnoDB: Uses event mutexes
      2017-07-07T14:12:21.495658Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
      2017-07-07T14:12:21.495675Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
      2017-07-07T14:12:21.495681Z 0 [Note] InnoDB: Using Linux native AIO
      2017-07-07T14:12:21.496281Z 0 [Note] InnoDB: Number of pools: 1
      2017-07-07T14:12:21.496399Z 0 [Note] InnoDB: Using CPU crc32 instructions
      2017-07-07T14:12:21.498276Z 0 [Note] InnoDB: Initializing buffer pool, total size = 70G, instances = 8, chunk size = 128M
      2017-07-07T14:12:23.670437Z 0 [Note] InnoDB: Completed initialization of buffer pool
      2017-07-07T14:12:24.505302Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2017-07-07T14:12:24.519781Z 0 [Note] InnoDB: Crash recovery did not find the parallel doublewrite buffer at /var/lib/mysql/data/xb_doublewrite
      2017-07-07T14:12:24.520995Z 0 [Note] InnoDB: Opened 4 undo tablespaces
      2017-07-07T14:12:24.521008Z 0 [Note] InnoDB: 4 undo tablespaces made active
      2017-07-07T14:12:24.521240Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
      2017-07-07T14:12:25.302975Z 0 [Note] InnoDB: Created parallel doublewrite buffer at /var/lib/mysql/data/xb_doublewrite, size 31457280 bytes
      2017-07-07T14:12:26.350034Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      2017-07-07T14:12:26.350120Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      2017-07-07T14:12:26.381664Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
      2017-07-07T14:12:26.382616Z 0 [Note] InnoDB: 3 redo rollback segment(s) found. 3 redo rollback segment(s) are active.
      2017-07-07T14:12:26.382635Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
      2017-07-07T14:12:26.385188Z 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.18-15 started; log sequence number 560659204343170
      2017-07-07T14:12:26.385388Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/data/ib_buffer_pool
      2017-07-07T14:12:26.385659Z 0 [Note] Plugin 'FEDERATED' is disabled.
      2017-07-07T14:12:26.402728Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
      2017-07-07T14:12:26.402754Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
      2017-07-07T14:12:26.408391Z 0 [Warning] CA certificate ca.pem is self signed.
      2017-07-07T14:12:26.408446Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
      2017-07-07T14:12:26.408741Z 0 [Note] Server hostname (bind-address): '::'; port: 3306
      2017-07-07T14:12:26.408759Z 0 [Note] - '::' resolves to '::';
      2017-07-07T14:12:26.408782Z 0 [Note] Server socket created on IP: '::'.
      2017-07-07T14:12:26.408812Z 0 [Note] Server hostname (bind-address): '::'; port: 3307
      2017-07-07T14:12:26.408817Z 0 [Note] - '::' resolves to '::';
      2017-07-07T14:12:26.408824Z 0 [Note] Server socket created on IP: '::'.
      2017-07-07T14:12:26.428747Z 0 [Note] Event Scheduler: Loaded 0 events
      2017-07-07T14:12:26.428946Z 0 [Note] WSREP: Found pre-stored initial position: 80814749-ff7f-0000-0084-4749ff7f0000:0
      2017-07-07T14:12:26.428956Z 0 [Note] WSREP: wsrep_load(): loading provider library 'none'
      2017-07-07T14:12:26.429065Z 0 [Note] /usr/sbin/mysqld: ready for connections.
      Version: '5.7.18-15-57-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Percona XtraDB Cluster (GPL), Release rel15, Revision 7693d6e, WSREP version 29.20, wsrep_29.20
      2017-07-07T14:12:26.429074Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check.
      2017-07-07T14:12:26.429077Z 0 [Note] Beginning of list of non-natively partitioned tables
      2017-07-07T14:12:26.444084Z 0 [Note] End of list of non-natively partitioned tables
      2017-07-07T14:12:28.091159Z 4 [Note] Access denied for user 'root'@'localhost' (using password: NO)
      2017-07-07T14:13:02.207020Z 0 [Note] InnoDB: Buffer pool(s) load completed at 170707 17:13:02
      2017-07-07T14:20:11.338033Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 1
      2017-07-07T14:21:22.454040Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 1
      2017-07-07 17:21:22 0x7f98eeffd700 InnoDB: Assertion failure in thread 140294821500672 in file fut0lst.ic line 85
      InnoDB: Failing assertion: addr.page == FIL_NULL || addr.boffset >= FIL_PAGE_DATA
      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.7/en/forcing-innodb-recovery.html
      InnoDB: about forcing recovery.
      14:21:22 UTC - 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.
      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 XtraDB Cluster better by reporting any
      bugs at https://bugs.launchpad.net/percona-xtradb-cluster

      key_buffer_size=8589934592
      read_buffer_size=131072
      max_used_connections=27
      max_threads=100001
      thread_count=3
      connection_count=3
      It is possible that mysqld could use up to
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 46803239 K bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.

      Thread pointer: 0x7f98f0000900
      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 = 7f98eeffcdc0 thread_stack 0x40000
      /usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xf0bb9c]
      /usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7ac271]
      /lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7fad89037330]
      /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7fad88474c37]
      /lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7fad88478028]
      /usr/sbin/mysqld[0x775f16]
      /usr/sbin/mysqld[0x775a04]
      /usr/sbin/mysqld[0x11600cd]
      /usr/sbin/mysqld[0x1165ff9]
      /usr/sbin/mysqld(_Z9trx_purgemmb+0x8db)[0x1166bab]
      /usr/sbin/mysqld(srv_purge_coordinator_thread+0xa28)[0x113e428]
      /lib/x86_64-linux-gnu/libpthread.so.0(+0x8184)[0x7fad8902f184]
      /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fad8853bffd]

      Trying to get some variables.
      Some pointers may be invalid and cause the dump to abort.
      Query (0): is an invalid pointer
      Connection ID (thread ID): 0
      Status: NOT_KILLED

      You may download the Percona XtraDB Cluster operations manual by visiting
      http://www.percona.com/software/percona-xtradb-cluster/. You may find information
      in the manual which will help you identify the cause of the crash.
      --------------------------------------------------------------------------

      At this point one undo log was truncated:

      root@host:/var/lib/mysql/innodb_log# ls -al
      total 401533900
      drwxr-xr-x 2 mysql mysql 98 Jul 7 17:21 .
      drwx------ 6 mysql mysql 78 Jun 27 2016 ..
      rw-r---- 1 mysql mysql 10737418240 Jul 7 19:16 ib_logfile0
      rw-r---- 1 mysql mysql 10737418240 Jul 7 17:08 ib_logfile1
      rw-rw--- 1 mysql mysql 10485760 Jul 7 17:21 undo001
      ^^^ this file was as large as others before execution ^^^
      rw-rw--- 1 mysql mysql 140219777024 Jul 7 17:21 undo002
      rw-rw--- 1 mysql mysql 124285616128 Jul 7 17:12 undo003
      rw-rw--- 1 mysql mysql 125179002880 Jul 7 17:12 undo004

      After restarting database got crash:

      2017-07-07T14:21:24.347237Z 0 [Note] InnoDB: PUNCH HOLE support available
      2017-07-07T14:21:24.347254Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2017-07-07T14:21:24.347262Z 0 [Note] InnoDB: Uses event mutexes
      2017-07-07T14:21:24.347269Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
      2017-07-07T14:21:24.347276Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
      2017-07-07T14:21:24.347299Z 0 [Note] InnoDB: Using Linux native AIO
      2017-07-07T14:21:24.347891Z 0 [Note] InnoDB: Number of pools: 1
      2017-07-07T14:21:24.348032Z 0 [Note] InnoDB: Using CPU crc32 instructions
      2017-07-07T14:21:24.349946Z 0 [Note] InnoDB: Initializing buffer pool, total size = 70G, instances = 8, chunk size = 128M
      2017-07-07T14:21:26.543556Z 0 [Note] InnoDB: Completed initialization of buffer pool
      2017-07-07T14:21:27.440389Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2017-07-07T14:21:27.455383Z 0 [Note] InnoDB: Recovering partial pages from the parallel doublewrite buffer at /var/lib/mysql/data/xb_doublewrite
      2017-07-07T14:21:27.501977Z 0 [Note] InnoDB: Opened 4 undo tablespaces
      2017-07-07T14:21:27.502015Z 0 [Note] InnoDB: 4 undo tablespaces made active
      2017-07-07T14:21:27.502301Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
      2017-07-07T14:21:28.072805Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 560659204826256
      2017-07-07T14:21:28.072864Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 560659204826328
      2017-07-07T14:21:28.631903Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 560659204826328
      2017-07-07T14:21:28.631977Z 0 [Note] InnoDB: Database was not shutdown normally!
      2017-07-07T14:21:28.631983Z 0 [Note] InnoDB: Starting crash recovery.
      2017-07-07T14:21:28.632605Z 0 [Warning] InnoDB: Page 9 in the doublewrite buffer is not within space bounds: page [page id: space=1, page number=163879]
      2017-07-07T14:21:28.632620Z 0 [Warning] InnoDB: Page 12 in the doublewrite buffer is not within space bounds: page [page id: space=1, page number=5013558]
      2017-07-07T14:21:28.632642Z 0 [Warning] InnoDB: Page 19 in the doublewrite buffer is not within space bounds: page [page id: space=1, page number=8831016]
      2017-07-07T14:21:28.635579Z 0 [Warning] InnoDB: Page 47 in the doublewrite buffer is not within space bounds: page [page id: space=1, page number=8576653]
      2017-07-07T14:21:29.147234Z 0 [Note] InnoDB: Created parallel doublewrite buffer at /var/lib/mysql/data/xb_doublewrite, size 31457280 bytes
      2017-07-07 17:21:29 0x7f364a85b780 InnoDB: Assertion failure in thread 139871155238784 in file fut0lst.ic line 85
      InnoDB: Failing assertion: addr.page == FIL_NULL || addr.boffset >= FIL_PAGE_DATA
      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.7/en/forcing-innodb-recovery.html
      InnoDB: about forcing recovery.
      14:21:29 UTC - 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.
      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 XtraDB Cluster better by reporting any
      bugs at https://bugs.launchpad.net/percona-xtradb-cluster

      key_buffer_size=8589934592
      read_buffer_size=131072
      max_used_connections=0
      max_threads=100001
      thread_count=0
      connection_count=0
      It is possible that mysqld could use up to
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 46803239 K bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.

      Thread pointer: 0x0
      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 = 0 thread_stack 0x40000
      /usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xf0bb9c]
      /usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7ac271]
      /lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f3648f8f330]
      /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f36483ccc37]
      /lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f36483d0028]
      /usr/sbin/mysqld[0x775f16]
      /usr/sbin/mysqld(_Z22trx_undo_free_preparedP5trx_t+0x0)[0x775cc8]
      /usr/sbin/mysqld(_Z19trx_undo_lists_initP10trx_rseg_t+0xdfc)[0x119639c]
      /usr/sbin/mysqld[0x117abb1]
      /usr/sbin/mysqld[0x117d577]
      /usr/sbin/mysqld(_Z24trx_sys_init_at_db_startv+0x1883)[0x1184603]
      /usr/sbin/mysqld(_Z34innobase_start_or_create_for_mysqlv+0x497e)[0x114bd2e]
      /usr/sbin/mysqld[0x1006188]
      /usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x51)[0x823901]
      /usr/sbin/mysqld[0xcfbf16]
      /usr/sbin/mysqld(_Z11plugin_initPiPPci+0x5f0)[0xd032c0]
      /usr/sbin/mysqld[0x7a4090]
      /usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x66e)[0x7a57be]
      /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f36483b7f45]
      /usr/sbin/mysqld[0x798f74]
      You may download the Percona XtraDB Cluster operations manual by visiting
      http://www.percona.com/software/percona-xtradb-cluster/. You may find information
      in the manual which will help you identify the cause of the crash.
      --------------------------------------------------------------------------

      I was able to start DB only with innodb_force_recovery=5.

      Packages:
      ii percona-xtradb-cluster-client-5.7 5.7.18-29.20-1.trusty amd64
      ii percona-xtradb-cluster-common-5.6 5.6.36-26.20-1.trusty amd64
      ii percona-xtradb-cluster-common-5.7 5.7.18-29.20-1.trusty amd64
      ii percona-xtradb-cluster-server-5.7 5.7.18-29.20-1.trusty amd64

        Smart Checklist

          Attachments

            Activity

              People

              • Assignee:
                krunal.bauskar Krunal Bauskar
                Reporter:
                lpjirasync lpjirasync (Inactive)
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated: