[MDEV-26291] ER_FILSORT_ABORT triggers - crash query when "for update" in a select statement Created: 2021-08-01  Updated: 2022-02-14  Resolved: 2022-01-31

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.4.19, 10.5.10
Fix Version/s: 10.6.1, 10.2.40, 10.3.31, 10.4.21, 10.5.11

Type: Bug Priority: Major
Reporter: Samuel Vicent Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 1
Labels: innodb, lock, update
Environment:

linux gentoo - Intel Xeon-E 2288G (https://www.ovhcloud.com/es-es/bare-metal/infra/infra-2/)

Attachments: PNG File Captura de pantalla 2021-08-01 a las 9.26.56.png    
Issue Links:
Duplicate
duplicates MDEV-25594 Crash in deadlock checker under high ... Closed
Relates
relates to MDEV-23338 server crash on select for update Open
relates to MDEV-23939 Crash with mariadb 10.4: storage/inno... Closed

 Description   

Hi,

MariaDb server crashes when a query like this is executed repeatedly:

SELECT m.* FROM messenger_messages_fr1 m WHERE (m.delivered_at is null OR m.delivered_at < '2021-07-30 1
1:35:00') AND (m.available_at <= '2021-07-30 12:35:00') AND (m.queue_name = 'mailer_async') ORDER BY available_at ASC LIMIT 1 FOR UPDATE

Logs show this:

0x7faff3f8f640 InnoDB: Assertion failure in file /var/tmp/portage/dev-db/mariadb-10.5.10-r1/work/mysql/storage/innobase/lock/lock0lock.cc line 6682
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

I am using the Messenger component from Symfony, which runs this query, I detected that when 2 servers are connected to the same database, and run the same symfony command for mananing queues, when both commands try to lock the same row repeatedly, this error happens.

This error is experienced both using a single database and multiple in a galera cluster setup.

 Comments   
Comment by Daniel Black [ 2021-08-02 ]

The "Sort Aborted" is a ER_FILSORT_ABORT error. This is caused by a disk write error during the file sort. Is there some OS cause here?

Either way, the server shouldn't abort based on this condition.

Thanks for the bug report.

Comment by Samuel Vicent [ 2021-08-02 ]

Hi,

Here you are more detailed info, (1) logs and (2) my.cnf conf:

1) LOGS:

2021-07-30 10:21:37 600928 [Warning] Sort aborted, host: localhost, user: tac_prod, thread: 600928, query: SELECT m.* FROM messenger_messages_fr1 m WHERE (m.delivered_at is null OR m.delivered_at < '2021-07-30 0
 
9:21:37') AND (m.available_at <= '2021-07-30 10:21:37') AND (m.queue_name = 'mailer_async') ORDER BY available_at ASC LIMIT 1 FOR UPDATE
 
2021-07-30 12:35:00 616101 [Warning] Sort aborted, host: localhost, user: tac_prod, thread: 616101, query: SELECT m.* FROM messenger_messages_fr1 m WHERE (m.delivered_at is null OR m.delivered_at < '2021-07-30 1
 
1:35:00') AND (m.available_at <= '2021-07-30 12:35:00') AND (m.queue_name = 'mailer_async') ORDER BY available_at ASC LIMIT 1 FOR UPDATE
 
2021-07-30 12:35:01 0x7faff3f8f640  InnoDB: Assertion failure in file /var/tmp/portage/dev-db/mariadb-10.5.10-r1/work/mysql/storage/innobase/lock/lock0lock.cc line 6682
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
 
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: https://mariadb.com/kb/en/library/innodb-recovery-modes/
 
InnoDB: about forcing recovery.
 
210730 12:35:01 [ERROR] mysqld got signal 6 ;
 
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.5.10-MariaDB-log
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=66
 
max_threads=153
 
thread_count=67
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467871 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7fafd0e9ae58
 
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 = 0x7faff3f8d458 thread_stack 0x49000
 
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55b6ad736e5e]
 
/usr/sbin/mysqld(handle_fatal_signal+0x485)[0x55b6ad240bb5]
 
/lib64/libpthread.so.0(+0x122e0)[0x7fb00d8fe2e0]
 
/lib64/libc.so.6(gsignal+0x141)[0x7fb00d43b701]
 
/lib64/libc.so.6(abort+0x112)[0x7fb00d425536]
 
/usr/sbin/mysqld(+0x63044a)[0x55b6acf2144a]
 
/usr/sbin/mysqld(+0x60916d)[0x55b6acefa16d]
 
/usr/sbin/mysqld(+0xc7523f)[0x55b6ad56623f]
 
/usr/sbin/mysqld(+0xc75d68)[0x55b6ad566d68]
 
/usr/sbin/mysqld(+0xce77a1)[0x55b6ad5d87a1]
 
/usr/sbin/mysqld(+0xce90c9)[0x55b6ad5da0c9]
 
/usr/sbin/mysqld(+0xc30822)[0x55b6ad521822]
 
/usr/sbin/mysqld(_ZN7handler17ha_index_read_mapEPhPKhm16ha_rkey_function+0x143)[0x55b6ad246133]
 
/usr/sbin/mysqld(_ZN7handler16read_range_firstEPK12st_key_rangeS2_bb+0x61)[0x55b6ad24b451]
 
/usr/sbin/mysqld(_ZN7handler21multi_range_read_nextEPPv+0xbe)[0x55b6ad17365e]
 
/usr/sbin/mysqld(_ZN23Mrr_simple_index_reader8get_nextEPPv+0x48)[0x55b6ad1736d8]
 
/usr/sbin/mysqld(_ZN10DsMrr_impl10dsmrr_nextEPPv+0x42)[0x55b6ad174a82]
 
/usr/sbin/mysqld(_ZN18QUICK_RANGE_SELECT8get_nextEv+0x27)[0x55b6ad36cb97]
 
/usr/sbin/mysqld(_Z8filesortP3THDP5TABLEP8FilesortP16Filesort_trackerP4JOINy+0xf3d)[0x55b6ad23ee2d]
 
/usr/sbin/mysqld(_Z17create_sort_indexP3THDP4JOINP13st_join_tableP8Filesort+0xd7)[0x55b6ad09b0f7]
 
/usr/sbin/mysqld(_ZN13st_join_table10sort_tableEv+0x7e)[0x55b6ad09b43e]
 
/usr/sbin/mysqld(_Z21join_init_read_recordP13st_join_table+0x3a)[0x55b6ad09b4ca]
 
/usr/sbin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x176)[0x55b6ad087266]
 
/usr/sbin/mysqld(_ZN4JOIN10exec_innerEv+0xe68)[0x55b6ad0b1d28]
 
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x34)[0x55b6ad0b2124]
 
