[MDEV-24257] innodb_gis.rtree_purge failed in bb, crash after "delete from t" Created: 2020-11-20  Updated: 2023-04-28

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.2, 10.4
Fix Version/s: 10.4, 10.5

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Marko Mäkelä
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-14059 InnoDB assertion failure offset >= ((... Closed
relates to MDEV-15275 innodb_gis.rtree_purge failed in buil... Open
relates to MDEV-15284 innodb_gis.rtree_concurrent_srch fail... Confirmed
relates to MDEV-27422 Server crashes, heap-buffer-overflow,... Confirmed

 Description   

https://buildbot.askmonty.org/buildbot/builders/kvm-deb-bionic-amd64/builds/6306/steps/mtr/logs/stdio

innodb_gis.rtree_purge '8k,innodb'       w1 [ fail ]
 
        Test ended at 2020-11-19 07:17:59
 
 
 
CURRENT_TEST: innodb_gis.rtree_purge
 
mysqltest: At line 25: query 'delete from t' failed: 2013: Lost connection to MySQL server during query
 
 
 
The result from queries just before the failure was:
 
SET @saved_frequency = @@GLOBAL.innodb_purge_rseg_truncate_frequency;
 
SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
 
create table t (
 
b point not null,d point not null, spatial key (d),spatial key (b)
 
) engine=innodb;
 
 
 
 
 
Server [mysqld.1 - pid: 28434, winpid: 28434, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
2020-11-19  7:17:54 0 [Note] /usr/sbin/mysqld (mysqld 10.4.18-MariaDB-1:10.4.18+maria~bionic-log) starting as process 28435 ...
 
2020-11-19  7:17:54 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32186)
 
2020-11-19  7:17:54 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
 
2020-11-19  7:17:54 0 [Note] Plugin 'partition' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'SEQUENCE' is disabled.
 
2020-11-19  7:17:54 0 [Note] InnoDB: innodb_page_size=8192
 
2020-11-19  7:17:54 0 [Note] InnoDB: Using Linux native AIO
 
2020-11-19  7:17:54 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2020-11-19  7:17:54 0 [Note] InnoDB: Uses event mutexes
 
2020-11-19  7:17:54 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2020-11-19  7:17:54 0 [Note] InnoDB: Number of pools: 1
 
2020-11-19  7:17:54 0 [Note] InnoDB: Using generic crc32 instructions
 
2020-11-19  7:17:54 0 [Note] mysqld: O_TMPFILE is not supported on /dev/shm/var/tmp/1/mysqld.1 (disabling future attempts)
 
2020-11-19  7:17:54 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
 
2020-11-19  7:17:54 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-11-19  7:17:54 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-11-19  7:17:54 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2020-11-19  7:17:54 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2020-11-19  7:17:54 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2020-11-19  7:17:54 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2020-11-19  7:17:54 0 [Note] InnoDB: Waiting for purge to start
 
2020-11-19  7:17:54 0 [Note] InnoDB: 10.4.18 started; log sequence number 70507; transaction id 33
 
2020-11-19  7:17:54 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var/1/mysqld.1/data/ib_buffer_pool
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_CMP' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'user_variables' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
2020-11-19  7:17:54 0 [Note] Plugin 'unix_socket' is disabled.
 
2020-11-19  7:17:54 0 [Note] InnoDB: Buffer pool(s) load completed at 201119  7:17:54
 
2020-11-19  7:17:54 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
 
2020-11-19  7:17:54 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
 
2020-11-19  7:17:54 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
 
2020-11-19  7:17:54 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
 
2020-11-19  7:17:54 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-aria'
 
2020-11-19  7:17:54 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
 
2020-11-19  7:17:54 0 [Note] Server socket created on IP: '127.0.0.1'.
 
2020-11-19  7:17:54 0 [Note] Reading of all Master_info entries succeeded
 
2020-11-19  7:17:54 0 [Note] Added new Master_info '' to hash table
 
2020-11-19  7:17:54 0 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.4.18-MariaDB-1:10.4.18+maria~bionic-log'  socket: '/dev/shm/var/tmp/1/mysqld.1.sock'  port: 16000  mariadb.org binary distribution
 
201119  7:17:56 [ERROR] 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.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.4.18-MariaDB-1:10.4.18+maria~bionic-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=1
 
max_threads=153
 
thread_count=7
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63536 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7efec8000c08
 
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 = 0x7eff16d67da8 thread_stack 0x49000
 
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x5599973456fe]
 
/usr/sbin/mysqld(handle_fatal_signal+0x515)[0x559996dbbbc5]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12980)[0x7eff23c5e980]
 
