[MDEV-29302] Failing assertion: trx->lock.table_locks.empty() Created: 2022-08-15  Updated: 2023-05-02  Resolved: 2023-05-02

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6.5
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Patrik Vaclavek Assignee: Vladislav Lesin
Resolution: Incomplete Votes: 0
Labels: innodb
Environment:

production, docker, linux
25GB of memory free
CPU about 15%
About 260 databases on the server


 Description   

Few seconds after creating new database and during table migration into it, mariadb server failed with following error lines.

Our configuration:

[mysqld]
 
max_allowed_packet=64M
 
back_log=1000
 
log_warnings=3
 
max_connections=1512
 
max_connect_errors=4294967295
 
key_buffer_size=1G
 
tmp_table_size=512M
 
thread_cache_size=200
 
innodb_rollback_on_timeout=1
 
innodb_buffer_pool_size=8G
 
innodb_log_file_size=4G
 
innodb_flush_log_at_trx_commit=1
 
innodb_file_per_table=1

First occurrence log:

2022-08-15  7:30:26 273422829 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-15  7:30:26 273422829 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-15  7:30:26 273422829 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-15  7:30:27 273422829 [Note] InnoDB: Cannot close file ./db_195/user_sessions.ibd because of pending fsync
 
2022-08-15 07:30:27 0x7efcc0474700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.6.5/storage/innobase/trx/trx0trx.cc line 918
 
InnoDB: Failing assertion: trx->lock.table_locks.empty()
 
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 mariadbd 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.
 
220815  7:30:27 [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.6.5-MariaDB-1:10.6.5+maria~focal
 
key_buffer_size=1073741824
 
read_buffer_size=131072
 
max_used_connections=339
 
max_threads=1026
 
thread_count=200
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3307842 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7efa94000c58
 
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 = 0x7efcc0473d98 thread_stack 0x49000
 
mysqld(my_print_stacktrace+0x32)[0x5630e4505442]
 
Printing to addr2line failed
 
mysqld(handle_fatal_signal+0x485)[0x5630e3fb86a5]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x153c0)[0x7effa64163c0]

UPDATE 2022-08-24:
Today this error occurred again, under same conditions. We created new DB named "db_276" and started to migrate tables.

2022-08-24  7:07:27 16520720 [Note] InnoDB: Cannot close file ./db_103/events.ibd because of pending fsync
 
2022-08-24  7:07:27 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:27 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:27 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:27 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:27 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:27 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:27 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:27 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:28 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:28 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:28 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:28 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:28 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:28 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:28 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:28 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:29 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:29 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:30 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:31 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:32 16520720 [Note] InnoDB: Cannot close file ./db_103/events.ibd because of pending fsync
 
2022-08-24  7:07:32 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:32 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:32 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:32 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:32 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:32 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:32 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:33 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:33 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:33 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:33 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:33 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:33 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:33 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:33 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:34 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:35 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:35 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:35 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:35 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:36 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:36 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:36 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:36 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:37 16520720 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2022-08-24  7:07:37 16520720 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2022-08-24  7:07:37 16520720 [Note] InnoDB: Online DDL : Applying log to index
 
2022-08-24  7:07:37 16520720 [Note] InnoDB: Cannot close file ./db_103/events.ibd because of pending fsync
 
2022-08-24 07:07:37 0x7fb5dc3de700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.6.5/storage/innobase/trx/trx0trx.cc line 918
 
InnoDB: Failing assertion: trx->lock.table_locks.empty()
 
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 mariadbd 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.
 
