crash when upgrading to 5.7 if changed pages bitmap is ON

[Rick Pizzi]

When upgrading Percona Server from 5.6 to 5.7, we consistently get a server crash upon starting 5.7 the first time, if the changed pages bitmap is used.

How to repeat:

- Install Percona Server 5.6.x
- ensure innodb_track_changed_pages=ON
- try to upgrade to Percons Server 5.7.x

Observe the following crash when starting the database with the 5.7.x binaries:

2017-11-02T10:54:40.046846+01:00 0 [Note] /usr/sbin/mysqld (mysqld 5.7.19-17-log) starting as process 30166 ...
2017-11-02T10:54:40.063031+01:00 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
2017-11-02T10:54:40.063206+01:00 0 [Note] InnoDB: PUNCH HOLE support available
2017-11-02T10:54:40.063227+01:00 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-11-02T10:54:40.063235+01:00 0 [Note] InnoDB: Uses event mutexes
2017-11-02T10:54:40.063242+01:00 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-11-02T10:54:40.063248+01:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-11-02T10:54:40.063255+01:00 0 [Note] InnoDB: Using Linux native AIO
2017-11-02T10:54:40.065254+01:00 0 [Note] InnoDB: Number of pools: 1
2017-11-02T10:54:40.065405+01:00 0 [Note] InnoDB: Using CPU crc32 instructions
2017-11-02T10:54:40.068154+01:00 0 [Note] InnoDB: Initializing buffer pool, total size = 160G, instances = 8, chunk size = 128M
2017-11-02T10:54:45.943203+01:00 0 [Note] InnoDB: Completed initialization of buffer pool
2017-11-02T10:54:48.245071+01:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-11-02T10:54:48.266791+01:00 0 [Note] InnoDB: Crash recovery did not find the parallel doublewrite buffer at /dbstorage/data/mysql5/xb_doublewrite
2017-11-02T10:54:48.267535+01:00 0 [Note] InnoDB: Highest supported file format is Barracuda.
2017-11-02T10:54:48.676832+01:00 0 [Note] InnoDB: Created parallel doublewrite buffer at /dbstorage/data/mysql5/xb_doublewrite, size 31457280 bytes
2017-11-02T10:54:51.638645+01:00 0 [Warning] InnoDB: Upgrading redo log: 2*32768 pages, LSN=87147368226450
2017-11-02T10:54:51.739300+01:00 0 [Note] InnoDB: Tracking redo log synchronously until 87147368226450
09:54:51 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=16777216
read_buffer_size=2097152
max_used_connections=0
max_threads=2501
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 = 25651593 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)[0xed36bc]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7a26e1]
/lib64/libpthread.so.0(+0xf7e0)[0x7fbbcbfda7e0]
/usr/sbin/mysqld(_Z26log_online_follow_redo_logv+0x190)[0xfb1000]
/usr/sbin/mysqld(_Z34innobase_start_or_create_for_mysqlv+0x5a5e)[0x1098ace]
/usr/sbin/mysqld[0xf53c70]
/usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x51)[0x802fe1]
/usr/sbin/mysqld[0xcd0226]
/usr/sbin/mysqld(_Z11plugin_initPiPPci+0x5f0)[0xcd6ff0]
/usr/sbin/mysqld[0x79af0b]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x64e)[0x79c4fe]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7fbbca1ffd1d]
/usr/sbin/mysqld[0x792165]

Fix is to disable innodb_track_changed_pages, start the server, then stop it and re-enable innodb_track_changed_pages and start again.

I believe the innodb_track_changed_pages feature is looking for redo logs which are yet to be (re)created and this is where it crashes.

[Nickolay Ihalainen (ihanick)]

docker run -it --name lp1734116 --entrypoint=/bin/bash percona:5.6
mysql_install_db
chown mysql:mysql /var/lib/mysql
add user=mysql and innodb_track_changed_pages=ON to [mysqld] section
mysqld & (5.6.37-82.2 started)
use test
create table t(c int) engine=innodb;
insert into t values (1);
set global innodb_fast_shutdown=0;
mysqladmin shutdown
apt-get update
apt-get install -y percona-server-server-5.7
apt-get install -y percona-server-5.7-dbg
mysqld --version
mysqld Ver 5.7.19-17 for debian-linux-gnu on x86_64 (Percona Server (GPL), Release '17', Revision 'e19a6b7b73f')

Or just use mysql.tar.gz as datadir and start mysql 5.7 with --innodb-track-changed_pages=1

Same stack trace:
0x0000000000f9b843 in log_online_follow_redo_log ()
    at /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/debian-jessie-64bit/percona-server-5.7-5.7.19-17/storage/innobase/log/log0online.cc:1288
1288 log_bmp_sys->end_lsn = log_sys->last_checkpoint_lsn;
(gdb) bt
#0 0x0000000000f9b843 in log_online_follow_redo_log ()
    at /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/debian-jessie-64bit/percona-server-5.7-5.7.19-17/storage/innobase/log/log0online.cc:1288
#1 0x000000000108793e in innobase_start_or_create_for_mysql ()
    at /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/debian-jessie-64bit/percona-server-5.7-5.7.19-17/storage/innobase/srv/srv0start.cc:2481
#2 0x0000000000f3be19 in innobase_init (p=<optimized out>)
    at /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/debian-jessie-64bit/percona-server-5.7-5.7.19-17/storage/innobase/handler/ha_innodb.cc:4353
#3 0x00000000007fc011 in ha_initialize_handlerton (plugin=0x1ff4718)
    at /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/debian-jessie-64bit/percona-server-5.7-5.7.19-17/sql/handler.cc:871
#4 0x0000000000c895f6 in plugin_initialize (plugin=plugin@entry=0x1ff4718)
    at /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/debian-jessie-64bit/percona-server-5.7-5.7.19-17/sql/sql_plugin.cc:1223
#5 0x0000000000c913b8 in plugin_init (argc=argc@entry=0x1dc8200 <remaining_argc>, argv=0x1ea9f10, flags=flags@entry=0)
    at /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/debian-jessie-64bit/percona-server-5.7-5.7.19-17/sql/sql_plugin.cc:1565
#6 0x00000000007932a6 in init_server_components () at /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/debian-jessie-64bit/percona-server-5.7-5.7.19-17/sql/mysqld.cc:4296
#7 0x0000000000794a49 in mysqld_main (argc=16, argv=0x1ea9f10)
    at /mnt/workspace/percona-server-5.7-debian-binary-rocks/label_exp/debian-jessie-64bit/percona-server-5.7-5.7.19-17/sql/mysqld.cc:5001
#8 0x00007ffff5b40b45 in __libc_start_main (main=0x7716e0 <main(int, char**)>, argc=1, argv=0x7fffffffec48, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>,
    stack_end=0x7fffffffec38) at libc-start.c:287
#9 0x000000000078afb4 in _start ()
(gdb) p log_bmp_sys
$1 = (log_bitmap_struct *) 0x0
(gdb) list
1283 return true;
1284 }
1285
1286 /* Grab the LSN of the last checkpoint, we will parse up to it */
1287...

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1128