Assertion failure in Xtrabackup --stats run on MySQL datadir (xtrabackup_56)

Reported by Sergei Glushchenko on 2013-05-02
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraBackup
High
Alexey Kopytov
2.0
High
Alexey Kopytov
2.1
High
Alexey Kopytov

Bug Description

I am running xtrabackup_56 --stats on server data directory and getting following assertion failure

2013-05-02 18:31:12 7fff7c5aa960 InnoDB: Assertion failure in thread 140735279704416 in file mtr0mtr.cc line 317
InnoDB: Failing assertion: !srv_read_only_mode
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.

Full log is following:

test❯ gdb --args /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/../src/xtrabackup_56 --defaults-file=/Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/var1/my.cnf --stats --datadir=/Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/var1/data --innodb_log_group_home_dir=/Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/logs
GNU gdb 6.3.50-20050815 (Apple version gdb-1824) (Wed Feb 6 22:51:23 UTC 2013)
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "x86_64-apple-darwin"...Reading symbols for shared libraries ... done

(gdb) r
Starting program: /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/src/xtrabackup_56 --defaults-file=/Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/var1/my.cnf --stats --datadir=/Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/var1/data --innodb_log_group_home_dir=/Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/logs
Reading symbols for shared libraries ++......................... done
/Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/src/xtrabackup_56 version 2.0.6 for MySQL server 5.6.10 osx10.7 (x86_64) (revision id: undefined)
xtrabackup: cd to /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/var1/data
xtrabackup: Target instance is assumed as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/logs
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 50331648
xtrabackup: Starting 'read-only' InnoDB instance to gather index statistics.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Started in read only mode
2013-05-02 18:31:10 7fff7c5aa960 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2013-05-02 18:31:10 7fff7c5aa960 InnoDB: !!!!!!!! UNIV_IBUF_DEBUG switched on !!!!!!!!!
2013-05-02 18:31:10 7fff7c5aa960 InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2013-05-02 18:31:10 7fff7c5aa960 InnoDB: !!!!!!!! UNIV_SEARCH_DEBUG switched on !!!!!!!!!
2013-05-02 18:31:10 7fff7c5aa960 InnoDB: !!!!!!!! UNIV_LOG_LSN_DEBUG switched on !!!!!!!!!
2013-05-02 18:31:10 7fff7c5aa960 InnoDB: !!!!!!!! UNIV_MEM_DEBUG switched on !!!!!!!!!
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3 with validation
InnoDB: CPU does not support crc32 instructions
InnoDB: Disabling background IO write threads.
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
Io handler thread 0 starts, id 4446801920
Io handler thread 1 starts, id 4452352000
Io handler thread 2 starts, id 4452888576
Io handler thread 3 starts, id 4453425152
InnoDB: Highest supported file format is Barracuda.
2013-05-02 18:31:12 7fff7c5aa960 InnoDB: Assertion failure in thread 140735279704416 in file mtr0mtr.cc line 317
InnoDB: Failing assertion: !srv_read_only_mode
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.