/usr/sbin/mysqld(+0xc75a82)[0x5599971aea82]
 
/usr/sbin/mysqld(+0xb0f460)[0x559997048460]
 
/usr/sbin/mysqld(+0xb21cc1)[0x55999705acc1]
 
/usr/sbin/mysqld(+0xb22ba7)[0x55999705bba7]
 
/usr/sbin/mysqld(+0xaf92b4)[0x5599970322b4]
 
/usr/sbin/mysqld(+0xa2e51c)[0x559996f6751c]
 
/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x9f)[0x559996dc720f]
 
/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x12c6)[0x559996f001c6]
 
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1e4d)[0x559996ba88cd]
 
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x1ea)[0x559996baef8a]
 
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x13c5)[0x559996bb13b5]
 
/usr/sbin/mysqld(_Z10do_commandP3THD+0x104)[0x559996bb2b34]
 
/usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x25e)[0x559996c90a1e]
 
/usr/sbin/mysqld(handle_one_connection+0x3d)[0x559996c90add]
 
/usr/sbin/mysqld(+0xdb70aa)[0x5599972f00aa]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db)[0x7eff23c536db]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7eff2267571f]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7efec8010040): delete from t
 
 
 
Connection ID (thread ID): 9
 
Status: NOT_KILLED
 
 
 
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
 
 
 
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
 
information that should help you find out what is causing the crash.
 
Writing a core file...
 
Working directory at /dev/shm/var/1/mysqld.1/data
 
Resource Limits:
 
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            8388608              unlimited            bytes     
Max core file size        unlimited            unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             23610                23610                processes 
Max open files            1024                 1024                 files     
Max locked memory         16777216             16777216             bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       23610                23610                signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us        
Core pattern: |/usr/share/apport/apport %p %s %c %d %P
 
 
 
----------SERVER LOG END-------------
 
 
 
 
 
 - found 'core' (0/0)
 
 
 
Trying 'dbx' to get a backtrace
 
 
 
Trying 'gdb' to get a backtrace from coredump /dev/shm/var/1/log/innodb_gis.rtree_purge-8k,innodb/mysqld.1/data/core
 
 
 
Trying 'lldb' to get a backtrace from coredump /dev/shm/var/1/log/innodb_gis.rtree_purge-8k,innodb/mysqld.1/data/core
 
 - deleting it, already saved 0
 
 - saving '/dev/shm/var/1/log/innodb_gis.rtree_purge-8k,innodb/' to '/dev/shm/var/log/innodb_gis.rtree_purge-8k,innodb/'
 
 
 
Retrying test innodb_gis.rtree_purge, attempt(2/3)...
 
 
 
worker[1] > Restart  - not started
 
***Warnings generated in error logs during shutdown after running tests: innodb_gis.rtree_purge
 
 
 
201119  7:17:56 [ERROR] mysqld got signal 11 ;
 
Attempting backtrace. You can use the following information to find out



 Comments   
Comment by Marko Mäkelä [ 2020-11-20 ]

Can you please try to provide a resolved stack trace?
Something like this:

gdb /usr/sbin/mysqld
 
list *0x5599971aea82
 
list *0x559997048460
 
…
 
list *0x559996f6751c
 
list *0xc75a82
 
list *0xb0f460
 
…
 
list *0xa2e51c
 
quit

The long addresses could vary due to address space layout randomization (ASLR), but hopefully the short ones will be portable.

Comment by Alice Sherepa [ 2021-04-13 ]

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest/builds/29208/steps/mtr_ps/logs/stdio

innodb_gis.rtree_purge '8k,innodb'       w1 [ fail ]
 
        Test ended at 2021-04-13 05:05:01
 
 
 