220824  7:07:37 [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.6.5-MariaDB-1:10.6.5+maria~focal
 
key_buffer_size=1073741824
 
read_buffer_size=131072
 
max_used_connections=641
 
max_threads=1514
 
thread_count=201
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4382437 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7fb3ac000c58
 
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 = 0x7fb5dc3ddd98 thread_stack 0x49000
 
mysqld(my_print_stacktrace+0x32)[0x559b6f5e7442]
 
mysqld(handle_fatal_signal+0x485)[0x559b6f09a6a5]



 Comments   
Comment by Patrik Vaclavek [ 2022-08-24 ]

Today, mariadb server died again. I updated the issue and added full log since the time new db was created. Any suggestions how to solve this?
I also added our configuration. Is it possible it is related to innodb_flush_log_at_trx_commit?

Comment by Vladislav Lesin [ 2023-02-20 ]

We found similar issue during RQG testing. In RQG it's marked as TBR-1799 and can be easily reproduced.

When the table is renamed, table locks are set with the following code in ha_innobase::rename_table():

        if (error == DB_SUCCESS) {                                              
                error = lock_table_for_trx(dict_sys.sys_tables, trx, LOCK_X);   
                if (error == DB_SUCCESS) {                                      
                        error = lock_table_for_trx(dict_sys.sys_foreign, trx,   
                                                   LOCK_X);                     
                        if (error == DB_SUCCESS) {                              
                                error = lock_table_for_trx(                     
                                        dict_sys.sys_foreign_cols,              
                                        trx, LOCK_X);                           
                        }                                                       
                }                                                               
        }                                                                       
                                                                                
        row_mysql_lock_data_dictionary(trx);                                    
                                                                                
        if (error == DB_SUCCESS) {                                              
                error = innobase_rename_table(trx, from, to, true);             
        }                                                                       
                                                                                
        DEBUG_SYNC(thd, "after_innobase_rename_table");

After that row_rename_table_for_mysql() starts executing of internal query with the following stack:

#3  0x00005627f813c1ed in trx_start_low (trx=0x7f1863c0ab58, read_write=<optimized out>)
 
    at ./storage/innobase/trx/trx0trx.cc:921                                    
#4  0x00005627f87bc21e in que_thr_step (thr=0x7f186c0627f0) at ./storage/innobase/include/que0que.inl:37
 
#5  que_run_threads_low (thr=<optimized out>) at ./storage/innobase/que/que0que.cc:709
 
#6  que_run_threads (thr=0x7f186c0627f0) at ./storage/innobase/que/que0que.cc:729
 
#7  0x00005627f87bc4d0 in que_eval_sql (info=info@entry=0x7f186c0426f8,         
    sql=sql@entry=0x5627f8caa0d0 "PROCEDURE RENAME_TABLE () IS\nBEGIN\nUPDATE SYS_TABLES SET NAME = :new_table_name\n WHERE NAME = :old_table_name;\nEND;\n", trx=trx@entry=0x7f1863c0ab58) at ./storage/innobase/que/que0que.cc:768
 
#8  0x00005627f87e4bf5 in row_rename_table_for_mysql (old_name=old_name@entry=0x7f182701b7d0 "test/#sql-alter-3770c9-17", 
    new_name=new_name@entry=0x7f182701b5d0 "test/t9_p", trx=trx@entry=0x7f1863c0ab58, use_fk=use_fk@entry=true)
 
    at ./storage/innobase/row/row0mysql.cc:2729                                 
#9  0x00005627f872a3f6 in innobase_rename_table (trx=trx@entry=0x7f1863c0ab58,  
    from=from@entry=0x7f182701c2d0 "./test/#sql-alter-3770c9-17", to=to@entry=0x7f182701c4d0 "./test/t9_p", use_fk=use_fk@entry=true)
 
    at ./storage/innobase/handler/ha_innodb.cc:13757                            
#10 0x00005627f873939b in ha_innobase::rename_table (this=<optimized out>, from=0x7f182701c2d0 "./test/#sql-alter-3770c9-17", 
    to=0x7f182701c4d0 "./test/t9_p") at ./storage/innobase/handler/ha_innodb.cc:14158

And trx_start_low() is invoked for already started transaction, what causes the assertion failure above.

Comment by Vladislav Lesin [ 2023-02-20 ]

theese, could you please send full backtrace to be sure this is the same issue we caught during our testing.

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