Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.4.13
-
None
Description
After update MariaDb server from 10.3.21 to 10.4.13 server is crashed twice in the last week.
There are logs from journalctl
May 28 02:55:33 db-slave mysqld: 2020-05-28 02:55:33 0x7fd1e80f4700 InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.4.13/storage/innobase/row/row0ins.cc line 231 |
May 28 02:55:33 db-slave mysqld: InnoDB: Failing assertion: !cursor->index->is_committed() |
May 28 02:55:33 db-slave mysqld: InnoDB: We intentionally generate a memory trap. |
May 28 02:55:33 db-slave mysqld: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/ |
May 28 02:55:33 db-slave mysqld: InnoDB: If you get repeated assertion failures or crashes, even |
May 28 02:55:33 db-slave mysqld: InnoDB: immediately after the mysqld startup, there may be |
May 28 02:55:33 db-slave mysqld: InnoDB: corruption in the InnoDB tablespace. Please refer to |
May 28 02:55:33 db-slave mysqld: InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/ |
May 28 02:55:33 db-slave mysqld: InnoDB: about forcing recovery. |
May 28 02:55:33 db-slave mysqld: 200528 2:55:33 [ERROR] mysqld got signal 6 ; |
May 28 02:55:33 db-slave mysqld: This could be because you hit a bug. It is also possible that this binary |
May 28 02:55:33 db-slave mysqld: or one of the libraries it was linked against is corrupt, improperly built, |
May 28 02:55:33 db-slave mysqld: or misconfigured. This error can also be caused by malfunctioning hardware. |
May 28 02:55:33 db-slave mysqld: To report this bug, see https://mariadb.com/kb/en/reporting-bugs |
May 28 02:55:33 db-slave mysqld: We will try our best to scrape up some info that will hopefully help |
May 28 02:55:33 db-slave mysqld: diagnose the problem, but since we have already crashed, |
May 28 02:55:33 db-slave mysqld: something is definitely wrong and this may fail. |
May 28 02:55:33 db-slave mysqld: Server version: 10.4.13-MariaDB-log |
May 28 02:55:33 db-slave mysqld: key_buffer_size=134217728 |
May 28 02:55:33 db-slave mysqld: read_buffer_size=131072 |
May 28 02:55:33 db-slave mysqld: max_used_connections=338 |
May 28 02:55:33 db-slave mysqld: max_threads=5002 |
May 28 02:55:33 db-slave mysqld: thread_count=355 |
May 28 02:55:33 db-slave mysqld: It is possible that mysqld could use up to |
May 28 02:55:33 db-slave mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11138886 K bytes of memory |
May 28 02:55:33 db-slave mysqld: Hope that's ok; if not, decrease some variables in the equation. |
May 28 02:55:33 db-slave mysqld: Thread pointer: 0x7fc02c0009a8 |
May 28 02:55:33 db-slave mysqld: Attempting backtrace. You can use the following information to find out |
May 28 02:55:33 db-slave mysqld: where mysqld died. If you see no messages after this, something went |
May 28 02:55:33 db-slave mysqld: terribly wrong... |
May 28 02:55:33 db-slave mysqld: stack_bottom = 0x7fd1e80f3ce0 thread_stack 0x49000 |
May 28 02:55:34 db-slave mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x5633b8f796ce] |
May 28 02:55:36 db-slave mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x5633b8a0ff7f] |
May 28 02:55:38 db-slave mysqld: /lib64/libpthread.so.0(+0xf5f0)[0x7fd207b505f0] |
May 28 02:55:41 db-slave mysqld: /lib64/libc.so.6(gsignal+0x37)[0x7fd205e21337] |
May 28 02:55:41 db-slave mysqld: /lib64/libc.so.6(abort+0x148)[0x7fd205e22a28] |
May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0x5b346a)[0x5633b871346a] |
May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb10cd4)[0x5633b8c70cd4] |
May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb10fd3)[0x5633b8c70fd3] |
May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb46d31)[0x5633b8ca6d31] |
May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb4c16a)[0x5633b8cac16a] |
May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb22c5b)[0x5633b8c82c5b] |
May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xa66bbc)[0x5633b8bc6bbc] |
May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhS1_+0x267)[0x5633b8a1b8c7] |
May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEP14rpl_group_info+0x291)[0x5633b8b181f1] |
May 28 02:55:46 db-slave mysqld: /usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEP14rpl_group_info+0x2dc)[0x5633b8b0aa0c] |
May 28 02:55:46 db-slave mysqld: /usr/sbin/mysqld(+0x5ffce8)[0x5633b875fce8] |
May 28 02:55:46 db-slave mysqld: /usr/sbin/mysqld(+0x7dacde)[0x5633b893acde] |
May 28 02:55:46 db-slave mysqld: /usr/sbin/mysqld(handle_rpl_parallel_thread+0x7bb)[0x5633b893d24b] |
May 28 02:55:48 db-slave mysqld: /lib64/libpthread.so.0(+0x7e65)[0x7fd207b48e65] |
May 28 02:55:51 db-slave mysqld: /lib64/libc.so.6(clone+0x6d)[0x7fd205ee988d] |
May 28 02:55:51 db-slave mysqld: Trying to get some variables. |
May 28 02:55:51 db-slave mysqld: Some pointers may be invalid and cause the dump to abort. |
May 28 02:55:51 db-slave mysqld: Query (0x7fc0d4ce590b): UPDATE ourTableName SET `ip` = '127.0.0.1', `updatedAt` = '2020-05-28T02:55:33Z' WHERE id = 12345678 |
May 28 02:55:51 db-slave mysqld: Connection ID (thread ID): 39 |
May 28 02:55:51 db-slave mysqld: Status: NOT_KILLED |
May 28 02:55:51 db-slave mysqld: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on |
May 28 02:55:51 db-slave mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains |
May 28 02:55:51 db-slave mysqld: information that should help you find out what is causing the crash. |
May 28 02:55:51 db-slave mysqld: Writing a core file... |
May 28 02:55:51 db-slave mysqld: Working directory at /var/lib/mysql |
May 28 02:55:51 db-slave mysqld: Resource Limits: |
May 28 02:55:51 db-slave mysqld: Limit Soft Limit Hard Limit Units |
May 28 02:55:51 db-slave mysqld: Max cpu time unlimited unlimited seconds |
May 28 02:55:51 db-slave mysqld: Max file size unlimited unlimited bytes |
May 28 02:55:51 db-slave mysqld: Max data size unlimited unlimited bytes |
May 28 02:55:51 db-slave mysqld: Max stack size 8388608 unlimited bytes |
May 28 02:55:51 db-slave mysqld: Max core file size 0 unlimited bytes |
May 28 02:55:51 db-slave mysqld: Max resident set unlimited unlimited bytes |
May 28 02:55:51 db-slave mysqld: Max processes 514547 514547 processes |
May 28 02:55:51 db-slave mysqld: Max open files 16364 16364 files |
May 28 02:55:51 db-slave mysqld: Max locked memory 65536 65536 bytes |
May 28 02:55:51 db-slave mysqld: Max address space unlimited unlimited bytes |
May 28 02:55:51 db-slave mysqld: Max file locks unlimited unlimited locks |
May 28 02:55:51 db-slave mysqld: Max pending signals 514547 514547 signals |
May 28 02:55:51 db-slave mysqld: Max msgqueue size 819200 819200 bytes |
May 28 02:55:51 db-slave mysqld: Max nice priority 0 0 |
May 28 02:55:51 db-slave mysqld: Max realtime priority 0 0 |
May 28 02:55:51 db-slave mysqld: Max realtime timeout unlimited unlimited us |
May 28 02:55:51 db-slave mysqld: Core pattern: co... |
May 28 02:56:01 db-slave systemd: mariadb.service: main process exited, code=killed, status=6/ABRT |
May 28 02:56:01 db-slave systemd: Unit mariadb.service entered failed state. |
May 28 02:56:01 db-slave systemd: mariadb.service failed. |
May 28 02:56:05 db-slave mysqld_exporter: time="2020-05-28T02:56:05Z" level=error msg="Error pinging mysqld: dial tcp [::1]:3306: connect: connection refused" source="exporter.go:146" |
May 28 02:56:06 db-slave systemd: mariadb.service holdoff time over, scheduling restart. |
May 28 02:56:06 db-slave systemd: Stopped MariaDB 10.4.13 database server. |
May 28 02:56:06 db-slave systemd: Starting MariaDB 10.4.13 database server... |
May 28 02:56:06 db-slave mysqld: 2020-05-28 2:56:06 0 [Note] /usr/sbin/mysqld (mysqld 10.4.13-MariaDB-log) starting as process 25946 ... |
May 28 02:56:06 db-slave mysqld: 2020-05-28 2:56:06 0 [Warning] Could not increase number of max_open_files to more than 16364 (request: 37055) |
May 28 02:56:06 db-slave mysqld: 2020-05-28 2:56:06 0 [Note] InnoDB: Using Linux native AIO |
May 28 02:56:06 db-slave mysqld: 2020-05-28 2:56:06 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins |
May 28 02:56:06 db-slave mysqld: 2020-05-28 2:56:06 0 [Note] InnoDB: Uses event mutexes |
May 28 02:56:06 db-slave mysqld: 2020-05-28 2:56:06 0 [Note] InnoDB: Compressed tables use zlib 1.2.7 |
May 28 02:56:06 db-slave mysqld: 2020-05-28 2:56:06 0 [Note] InnoDB: Number of pools: 1 |
May 28 02:56:06 db-slave mysqld: 2020-05-28 2:56:06 0 [Note] InnoDB: Using SSE2 crc32 instructions |
May 28 02:56:06 db-slave mysqld: 2020-05-28 2:56:06 0 [Note] InnoDB: Initializing buffer pool, total size = 66G, instances = 24, chunk size = 128M |
May 28 02:56:09 db-slave mysqld: 2020-05-28 2:56:09 0 [Note] InnoDB: Completed initialization of buffer pool |
May 28 02:56:09 db-slave mysqld: 2020-05-28 2:56:09 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). |
May 28 02:56:09 db-slave mysqld: 2020-05-28 2:56:09 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=53195850341358 |
May 28 02:56:10 db-slave mysqld: 2020-05-28 2:56:10 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo |
May 28 02:56:10 db-slave mysqld: 2020-05-28 2:56:10 0 [Note] InnoDB: Trx id counter is 30000635124 |
May 28 02:56:10 db-slave mysqld: 2020-05-28 2:56:10 0 [Note] InnoDB: Starting final batch to recover 4620 pages from redo log. |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: Last binlog file './mysqld-bin.035240', position 370109787 |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: 128 out of 128 rollback segments are active. |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: Starting in background the rollback of recovered transactions |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: Creating shared tablespace for temporary tables |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: Rolled back recovered transaction 30000635119 |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: Rollback of non-prepared transactions completed |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: Waiting for purge to start |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: 10.4.13 started; log sequence number 53195850342929; transaction id 30000635127 |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] Plugin 'FEEDBACK' is disabled. |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [ERROR] mysqld: Plugin 'file_key_management' already installed |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] Using encryption key id 1 for temporary files |
May 28 02:56:11 db-slave mysqld: 2020-05-28 2:56:11 0 [Note] Recovering after a crash using mysqld-bin |
May 28 02:56:12 db-slave mysqld: 2020-05-28 2:56:12 0 [Note] Starting crash recovery... |
May 28 02:56:12 db-slave mysqld: 2020-05-28 2:56:12 0 [Note] Crash recovery finished. |
May 28 02:56:12 db-slave mysqld: 2020-05-28 2:56:12 0 [Note] Server socket created on IP: '::'. |
May 28 02:56:12 db-slave mysqld: 2020-05-28 2:56:12 0 [Note] Reading of all Master_info entries succeeded |
May 28 02:56:12 db-slave mysqld: 2020-05-28 2:56:12 0 [Note] Added new Master_info '' to hash table |
May 28 02:56:12 db-slave mysqld: 2020-05-28 2:56:12 10 [Note] Slave I/O thread: Start asynchronous replication to master 'repl@172.16.11.102:3306' in log 'mysqld-bin.001446' at position 4 |
May 28 02:56:12 db-slave mysqld: 2020-05-28 2:56:12 11 [Note] Slave SQL thread initialized, starting replication in log 'mysqld-bin.001446' at position 4, relay log './mysqld-relay-bin.000001' position: 4; GTID position '0-1-1799532479,1-1-9932339280,3-3-3238391981,7-7-5053890666' |
May 28 02:56:12 db-slave mysqld: 2020-05-28 2:56:12 0 [Note] /usr/sbin/mysqld: ready for connections. |
May 28 02:56:12 db-slave mysqld: Version: '10.4.13-MariaDB-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server |
May 28 02:56:12 db-slave mysqld: 2020-05-28 2:56:12 10 [Note] Slave I/O thread: connected to master 'user_for_replication@MASTER_IP_WAS_HERE:3306',replication starts at GTID position '1-1-9932339280,0-1-1799532479,3-3-3238391981,7-7-5053890666' |
Attachments
Issue Links
- is duplicated by
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
MDEV-27734 Set innodb_change_buffering=none by default
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
(6 relates to)
Activity
The slave DB has been crashed again after about 3 weeks uptime. Possible it was crashed after this query (same for previous crash), but I noticed the column "ip" has BTREE index, maybe it will be helpful for you.
The query is:
Jun 13 09:47:56 db-slave mysqld[25946]: Query (0x7f04bdaf140b): UPDATE tableName SET ip = '1.1.1.1', updatedAt = '2020-06-13T09:47:36Z' WHERE id = 12345 |
Full log:
Jun 13 09:47:36 db-slave mysqld: 2020-06-13 09:47:36 0x7f1660098700 InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.4.13/storage/innobase/row/row0ins.cc line 231 |
Jun 13 09:47:36 db-slave mysqld: InnoDB: Failing assertion: !cursor->index->is_committed() |
Jun 13 09:47:36 db-slave mysqld: InnoDB: We intentionally generate a memory trap. |
Jun 13 09:47:36 db-slave mysqld: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/ |
Jun 13 09:47:36 db-slave mysqld: InnoDB: If you get repeated assertion failures or crashes, even |
Jun 13 09:47:36 db-slave mysqld: InnoDB: immediately after the mysqld startup, there may be |
Jun 13 09:47:36 db-slave mysqld: InnoDB: corruption in the InnoDB tablespace. Please refer to |
Jun 13 09:47:36 db-slave mysqld: InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/ |
Jun 13 09:47:36 db-slave mysqld: InnoDB: about forcing recovery. |
Jun 13 09:47:36 db-slave mysqld: 200613 9:47:36 [ERROR] mysqld got signal 6 ; |
Jun 13 09:47:36 db-slave mysqld: This could be because you hit a bug. It is also possible that this binary |
Jun 13 09:47:36 db-slave mysqld: or one of the libraries it was linked against is corrupt, improperly built, |
Jun 13 09:47:36 db-slave mysqld: or misconfigured. This error can also be caused by malfunctioning hardware. |
Jun 13 09:47:36 db-slave mysqld: To report this bug, see https://mariadb.com/kb/en/reporting-bugs |
Jun 13 09:47:36 db-slave mysqld: We will try our best to scrape up some info that will hopefully help |
Jun 13 09:47:36 db-slave mysqld: diagnose the problem, but since we have already crashed, |
Jun 13 09:47:36 db-slave mysqld: something is definitely wrong and this may fail. |
Jun 13 09:47:36 db-slave mysqld: Server version: 10.4.13-MariaDB-log |
Jun 13 09:47:36 db-slave mysqld: key_buffer_size=134217728 |
Jun 13 09:47:36 db-slave mysqld: read_buffer_size=131072 |
Jun 13 09:47:36 db-slave mysqld: max_used_connections=2354 |
Jun 13 09:47:36 db-slave mysqld: max_threads=5002 |
Jun 13 09:47:36 db-slave mysqld: thread_count=2059 |
Jun 13 09:47:36 db-slave mysqld: It is possible that mysqld could use up to |
Jun 13 09:47:36 db-slave mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11138886 K bytes of memory |
Jun 13 09:47:36 db-slave mysqld: Hope that's ok; if not, decrease some variables in the equation. |
Jun 13 09:47:36 db-slave mysqld: Thread pointer: 0x7f04bc001298 |
Jun 13 09:47:36 db-slave mysqld: Attempting backtrace. You can use the following information to find out |
Jun 13 09:47:36 db-slave mysqld: where mysqld died. If you see no messages after this, something went |
Jun 13 09:47:36 db-slave mysqld: terribly wrong... |
Jun 13 09:47:36 db-slave mysqld: stack_bottom = 0x7f16600975c0 thread_stack 0x49000 |
Jun 13 09:47:38 db-slave mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x556874deb6ce] |
Jun 13 09:47:38 db-slave mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x556874881f7f] |
Jun 13 09:47:42 db-slave mysqld: /lib64/libpthread.so.0(+0xf5f0)[0x7f16698f95f0] |
Jun 13 09:47:45 db-slave mysqld: /lib64/libc.so.6(gsignal+0x37)[0x7f1667bca337] |
Jun 13 09:47:45 db-slave mysqld: /lib64/libc.so.6(abort+0x148)[0x7f1667bcba28] |
Jun 13 09:47:49 db-slave mysqld: /usr/sbin/mysqld(+0x5b346a)[0x55687458546a] |
Jun 13 09:47:49 db-slave mysqld: /usr/sbin/mysqld(+0xb10cd4)[0x556874ae2cd4] |
Jun 13 09:47:49 db-slave mysqld: /usr/sbin/mysqld(+0xb10fd3)[0x556874ae2fd3] |
Jun 13 09:47:49 db-slave mysqld: /usr/sbin/mysqld(+0xb46d31)[0x556874b18d31] |
Jun 13 09:47:50 db-slave mysqld: /usr/sbin/mysqld(+0xb4c16a)[0x556874b1e16a] |
Jun 13 09:47:50 db-slave mysqld: /usr/sbin/mysqld(+0xb22c5b)[0x556874af4c5b] |
Jun 13 09:47:50 db-slave mysqld: /usr/sbin/mysqld(+0xa66bbc)[0x556874a38bbc] |
Jun 13 09:47:50 db-slave mysqld: /usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhS1_+0x267)[0x55687488d8c7] |
Jun 13 09:47:50 db-slave mysqld: /usr/sbin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEP14rpl_group_info+0x291)[0x55687498a1f1] |
Jun 13 09:47:50 db-slave mysqld: /usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEP14rpl_group_info+0x2dc)[0x55687497ca0c] |
Jun 13 09:47:50 db-slave mysqld: /usr/sbin/mysqld(+0x5ffce8)[0x5568745d1ce8] |
Jun 13 09:47:50 db-slave mysqld: /usr/sbin/mysqld(handle_slave_sql+0x1506)[0x5568745db4e6] |
Jun 13 09:47:53 db-slave mysqld: /lib64/libpthread.so.0(+0x7e65)[0x7f16698f1e65] |
Jun 13 09:47:56 db-slave mysqld: /lib64/libc.so.6(clone+0x6d)[0x7f1667c9288d] |
Jun 13 09:47:56 db-slave mysqld: Trying to get some variables. |
Jun 13 09:47:56 db-slave mysqld: Some pointers may be invalid and cause the dump to abort. |
Jun 13 09:47:56 db-slave mysqld: Query (0x7f04bdaf140b): UPDATE tableName SET ip = '1.1.1.1', updatedAt = '2020-06-13T09:47:36Z' WHERE id = 12345 |
Jun 13 09:47:56 db-slave mysqld: Connection ID (thread ID): 11 |
Jun 13 09:47:56 db-slave mysqld: Status: NOT_KILLED |
Jun 13 09:47:56 db-slave mysqld: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on |
Jun 13 09:47:56 db-slave mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains |
Jun 13 09:47:56 db-slave mysqld: information that should help you find out what is causing the crash. |
Jun 13 09:47:56 db-slave mysqld: Writing a core file... |
Jun 13 09:47:56 db-slave mysqld: Working directory at /var/lib/mysql |
Jun 13 09:47:56 db-slave mysqld: Resource Limits: |
Jun 13 09:47:56 db-slave mysqld: Limit Soft Limit Hard Limit Units |
Jun 13 09:47:56 db-slave mysqld: Max cpu time unlimited unlimited seconds |
Jun 13 09:47:56 db-slave mysqld: Max file size unlimited unlimited bytes |
Jun 13 09:47:56 db-slave mysqld: Max data size unlimited unlimited bytes |
Jun 13 09:47:56 db-slave mysqld: Max stack size 8388608 unlimited bytes |
Jun 13 09:47:56 db-slave mysqld: Max core file size 0 unlimited bytes |
Jun 13 09:47:56 db-slave mysqld: Max resident set unlimited unlimited bytes |
Jun 13 09:47:56 db-slave mysqld: Max processes 514547 514547 processes |
Jun 13 09:47:56 db-slave mysqld: Max open files 16364 16364 files |
Jun 13 09:47:56 db-slave mysqld: Max locked memory 65536 65536 bytes |
Jun 13 09:47:56 db-slave mysqld: Max address space unlimited unlimited bytes |
Jun 13 09:47:56 db-slave mysqld: Max file locks unlimited unlimited locks |
Jun 13 09:47:56 db-slave mysqld: Max pending signals 514547 514547 signals |
Jun 13 09:47:56 db-slave mysqld: Max msgqueue size 819200 819200 bytes |
Jun 13 09:47:56 db-slave mysqld: Max nice priority 0 0 |
Jun 13 09:47:56 db-slave mysqld: Max realtime priority 0 0 |
Jun 13 09:47:56 db-slave mysqld: Max realtime timeout unlimited unlimited us |
Jun 13 09:47:56 db-slave mysqld: Core pattern: co... |
|
I am convinced that the InnoDB change buffer can corrupt secondary indexes. We have recent reports of that from 10.4 and later versions, even after those errors related to MDEV-22373 that we were able to reproduce have been fixed. This is no a new problem; see MDEV-9663 and MDEV-24449.
MDEV-27734 will set innodb_change_buffering=none by default in MariaDB Server 10.5.15, 10.6.7, and later. I recommend everyone to set that. Note that even after the change buffer has been disabled, already buffered changes to secondary indexes will be merged. Also note that corrupted secondary indexes will not be automatically repaired. You should drop and create affected indexes.
Without a repeatable test case, it is hard or impossible to say what caused the corruption in the first place.
The most recent example of change buffer induced corruption is MDEV-30009.
The failing assertion was not replaced with error propagation to the caller in MDEV-13542. I think that we should do that.
I evaluated the impact of replacing the assertion failure with error propagation in MariaDB Server 10.4. It looks like the DB_CORRUPTION return value from row_ins_sec_index_entry_by_modify() would be propagated all way up to row_update_for_mysql(), and ha_innobase::update_row() or ha_innobase::delete_row() would return HA_ERR_CRASHED. In row_insert_for_mysql() we would end up outputting an error message in row_mysql_handle_errors() and returning HA_ERR_CRASHED from ha_innobase::update_row() or ha_innobase::write_row().
I did not check what would happen thereafter: would the transaction be rolled back or committed, and would the server crash on the rollback?
@Elena Stepanova, This table has no HASH indices, BTREE indices only