Program received signal SIGABRT, Aborted.
0x00007fff9235fce2 in __pthread_kill ()
(gdb) bt
#0 0x00007fff9235fce2 in __pthread_kill ()
#1 0x00007fff936b37d2 in pthread_kill ()
#2 0x00007fff936a4a7a in abort ()
#3 0x000000010032ca2b in mtr_commit (mtr=0x7fff5fbf9ff8) at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/mtr/mtr0mtr.cc:317
#4 0x00000001004929c6 in trx_sys_file_format_max_write (format_id=0, name=0x0) at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/trx/trx0sys.cc:646
#5 0x000000010049284c in trx_sys_file_format_max_set (format_id=0, name=0x0) at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/trx/trx0sys.cc:773
#6 0x0000000100492a34 in trx_sys_file_format_tag_init () at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/trx/trx0sys.cc:797
#7 0x000000010045dfab in innobase_start_or_create_for_mysql () at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/srv/srv0start.cc:2455
#8 0x000000010000877d in innodb_init () at xtrabackup.cc:3422
#9 0x00000001000049a9 in xtrabackup_stats_func () at xtrabackup.cc:6145
#10 0x0000000100002ca3 in main (argc=0, argv=0x101b010f0) at xtrabackup.cc:8618
(gdb) bt full
#0 0x00007fff9235fce2 in __pthread_kill ()
No symbol table info available.
#1 0x00007fff936b37d2 in pthread_kill ()
No symbol table info available.
#2 0x00007fff936a4a7a in abort ()
No symbol table info available.
#3 0x000000010032ca2b in mtr_commit (mtr=0x7fff5fbf9ff8) at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/mtr/mtr0mtr.cc:317
No locals.
#4 0x00000001004929c6 in trx_sys_file_format_max_write (format_id=0, name=0x0) at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/trx/trx0sys.cc:646
  mtr = {
  state = 56456,
  memo = {
    heap = 0x0,
    used = 32,
    data = "\002\000\000\000\000\000\000\000�\020�\002\001\000\000\0006\000\000\000\000\000\000\000�\020�\002\001\000\000\000t�", '\0' <repeats 14 times>, "\020\000\000\000\000\000\000\000\002", '\0' <repeats 15 times>, "t�\000\000\000\000\000\000�z�\t\001\000\000\000\000\002\000\001\000\000\000\000\002", '\0' <repeats 15 times>, "\002", '\0' <repeats 15 times>, "\002", '\0' <repeats 15 times>, "\002", '\0' <repeats 15 times>, "\002", '\0' <repeats 15 times>, "\002", '\0' <repeats 15 times>, "\002", '\0' <repeats 15 times>, "\002", '\0' <repeats 15 times>, "\002", '\0' <repeats 15 times>, "\002", '\0' <repeats 15 times>, "\002\000\000"...,
    base = {
      count = 140734799782480,
      start = 0x7fff5fc0ef50,
      end = 0x101223b01
    },
    list = {
      prev = 0x7fff5fbfa390,
      next = 0x7fff5fc3d140
    },
    buf_end = 0,
    magic_n = 375767
  },
  log = {
    heap = 0x0,
    used = 14,
    data = "\b\000\005?��r��P[�\000\000\001;\"\001\001", '\0' <repeats 35 times>, "���_�\000\0008��_�\000\000ࢿ_�\000\000���_�\000\000\020Q�_�\000\000���_�\000\000���_�\000\000\000;\"\001\001\000\000\000\001\000\000\000\000\000\000\000\020Q�_�\000\0000��_�\000\000�v�_�\000\000���_�\000\000Y\001\000\000\000\000\000\000\001;\"\001\001\000\000\000�A\"\001\001\000\000\000�\004�\000\001\000\000\000\017;\"\001\001\000\000\000\001;\"\001\001\000\000\000\001\000\000\000\000\000\000\000��_�\000\000�"...,
    base = {
      count = 4299771424,
      start = 0x4330000000000000,
      end = 0x300
    },
    list = {
      prev = 0x100ab1fe2,
      next = 0x101116460
    },
    buf_end = 0,
    magic_n = 375767
  },
  inside_ibuf = 0,
  modifications = 1,
  made_dirty = 1,
  n_log_recs = 1,
  n_freed_pages = 0,
  log_mode = 21,
  start_lsn = 140734799783184,
  end_lsn = 0,
  magic_n = 54551
}
  ptr = (unsigned char *) 0x102c67ff0 "��r��P[�\024�\036B"
  block = (buf_block_t *) 0x102801080
  tag_value = 11793927649537055617
#5 0x000000010049284c in trx_sys_file_format_max_set (format_id=0, name=0x0) at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/trx/trx0sys.cc:773
  ret = 0
#6 0x0000000100492a34 in trx_sys_file_format_tag_init () at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/trx/trx0sys.cc:797
  format_id = 18446744073709551615