CURRENT_TEST: innodb_gis.rtree_purge
 
mysqltest: At line 23: query 'delete from t' failed: 2013: Lost connection to MySQL server during query
 
 
 
The result from queries just before the failure was:
 
SET @saved_frequency = @@GLOBAL.innodb_purge_rseg_truncate_frequency;
 
SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
 
create table t (
 
b point not null,d point not null, spatial key (d),spatial key (b)
 
) engine=innodb;
 
 
 
 
 
Server [mysqld.1 - pid: 8010, winpid: 8010, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
210413  5:04:59 [ERROR] 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.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.2.38-MariaDB-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=1
 
max_threads=153
 
thread_count=6
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63019 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f8d980009a8
 
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 = 0x7f8de814ecc8 thread_stack 0x49000
 
mysys/stacktrace.c:173(my_print_stacktrace)[0x55c1476c5b0e]
 
sql/signal_handler.cc:221(handle_fatal_signal)[0x55c147176bd5]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f8def6a7390]
 
gis/gis0sea.cc:163(rtr_pcur_getnext_from_path(dtuple_t const*, page_cur_mode_t, btr_cur_t*, unsigned long, unsigned long, bool, mtr_t*))[0x55c14761257d]
 
row/row0row.cc:1066(row_search_index_entry(dict_index_t*, dtuple_t const*, unsigned long, btr_pcur_t*, mtr_t*))[0x55c147491b85]
 
row/row0upd.cc:2393(row_upd_sec_index_entry(upd_node_t*, que_thr_t*))[0x55c1474b0073]
 
row/row0upd.cc:3312(row_upd)[0x55c1474b12bb]
 
row/row0mysql.cc:1824(row_update_for_mysql(row_prebuilt_t*))[0x55c14747d67c]
 
handler/ha_innodb.cc:9122(ha_innobase::delete_row(unsigned char const*))[0x55c1473bcce4]
 
sql/handler.cc:6178(handler::ha_delete_row(unsigned char const*))[0x55c1471811af]
 
sql/sql_delete.cc:583(mysql_delete(THD*, TABLE_LIST*, Item*, SQL_I_List<st_order>*, unsigned long long, unsigned long long, select_result*))[0x55c14729c910]
 
sql/sql_parse.cc:4426(mysql_execute_command(THD*))[0x55c146fd6962]
 
sql/sql_prepare.cc:5053(Prepared_statement::execute(String*, bool))[0x55c146ff00bd]
 
sql/sql_prepare.cc:4482(Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*))[0x55c146ff07c0]
 
sql/sql_prepare.cc:3468(mysql_stmt_execute_common(THD*, unsigned long, unsigned char*, unsigned char*, unsigned long, bool, bool) [clone .constprop.170])[0x55c146ff137f]
 
sql/sql_prepare.cc:3260(mysqld_stmt_execute(THD*, char*, unsigned int))[0x55c146ff14ea]
 
sql/sql_parse.cc:1770(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x55c146fdce88]
 
sql/sql_parse.cc:1384(do_command(THD*))[0x55c146fdedac]
 
sql/sql_connect.cc:1336(do_handle_one_connection(CONNECT*))[0x55c1470ad872]
 
sql/sql_connect.cc:1243(handle_one_connection)[0x55c1470ad9cd]
 
perfschema/pfs.cc:1872(pfs_spawn_thread)[0x55c1473069b1]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f8def69d6ba]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f8deed4882d]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f8d980525d8): delete from t
 
 
 
Connection ID (thread ID): 13
 
Status: NOT_KILLED

Comment by Marko Mäkelä [ 2021-04-13 ]

This looks like a fundamental design problem with the MySQL 5.7 SPATIAL INDEX implementation that had been imported to MariaDB 10.2.2.

MDEV-15284 shows a race condition between ROLLBACK and concurrent reads.

The locking and latching rules for R-trees are completely unclear to me. While I worked on MDEV-20612, I noticed some inconsistency in the locking.

The comments in MDEV-14059 highlight a questionable hack around buffer pool block descriptors, which may be directly related to this failure.

Generated at Thu Feb 08 09:28:36 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.