| 2016-10-26 22:47:00 |
Ivgeni Segal |
description |
There appears to be an intermittent hard to reproduce crash when creating SPATIAL index or inserting into a table with a SPATIAL index.
We were able to catch it at 100% success by performing a DELETE * FROM table and cancelling the delete so that an undo operation is performed and which subsequently crashes and places the server into 100% crash reproducibility loop.
Attached is the log of the start, as well as GDB session showing backtrace and local variables.
We saved the core file so please feel free to let us know if there are any particular variables you would like to examine.
2016-10-26T22:26:40.798737Z 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 65535)
2016-10-26T22:26:40.798886Z 0 [Warning] Changed limits: max_connections: 214 (requested 1000)
2016-10-26T22:26:40.798894Z 0 [Warning] Changed limits: table_open_cache: 400 (requested 2048)
2016-10-26T22:26:41.138365Z 0 [Warning] The use of InnoDB is mandatory since MySQL 5.7. The former options like '--innodb=0/1/OFF/ON' or '--skip-innodb' are ignored.
2016-10-26T22:26:41.138431Z 0 [Warning] The syntax 'avoid_temporal_upgrade' is deprecated and will be removed in a future release
2016-10-26T15:26:41.138552-08:00 0 [Warning] The use of InnoDB is mandatory since MySQL 5.7. The former options like '--innodb=0/1/OFF/ON' or '--skip-innodb' are ignored.
2016-10-26T15:26:41.138560-08:00 0 [Warning] The syntax 'avoid_temporal_upgrade' is deprecated and will be removed in a future release
2016-10-26T15:26:41.138655-08:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-10-26T15:26:41.138691-08:00 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2016-10-26T15:26:41.143780-08:00 0 [Note] /usr/sbin/mysqld (mysqld 5.7.15-9-log) starting as process 2303 ...
2016-10-26T15:26:41.198004-08: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
2016-10-26T15:26:41.198163-08:00 0 [Note] InnoDB: PUNCH HOLE support available
2016-10-26T15:26:41.198214-08:00 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-10-26T15:26:41.198233-08:00 0 [Note] InnoDB: Uses event mutexes
2016-10-26T15:26:41.198249-08:00 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-10-26T15:26:41.198265-08:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-10-26T15:26:41.198293-08:00 0 [Note] InnoDB: Using Linux native AIO
2016-10-26T15:26:41.199181-08:00 0 [Note] InnoDB: Number of pools: 1
2016-10-26T15:26:41.199624-08:00 0 [Note] InnoDB: Using CPU crc32 instructions
2016-10-26T15:26:41.206069-08:00 0 [Note] InnoDB: Initializing buffer pool, total size = 4.5G, instances = 4, chunk size = 128M
2016-10-26T15:26:41.708020-08:00 0 [Note] InnoDB: Completed initialization of buffer pool
2016-10-26T15:26:41.899299-08:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2016-10-26T15:26:41.932764-08:00 0 [Note] InnoDB: Recovering partial pages from the parallel doublewrite buffer at /vol/data-files/mysql/xb_doublewrite
2016-10-26T15:26:41.966581-08:00 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-10-26T15:26:42.111877-08:00 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 74203403885
2016-10-26T15:26:42.146248-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74208646656
2016-10-26T15:26:42.179297-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74213889536
2016-10-26T15:26:42.207753-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74218373807
2016-10-26T15:26:42.357286-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74204124672
2016-10-26T15:26:42.403936-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74209367552
2016-10-26T15:26:42.450803-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74214610432
2016-10-26T15:26:42.484691-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74218373807
2016-10-26T15:26:42.484999-08:00 0 [Note] InnoDB: Database was not shutdown normally!
2016-10-26T15:26:42.485036-08:00 0 [Note] InnoDB: Starting crash recovery.
2016-10-26T15:26:43.010409-08:00 0 [Note] InnoDB: Created parallel doublewrite buffer at /vol/data-files/mysql/xb_doublewrite, size 15728640 bytes
2016-10-26T15:26:43.913424-08:00 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 92661 row operations to undo
2016-10-26T15:26:43.913493-08:00 0 [Note] InnoDB: Trx id counter is 73206528
2016-10-26T15:26:43.914279-08:00 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
2016-10-26T15:26:44.937905-08:00 0 [Note] InnoDB: Apply batch completed
2016-10-26T15:26:44.938012-08:00 0 [Note] InnoDB: Last MySQL binlog file position 0 5887, file name mysql-bin.000071
2016-10-26T15:26:44.975231-08:00 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions
2016-10-26T15:26:44.975294-08:00 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2016-10-26T15:26:44.975313-08:00 0 [Note] InnoDB: Rolling back trx with id 73206045, 92661 rows to undo
2016-10-26T15:26:44.975354-08:00 0 [Note] InnoDB: Creating shared tablespace for temporary tables
InnoDB: Progress in percents: 12016-10-26T15:26:44.975505-08:00 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
22:32:17 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
read_buffer_size=131072
max_used_connections=0
max_threads=215
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 = 117962 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)[0xec804c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x79e2f1]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7ffff671c330]
/usr/sbin/mysqld(_Z26page_cur_search_with_matchPK11buf_block_tPK12dict_index_tPK8dtuple_t15page_cur_mode_tPmS9_P10page_cur_tP8rtr_info+0x1b1)[0xfe6351]
/usr/sbin/mysqld(_Z27btr_cur_search_to_nth_levelP12dict_index_tmPK8dtuple_t15page_cur_mode_tmP9btr_cur_tmPKcmP5mtr_t+0x12b9)[0x1110f79]
/usr/sbin/mysqld(_Z17rtr_pcur_open_lowP12dict_index_tmPK8dtuple_t15page_cur_mode_tmP10btr_pcur_tPKcmP5mtr_t+0xfa)[0x121b1aa]
/usr/sbin/mysqld(_Z22row_search_index_entryP12dict_index_tPK8dtuple_tmP10btr_pcur_tP5mtr_t+0x4f)[0x1059b6f]
/usr/sbin/mysqld[0x122c188]
/usr/sbin/mysqld(_Z12row_undo_modP11undo_node_tP9que_thr_t+0x55c)[0x122e80c]
/usr/sbin/mysqld(_Z13row_undo_stepP9que_thr_t+0x6c)[0x1074d2c]
/usr/sbin/mysqld(_Z15que_run_threadsP9que_thr_t+0x874)[0x1006064]
/usr/sbin/mysqld(_Z31trx_rollback_or_clean_recoveredm+0xd01)[0x10ca931]
/usr/sbin/mysqld(trx_rollback_or_clean_all_recovered+0x49)[0x10cb849]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8184)[0x7ffff6714184]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7ffff5c2137d]
You 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. |
Distribution Ubuntu
Package: percona-server-server-5.7 5.7.15-9-1.trusty
Distributor ID: Ubuntu
Description: Ubuntu 14.04.4 LTS
Release: 14.04
Codename: trusty
There appears to be an intermittent hard to reproduce crash when creating SPATIAL index or inserting into a table with a SPATIAL index.
We were able to catch it at 100% success by performing a DELETE * FROM table and cancelling the delete so that an undo operation is performed and which subsequently crashes and places the server into 100% crash reproducibility loop.
Attached is the log of the start, as well as GDB session showing backtrace and local variables.
We saved the core file so please feel free to let us know if there are any particular variables you would like to examine.
2016-10-26T22:26:40.798737Z 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 65535)
2016-10-26T22:26:40.798886Z 0 [Warning] Changed limits: max_connections: 214 (requested 1000)
2016-10-26T22:26:40.798894Z 0 [Warning] Changed limits: table_open_cache: 400 (requested 2048)
2016-10-26T22:26:41.138365Z 0 [Warning] The use of InnoDB is mandatory since MySQL 5.7. The former options like '--innodb=0/1/OFF/ON' or '--skip-innodb' are ignored.
2016-10-26T22:26:41.138431Z 0 [Warning] The syntax 'avoid_temporal_upgrade' is deprecated and will be removed in a future release
2016-10-26T15:26:41.138552-08:00 0 [Warning] The use of InnoDB is mandatory since MySQL 5.7. The former options like '--innodb=0/1/OFF/ON' or '--skip-innodb' are ignored.
2016-10-26T15:26:41.138560-08:00 0 [Warning] The syntax 'avoid_temporal_upgrade' is deprecated and will be removed in a future release
2016-10-26T15:26:41.138655-08:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-10-26T15:26:41.138691-08:00 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2016-10-26T15:26:41.143780-08:00 0 [Note] /usr/sbin/mysqld (mysqld 5.7.15-9-log) starting as process 2303 ...
2016-10-26T15:26:41.198004-08: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
2016-10-26T15:26:41.198163-08:00 0 [Note] InnoDB: PUNCH HOLE support available
2016-10-26T15:26:41.198214-08:00 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-10-26T15:26:41.198233-08:00 0 [Note] InnoDB: Uses event mutexes
2016-10-26T15:26:41.198249-08:00 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-10-26T15:26:41.198265-08:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-10-26T15:26:41.198293-08:00 0 [Note] InnoDB: Using Linux native AIO
2016-10-26T15:26:41.199181-08:00 0 [Note] InnoDB: Number of pools: 1
2016-10-26T15:26:41.199624-08:00 0 [Note] InnoDB: Using CPU crc32 instructions
2016-10-26T15:26:41.206069-08:00 0 [Note] InnoDB: Initializing buffer pool, total size = 4.5G, instances = 4, chunk size = 128M
2016-10-26T15:26:41.708020-08:00 0 [Note] InnoDB: Completed initialization of buffer pool
2016-10-26T15:26:41.899299-08:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2016-10-26T15:26:41.932764-08:00 0 [Note] InnoDB: Recovering partial pages from the parallel doublewrite buffer at /vol/data-files/mysql/xb_doublewrite
2016-10-26T15:26:41.966581-08:00 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-10-26T15:26:42.111877-08:00 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 74203403885
2016-10-26T15:26:42.146248-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74208646656
2016-10-26T15:26:42.179297-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74213889536
2016-10-26T15:26:42.207753-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74218373807
2016-10-26T15:26:42.357286-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74204124672
2016-10-26T15:26:42.403936-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74209367552
2016-10-26T15:26:42.450803-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74214610432
2016-10-26T15:26:42.484691-08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 74218373807
2016-10-26T15:26:42.484999-08:00 0 [Note] InnoDB: Database was not shutdown normally!
2016-10-26T15:26:42.485036-08:00 0 [Note] InnoDB: Starting crash recovery.
2016-10-26T15:26:43.010409-08:00 0 [Note] InnoDB: Created parallel doublewrite buffer at /vol/data-files/mysql/xb_doublewrite, size 15728640 bytes
2016-10-26T15:26:43.913424-08:00 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 92661 row operations to undo
2016-10-26T15:26:43.913493-08:00 0 [Note] InnoDB: Trx id counter is 73206528
2016-10-26T15:26:43.914279-08:00 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
2016-10-26T15:26:44.937905-08:00 0 [Note] InnoDB: Apply batch completed
2016-10-26T15:26:44.938012-08:00 0 [Note] InnoDB: Last MySQL binlog file position 0 5887, file name mysql-bin.000071
2016-10-26T15:26:44.975231-08:00 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions
2016-10-26T15:26:44.975294-08:00 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2016-10-26T15:26:44.975313-08:00 0 [Note] InnoDB: Rolling back trx with id 73206045, 92661 rows to undo
2016-10-26T15:26:44.975354-08:00 0 [Note] InnoDB: Creating shared tablespace for temporary tables
InnoDB: Progress in percents: 12016-10-26T15:26:44.975505-08:00 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
22:32:17 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
read_buffer_size=131072
max_used_connections=0
max_threads=215
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 = 117962 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)[0xec804c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x79e2f1]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7ffff671c330]
/usr/sbin/mysqld(_Z26page_cur_search_with_matchPK11buf_block_tPK12dict_index_tPK8dtuple_t15page_cur_mode_tPmS9_P10page_cur_tP8rtr_info+0x1b1)[0xfe6351]
/usr/sbin/mysqld(_Z27btr_cur_search_to_nth_levelP12dict_index_tmPK8dtuple_t15page_cur_mode_tmP9btr_cur_tmPKcmP5mtr_t+0x12b9)[0x1110f79]
/usr/sbin/mysqld(_Z17rtr_pcur_open_lowP12dict_index_tmPK8dtuple_t15page_cur_mode_tmP10btr_pcur_tPKcmP5mtr_t+0xfa)[0x121b1aa]
/usr/sbin/mysqld(_Z22row_search_index_entryP12dict_index_tPK8dtuple_tmP10btr_pcur_tP5mtr_t+0x4f)[0x1059b6f]
/usr/sbin/mysqld[0x122c188]
/usr/sbin/mysqld(_Z12row_undo_modP11undo_node_tP9que_thr_t+0x55c)[0x122e80c]
/usr/sbin/mysqld(_Z13row_undo_stepP9que_thr_t+0x6c)[0x1074d2c]
/usr/sbin/mysqld(_Z15que_run_threadsP9que_thr_t+0x874)[0x1006064]
/usr/sbin/mysqld(_Z31trx_rollback_or_clean_recoveredm+0xd01)[0x10ca931]
/usr/sbin/mysqld(trx_rollback_or_clean_all_recovered+0x49)[0x10cb849]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8184)[0x7ffff6714184]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7ffff5c2137d]
You 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. |
|