/usr/sbin/mysqld(_Z12mysql_selectP3THDP10TABLE_LISTR4ListI4ItemEPS4_jP8st_orderS9_S7_S9_yP13select_resultP18st_select_lex_unitP13st_select_lex+0xf6)[0x55b6ad0aff86]
 
/usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x140)[0x55b6ad0b0a00]
 
/usr/sbin/mysqld(+0x750b6e)[0x55b6ad041b6e]
 
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x3f58)[0x55b6ad04e7e8]
 
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x210)[0x55b6ad04fb30]
 
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x13cd)[0x55b6ad051f5d]
 
/usr/sbin/mysqld(_Z10do_commandP3THD+0x11d)[0x55b6ad05384d]
 
/usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECTb+0x2c2)[0x55b6ad1446d2]
 
/usr/sbin/mysqld(handle_one_connection+0x5d)[0x55b6ad14494d]
 
/usr/sbin/mysqld(+0xb8af30)[0x55b6ad47bf30]
 
/lib64/libpthread.so.0(+0x7e3e)[0x7fb00d8f3e3e]
 
/lib64/libc.so.6(clone+0x3f)[0x7fb00d4fb2cf]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7fafd0eeaaf0): SELECT m.* FROM messenger_messages_fr1 m WHERE (m.delivered_at is null OR m.delivered_at < '2021-07-30 11:35:00') AND (m.available_at <= '2021-07-30 12:35:00') AND (m.queue_name = 'default_async') ORDER BY available_at ASC LIMIT 1 FOR UPDATE
 
 
 