#7 0x000000010045dfab in innobase_start_or_create_for_mysql () at /Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/mysql-5.6/storage/innobase/srv/srv0start.cc:2455
  sum_of_data_file_sizes = 0
  err = DB_SUCCESS
  i = 2
  logfile0 = 0x0
  unit = 77 'M'
  min_flushed_lsn = 1638320
  srv_n_log_files_found = 2
  dirnamelen = 69
  size = 100
  io_limit = 256
  mtr = {
  state = 7882826764524942637,
  memo = {
    heap = 0x617261702079726f,
    used = 2860321072244077,
    data = "�\n�\001\001\000\000\000�\n�\001\001\000\000\000�\n�\001\001\000\000\000 ޿_�\000\000�\n�\001\001\000\000\000\001\000\000\000\002\000\000\000h޿_�\000\000Rإ\000�\001\000\000\a\031�X�E�[�޿_�\000\000^�\006\000\001\000\000\000\020�\001\002\001\000\000\000�߿_�\000\000\000\000\000\000\000\000\000\000p\t�\001�\000\000\000X�_�\000\000h޿_�\000\000\000\000\000\000\000\000\000\000?�_�\000\000\001\000\000\000\000\000\000\000p��_�\000\000�޿_�\000\000`K�_�\000\000�޿_�\000\000P�_�\000\000"...,
    base = {
      count = 4313988493,
      start = 0x101223d83,
      end = 0x1
    },
    list = {
      prev = 0x7fff5fbfe080,
      next = 0x7fff5fc179cd
    },
    buf_end = 4313988483,
    magic_n = 140734800059248
  },
  log = {
    heap = 0x7fff5fbfe060,
    used = 140734799891296,
    data = "/+j��\000\000��_�\000\000�;\"\001\001\000\000\000��_�\0001\a\031�X�E�[��_�\000\000\000\002\000\000\000\000\000\000��_�\000\000jd�\000\001\000\000\000�0Z|�\000\000 �_�\000\000�Nj��\000\000\000\000\000\000\000\000\000\000���2", '\0' <repeats 72 times>, "\003", '\0' <repeats 99 times>, "\a\031�X�E�[", '\0' <repeats 32 times>, "\020�_�\000\000�.\000\000\001\000\000\000��_�\000\000\000��_�\000\000\000\000@\006", '\0' <repeats 12 times>, "\002\000\000\000\000\000\000"...,
    base = {
      count = 0,
      start = 0x0,
      end = 0x7fff5fbfe300
    },
    list = {
      prev = 0x6400000,
      next = 0x0
    },
    buf_end = 2,
    magic_n = 3270308424552834418
  },
  inside_ibuf = 0,
  modifications = 1,
  made_dirty = 0,
  n_log_recs = 163780800,
  n_freed_pages = 85899346421,
  log_mode = 0,
  start_lsn = 1367494240,
  end_lsn = 0,
  magic_n = 1367494241
}
  logfilename = "/Users/sergei/percona/repo/xb-bug1174314/2.0-xb-bug1174314/test/logs/ib_logfile1\000t\020\001\001\000\000\000\000\000\000\002\000\000\000\000���_�\000\000ål��\000\000��\001\001\000\000\000 :�\000\001\000\000\0007:�\000\001\000\000\000\003\000\000�\000\000\000\000��_�\000\000\000\000\000\000\000\000\000\000���_�\000\000p�_�\000\000\000\000\000\000\000\000\000\000\a\031�X�E�[ ��_�\000\000"...
  create_new_db = 0
  max_flushed_lsn = 1638320
  sum_of_new_sizes = 0
  tablespace_size_in_header = 1367494240
  ib_bh = (struct ib_bh_t *) 0x10a003600
#8 0x000000010000877d in innodb_init () at xtrabackup.cc:3422
  err = 1486297351
#9 0x00000001000049a9 in xtrabackup_stats_func () at xtrabackup.cc:6145
  n = 2
#10 0x0000000100002ca3 in main (argc=0, argv=0x101b010f0) at xtrabackup.cc:8618
  ho_error = 0
(gdb) q

description: updated
affects: percona-server → percona-xtrabackup

Assertion failed when server tries to update max file format in datafiles being run in read only mode. xtrabackup prior to 5.6 sets srv_max_file_format_at_startup as DICT_TF_FORMAT_51 (which is 0 or UNIV_FORMAT_A, Antelope format) while 5.6-based version sets it to UNIV_FORMAT_MAX (which is 1 or UNIV_FORMAT_B or DICT_F_FORMAT_ZIP, Barracuda format).

I can propose 2 solutions:
1. Set srv_max_file_format_at_startup to 0 for 5.6 as well
2. Patch InnoDB to not update file format tag at startup

Is there an upstream InnoDB bug in there in that it tries to update the format tag on a read-only server? I.e. --innodb-read-only does not work with --innodb-file-format-max=Barracuda after the database was tagged with Antelope?

Checking file format is a good idea, so that someone with an ancient XB binary does not corrupt his Cheetah database by accident in 10 years, thus I think it's better not set srv_max_file_format_at_startup to 0 if possible/practical.

Alexey Kopytov (akopytov) wrote :

This has nothing to do with both srv_max_file_format_at_startup and file format checking.

It's just that InnoDB wants to update the system tablespace unconditionally with the _minimum_ supported format on startup, if the corresponding field in the transaction system header is not initialized. I.e. it doesn't honor srv_read_only, reported as http://bugs.mysql.com/bug.php?id=69131

An uninitialized transaction system header can be a result of either

- old datafiles created with MySQL 5.0 or MySQL 5.1 with built-in InnoDB
or
- empty page, i.e. a new system tablespace has been created, but the corresponding file format tag update has not been flushed yet. This is what we are hitting here.

So we need to fix http://bugs.mysql.com/bug.php?id=69131. File format checks are made irregardless of the file_format_on_startup value.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.