Connection ID (thread ID): 616124
 
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,not_null_range_scan=off
 
 
 
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 /var/lib/mysql
 
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        0                    unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             128471               128471               processes 
Max open files            32768                32768                files     
Max locked memory         unlimited            unlimited            bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       128471               128471               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: |/lib/systemd/systemd-coredump %P %u %g %s %t %c %h

2) CONF:

[client]
 
socket                        = /var/run/mysqld/mysqld.sock
 
character-sets-dir                = /usr/share/mariadb/charsets
 
loose-default-character-set=utf8
 
 
 
[mysql]
 
# uncomment the next directive if you are not familiar with SQL
 
#safe-updates
 
 
 
[mysqldump]
 
quick
 
max_allowed_packet            = 16M
 
 
 
[myisamchk]
 
character-sets-dir=/usr/share/mariadb/charsets
 
 
 
[myisampack]
 
character-sets-dir=/usr/share/mariadb/charsets
 
# /etc/mysql/50-distro-server.cnf: The global mysql configuration file.
 
 
 
# add a section [mysqld-4.1] or [mysqld-5.0] for specific configurations
 
[mysqld]
 
character-set-server                = utf8
 
user                        = mysql
 
port                        = 3306
 
socket                        = /var/run/mysqld/mysqld.sock
 
pid-file                    = /var/run/mysqld/mariadb.pid
 
log-error                    = /var/log/mysql/mysqld.err
 
basedir                        = /usr
 
datadir                        = /var/lib/mysql
 
skip-external-locking
 
lc_messages_dir                    = /usr/share/mariadb
 
#Set this to your desired error message language
 
lc_messages                    = en_US
 
 
 
# security:
 
# using "localhost" in connects uses sockets by default
 
# skip-networking
 
bind-address                    = 127.0.0.1
 
 
 
log-bin
 
server-id                    = 1
 
 
 
# point the following paths to different dedicated disks
 
tmpdir                        = /tmp/
 
#log-update                    = /path-to-dedicated-directory/hostname
 
[mysqld]
 
#innodb_large_prefix = true
 
#innodb_file_format = barracuda
 
innodb_file_per_table = true
 
innodb_default_row_format=DYNAMIC
 
[mysqld]
 
query_cache_size=0
 
query_cache_type=0
 
query_cache_limit=2M
 
table_definition_cache=1M
 
 
 
innodb_buffer_pool_size=512M
 
#innodb_buffer_pool_instances=1
 
innodb_log_file_size=128M
 
 
 
join_buffer_size=128M
 
tmp_table_size=64M
 
max_heap_table_size=64M
 
binlog_cache_size=16M
 
 
 
skip-log-bin
 
 
 
feedback=on
 
performance_schema=on
 
[mysqld]                                                                                                                                                                                                           
 
 
log-bin
 
 
 
binlog_format   = mixed
 
#replicate-do-db = maildb
 
 
 
expire_logs_days = 2
 
 
 
bind-address    = 0.0.0.0
 
 
 
#skip-name-resolve
 
[mysqld]
 
 
 
sql_mode = "NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION"

Thank you very much indeed.

Comment by Samuel Vicent [ 2021-08-31 ]

Just for your info I there is a modification in the messenger table indexes, used by the Symfony messenger component. May have some relationship and could help you in some way:

https://github.com/symfony/symfony/blob/4.4/CHANGELOG-4.4.md

bug #42345 [Messenger] Remove indices in messenger table on MySQL to prevent deadlocks while removing messages when running multiple consumers (jeroennoten)

Thanks

Comment by Marko Mäkelä [ 2022-01-31 ]

The crash occurred in the expansion of the macro check_trx_state() in the function DeadlockChecker::check_and_resolve(). Thus, I think that this report duplicates MDEV-25594.

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