Details
-
Bug
-
Status: Closed (View Workflow)
-
Blocker
-
Resolution: Fixed
-
N/A
Description
The test case appears to be deterministic, the concurrency here is on the transaction level. I suppose it can be further simplified, but it's not easy to guess blindly what can be replaced with what, so I'll leave it as it is for now, hopefully it will be clearer after the analysis.
--source include/have_innodb.inc
|
|
|
CREATE TABLE t1 (id INT PRIMARY KEY, col_varchar VARCHAR(8)) ENGINE=InnoDB; |
INSERT INTO t1 (id) VALUES (1),(2); |
CREATE TABLE t2 (id INT, f INT, s DATE, e DATE, PERIOD FOR p(s,e), PRIMARY KEY(id, p WITHOUT OVERLAPS)) ENGINE=InnoDB; |
INSERT INTO t2 VALUES (1,0,'2000-01-01','2000-01-02'); |
CREATE TABLE t3 (id INT, f BLOB, UNIQUE(f)) ENGINE=InnoDB; |
|
|
--connection default
|
SET innodb_lock_wait_timeout=1; |
START TRANSACTION; |
DELETE FROM t1; |
|
|
--connect (con1,localhost,root,,)
|
START TRANSACTION; |
UPDATE t2 SET f = 20; |
|
|
--connection default
|
--send
|
DELETE FROM t2 FOR PORTION OF p FROM '2000-01-01' TO '2000-01-02'; |
|
|
--connection con1
|
INSERT INTO t3 (id) VALUES (1), (2); |
UPDATE t1 SET col_varchar = 'bar'; |
COMMIT; |
|
|
--connection default
|
--error ER_LOCK_DEADLOCK
|
--reap
|
COMMIT; |
UPDATE t3 SET f = 'foo' ORDER BY f LIMIT 1; |
|
|
# Cleanup
|
DROP TABLE t1, t2, t3; |
|
10.6 d77b9a4925c971364707d435028add41e8015173 |
mariadbd: /data/bld/10.6-asan/storage/innobase/handler/ha_innodb.cc:16341: virtual int ha_innobase::external_lock(THD*, int): Assertion `not_autocommit || trx->n_mysql_tables_in_use || (trx->lock.trx_locks).count == 0' failed.
|
250126 21:12:56 [ERROR] /share8t/bld/10.6-asan/sql/mariadbd got signal 6 ;
|
|
|
#9 0x00007fee4cc53eb2 in __GI___assert_fail (assertion=0x55ae9e0c92a0 "not_autocommit || trx->n_mysql_tables_in_use || (trx->lock.trx_locks).count == 0", file=0x55ae9e0b2be0 "/data/bld/10.6-asan/storage/innobase/handler/ha_innodb.cc", line=16341, function=0x55ae9e0c90e0 "virtual int ha_innobase::external_lock(THD*, int)") at ./assert/assert.c:101
|
#10 0x000055ae9c78fe97 in ha_innobase::external_lock (this=0x62d0000a1760, thd=0x62b0000bd218, lock_type=0) at /data/bld/10.6-asan/storage/innobase/handler/ha_innodb.cc:16341
|
#11 0x000055ae9bd01e12 in handler::ha_external_lock (this=0x62d0000a1760, thd=0x62b0000bd218, lock_type=0) at /data/bld/10.6-asan/sql/handler.cc:7226
|
#12 0x000055ae9bcddd10 in handler::create_lookup_handler (this=0x6250002a3148) at /data/bld/10.6-asan/sql/handler.cc:3326
|
#13 0x000055ae9bd06fb4 in handler::prepare_for_insert (this=0x6250002a3148, do_create=true) at /data/bld/10.6-asan/sql/handler.cc:7689
|
#14 0x000055ae9b77872a in mysql_update (thd=0x62b0000bd218, table_list=0x62d0000a0578, fields=..., values=..., conds=0x0, order_num=1, order=0x62d0000a0ff0, limit=1, ignore=false, found_return=0x7fee3e0e3f00, updated_return=0x7fee3e0e3f20) at /data/bld/10.6-asan/sql/sql_update.cc:1024
|
#15 0x000055ae9b43df7d in mysql_execute_command (thd=0x62b0000bd218, is_called_from_prepared_stmt=false) at /data/bld/10.6-asan/sql/sql_parse.cc:4477
|
#16 0x000055ae9b457d60 in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62d0000a0438 "UPDATE t3 SET f = 'foo' ORDER BY f LIMIT 1", length=42, parser_state=0x7fee3e0e4a90) at /data/bld/10.6-asan/sql/sql_parse.cc:8208
|
#17 0x000055ae9b42d123 in dispatch_command (command=COM_QUERY, thd=0x62b0000bd218, packet=0x629000276219 "UPDATE t3 SET f = 'foo' ORDER BY f LIMIT 1", packet_length=42, blocking=true) at /data/bld/10.6-asan/sql/sql_parse.cc:1908
|
#18 0x000055ae9b429e57 in do_command (thd=0x62b0000bd218, blocking=true) at /data/bld/10.6-asan/sql/sql_parse.cc:1421
|
#19 0x000055ae9b8ac8c1 in do_handle_one_connection (connect=0x608000018ab8, put_in_cache=true) at /data/bld/10.6-asan/sql/sql_connect.cc:1386
|
#20 0x000055ae9b8ac420 in handle_one_connection (arg=0x608000018a38) at /data/bld/10.6-asan/sql/sql_connect.cc:1298
|
#21 0x000055ae9c525966 in pfs_spawn_thread (arg=0x617000007e98) at /data/bld/10.6-asan/storage/perfschema/pfs.cc:2201
|
#22 0x00007fee4cca81c4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
|
#23 0x00007fee4cd2885c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
|
|
10.11 3a6af458e6149657c1e135af821a23a7c15c68f1 |
mariadbd: /data/bld/11.4-asan/storage/innobase/trx/trx0trx.cc:376: void trx_t::free(): Assertion `!n_mysql_tables_in_use' failed.
|
250126 21:13:52 [ERROR] /share8t/bld/11.4-asan/sql/mariadbd got signal 6 ;
|
|
|
#9 0x00007f30dca53eb2 in __GI___assert_fail (assertion=0x55b9748a8880 "!n_mysql_tables_in_use", file=0x55b9748a8120 "/data/bld/11.4-asan/storage/innobase/trx/trx0trx.cc", line=376, function=0x55b9748a88c0 "void trx_t::free()") at ./assert/assert.c:101
|
#10 0x000055b97318bc48 in trx_t::free (this=0x7f30cf970380) at /data/bld/11.4-asan/storage/innobase/trx/trx0trx.cc:376
|
#11 0x000055b972b71000 in innobase_close_connection (thd=0x62c0001e0218) at /data/bld/11.4-asan/storage/innobase/handler/ha_innodb.cc:2954
|
#12 0x000055b972177423 in ha_close_connection (thd=0x62c0001e0218) at /data/bld/11.4-asan/sql/handler.cc:955
|
#13 0x000055b9716b7bef in THD::free_connection (this=0x62c0001e0218) at /data/bld/11.4-asan/sql/sql_class.cc:1737
|
#14 0x000055b971432021 in unlink_thd (thd=0x62c0001e0218) at /data/bld/11.4-asan/sql/mysqld.cc:2871
|
#15 0x000055b971cd9686 in do_handle_one_connection (connect=0x608000005138, put_in_cache=true) at /data/bld/11.4-asan/sql/sql_connect.cc:1419
|
#16 0x000055b971cd9138 in handle_one_connection (arg=0x6080000050b8) at /data/bld/11.4-asan/sql/sql_connect.cc:1320
|
#17 0x000055b9729557a8 in pfs_spawn_thread (arg=0x617000007e98) at /data/bld/11.4-asan/storage/perfschema/pfs.cc:2201
|
#18 0x00007f30dcaa81c4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
|
#19 0x00007f30dcb2885c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
|
The failure started happening after this commit in 10.6:
commit ddd7d5d8e34c3edd7ebf4790eec2c4e4d9141e94
|
Commit: Marko Mäkelä
|
CommitDate: Thu Dec 12 18:02:00 2024 +0200
|
|
|
MDEV-24035 Failing assertion: UT_LIST_GET_LEN(lock.trx_locks) == 0 causing disruption and replication failure
|
No obvious immediate problem on a non-debug build.
Attachments
Issue Links
- is caused by
-
-
- Closed
-
- relates to
-
-
- Needs Feedback
-
Activity
It turns out that there are two bugs in mysql_delete(), which is handling DELETE statements. The transaction had been aborted here:
|
10.6 d77b9a4925c971364707d435028add41e8015173 |
#0 innodb_transaction_abort (thd=0x7ef9ec0011d8, all=0x1, err=DB_DEADLOCK) at /home/marko/10.6/storage/innobase/handler/ha_innodb.cc:2155
|
#1 0x00006012ca52514e in convert_error_code_to_mysql (error=DB_DEADLOCK, flags=<optimized out>, thd=0x7ef9ec0011d8) at /home/marko/10.6/storage/innobase/handler/ha_innodb.cc:2227
|
#2 0x00006012ca52893a in ha_innobase::index_read (this=0x7ef9ec1c2ca8, buf=0x7ef9ec1c34a8 "\377", key_ptr=key_ptr@entry=0x0, key_len=key_len@entry=0x0, find_flag=find_flag@entry=HA_READ_AFTER_KEY)
|
at /home/marko/10.6/storage/innobase/handler/ha_innodb.cc:9145
|
#3 0x00006012ca528fdc in ha_innobase::index_first (this=0x7ef9ec0011d8, buf=0x6012cd43f078 "\f") at /home/marko/10.6/storage/innobase/handler/ha_innodb.cc:9471
|
#4 ha_innobase::rnd_next (this=0x7ef9ec0011d8, buf=0x6012cd43f078 "\f") at /home/marko/10.6/storage/innobase/handler/ha_innodb.cc:9563
|
#5 0x00006012ca26886b in handler::ha_rnd_next (this=0x7ef9ec1c2ca8, buf=0x7ef9ec1c34a8 "\377") at /home/marko/10.6/sql/handler.cc:3533
|
#6 0x00006012ca3d8694 in rr_sequential (info=0x7efa1ee7c768) at /home/marko/10.6/sql/records.cc:519
|
#7 0x00006012ca3f2993 in READ_RECORD::read_record (this=0x7efa1ee7c768) at /home/marko/10.6/sql/records.h:81
|
#8 mysql_delete (thd=thd@entry=0x7ef9ec0011d8, table_list=0x7ef9ec0166c0, conds=0x7ef9ec017a90, order_list=order_list@entry=0x7ef9ec005ee0, limit=0xffffffffffffffff, options=0x0, result=<optimized out>)
|
at /home/marko/10.6/sql/sql_delete.cc:776
|
#9 0x00006012c9ff9f5a in mysql_execute_command (thd=thd@entry=0x7ef9ec0011d8, is_called_from_prepared_stmt=<optimized out>) at /home/marko/10.6/sql/sql_parse.cc:4924
|
#10 0x00006012c9ff1220 in mysql_parse (thd=thd@entry=0x7ef9ec0011d8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7efa1ee7d510) at /home/marko/10.6/sql/sql_parse.cc:8208
|
#11 0x00006012c9fef8b0 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7ef9ec0011d8,
|
packet=packet@entry=0x7ef9ec00c529 "DELETE FROM t2 FOR PORTION OF p FROM '2000-01-01' TO '2000-01-02'", packet_length=packet_length@entry=0x41, blocking=0x1) at /home/marko/10.6/sql/sql_parse.cc:1908
|
Because of this, the call to ha_innobase::external_lock(F_RDLCK) will return an error, which the caller is ignoring (again):
|
10.6 d77b9a4925c971364707d435028add41e8015173 |
#0 ha_innobase::external_lock (this=0x7ef9ec0187e8, thd=0x7ef9ec0011d8, lock_type=0x0) at /home/marko/10.6/storage/innobase/handler/ha_innodb.cc:16165
|
#1 0x00006012ca268131 in handler::ha_external_lock (this=0x7ef9ec0187e8, thd=0x7ef9ec0011d8, lock_type=lock_type@entry=0x0) at /home/marko/10.6/sql/handler.cc:7226
|
#2 0x00006012ca272238 in handler::create_lookup_handler (this=0x7ef9ec1c2ca8) at /home/marko/10.6/sql/handler.cc:3326
|
#3 handler::prepare_for_insert (this=0x7ef9ec1c2ca8, do_create=<optimized out>) at /home/marko/10.6/sql/handler.cc:7689
|
#4 0x00006012ca3f2b1e in mysql_delete (thd=thd@entry=0x7ef9ec0011d8, table_list=0x7ef9ec0166c0, conds=0x7ef9ec017a90, order_list=order_list@entry=0x7ef9ec005ee0, limit=0xffffffffffffffff, options=0x0,
|
result=<optimized out>) at /home/marko/10.6/sql/sql_delete.cc:823
|
#5 0x00006012c9ff9f5a in mysql_execute_command (thd=thd@entry=0x7ef9ec0011d8, is_called_from_prepared_stmt=<optimized out>) at /home/marko/10.6/sql/sql_parse.cc:4924
|
#6 0x00006012c9ff1220 in mysql_parse (thd=thd@entry=0x7ef9ec0011d8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7efa1ee7d510) at /home/marko/10.6/sql/sql_parse.cc:8208
|
#7 0x00006012c9fef8b0 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7ef9ec0011d8,
|
packet=packet@entry=0x7ef9ec00c529 "DELETE FROM t2 FOR PORTION OF p FROM '2000-01-01' TO '2000-01-02'", packet_length=packet_length@entry=0x41, blocking=0x1) at /home/marko/10.6/sql/sql_parse.cc:1908
|
This error is being ignored here:
|
mysql_delete() |
|
822
|
if (table->versioned(VERS_TIMESTAMP) || (table_list->has_period())) |
823
|
table->file->prepare_for_insert(1);
|
Like I have pointed out in MDEV-24812 two years ago, it would be helpful to declare this kind of functions with the attribute warn_unused_result, so that errors cannot be ignored. In any case, already the first error was being ignored in the same function. The following patch would fix that:
diff --git a/sql/sql_delete.cc b/sql/sql_delete.cc
|
index 2e77e32aed9..702f9d2d1ac 100644
|
--- a/sql/sql_delete.cc
|
+++ b/sql/sql_delete.cc
|
@@ -790,6 +790,8 @@ bool mysql_delete(THD *thd, TABLE_LIST *table_list, COND *conds,
|
}
|
}
|
end_read_record(&info);
|
+ if (error)
|
+ goto terminate_delete;
|
if (unlikely(deltempfile->get(table)) ||
|
unlikely(table->file->ha_index_or_rnd_end()) ||
|
unlikely(init_read_record(&info, thd, table, 0, &deltempfile->sort, 0, |
In addition to this, I would propose adding a non-debug assertion in order to prevent serious corruption:
diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc
|
index 4dd7a9405dd..8dafc0e606e 100644
|
--- a/storage/innobase/handler/ha_innodb.cc
|
+++ b/storage/innobase/handler/ha_innodb.cc
|
@@ -16311,6 +16311,7 @@ ha_innobase::external_lock(
|
case F_UNLCK:
|
DEBUG_SYNC_C("ha_innobase_end_statement");
|
m_mysql_has_locked = false;
|
+ ut_a(trx->n_mysql_tables_in_use);
|
|
if (--trx->n_mysql_tables_in_use) {
|
break; |
Also the return value of table->file->prepare_for_insert() must be checked in mysql_delete(), possibly with something like the following:
@@ -820,7 +822,11 @@ bool mysql_delete(THD *thd, TABLE_LIST *table_list, COND *conds,
|
&& table->file->has_transactions();
|
|
if (table->versioned(VERS_TIMESTAMP) || (table_list->has_period()))
|
- table->file->prepare_for_insert(1);
|
+ {
|
+ error= table->file->prepare_for_insert(1);
|
+ if (error)
|
+ terminate_delete;
|
+ }
|
DBUG_ASSERT(table->file->inited != handler::NONE);
|
|
THD_STAGE_INFO(thd, stage_updating); |
Interesting 2 things:
1) we never check result of handler::prepare_for_insert() (not in even one case)
2) failure of handler::prepare_for_insert() do not set an error (if add process of this error a lot of tests fails (mostly innodb & replication)
So above is not just question of reaction on error result in one chosen place.
following sequence(s) of tests:
|
binlog_encryption.rpl_init_slave_errors binlog_encryption.rpl_switch_stm_row_mixed binlog_encryption.rpl_loadfile
|
binlog_encryption.rpl_switch_stm_row_mixed
|
federated.federatedx federated.assisted_discovery
|
rpl.rpl_timezone
|
rpl.rpl_timezone
|
rpl.rpl_row_annotate_do
|
rpl.rpl_row_annotate_dont
|
rpl.rpl_gtid_errorlog rpl.rpl_binlog_compress rpl.rpl_change_master_find_log_pos_err rpl.rpl_LD_INFILE rpl.rpl_bug33931 rpl.rpl_create_drop_udf rpl.rpl_drop rpl.rpl_create_drop_view rpl.rpl_auto_increment_11932 rpl.rpl_15867 rpl.rpl_events rpl.rpl_create_drop_index rpl.rpl_000017 rpl.rpl_gis_user_var rpl.rpl_bit_npk rpl.rpl_binlog_corruption rpl.rpl_gtid_misc rpl.rpl_create_if_not_exists rpl.rpl_EE_err rpl.rpl_insert rpl.rpl_multi_update2 rpl.rpl_create_drop_trigger rpl.rpl_domain_id_filter_restart rpl.rpl_function_defaults rpl.rpl_auto_increment_bug33029 rpl.rpl_colSize rpl.rpl_drop_db rpl.rpl_charset_sjis rpl.rpl_create_drop_event rpl.rpl_get_lock rpl.rpl_incident rpl.rpl_autogen_query_multi_byte_char rpl.rpl_gtid_delete_domain rpl.failed_create_view-6409 rpl.rpl_do_grant rpl.rpl_drop_view rpl.rpl_critical_errors rpl.rpl_charset rpl.rpl_alter rpl.rpl_create_drop_user rpl.rpl_bug41902 rpl.rpl_delete_no_where rpl.rpl_create_drop_function rpl.rpl_heartbeat_debug rpl.grant_replication_slave rpl.rpl_create_drop_db rpl.rpl_idempotency rpl.rpl_relayspace rpl.rpl_heartbeat_ssl rpl.ignore_table_autoinc-9737 rpl.rpl_ctype_latin1 rpl.rpl_alter_db rpl.rpl_change_master rpl.replace rpl.rpl_create_drop_role rpl.rpl_dump_request_retry_warning rpl.rpl_auditing rpl.rpl_grant rpl.rpl_create_drop_procedure rpl.rpl_bit rpl.rpl_gtid_mdev4820
|
rpl.rpl_insert_delayed
|
rpl.rpl_15867 rpl.rpl_auto_increment_11932 rpl.rpl_create_drop_view rpl.rpl_drop rpl.rpl_create_drop_udf rpl.rpl_bug33931 rpl.rpl_LD_INFILE rpl.rpl_binlog_compress rpl.rpl_gtid_errorlog rpl.rpl_change_master_find_log_pos_err rpl.rpl_create_if_not_exists rpl.rpl_gtid_misc rpl.rpl_binlog_corruption rpl.rpl_bit_npk rpl.rpl_gis_user_var rpl.rpl_000017 rpl.rpl_events rpl.rpl_create_drop_index rpl.rpl_create_drop_user rpl.rpl_charset rpl.rpl_alter rpl.rpl_bug41902 rpl.rpl_critical_errors rpl.failed_create_view-6409 rpl.rpl_drop_view rpl.rpl_do_grant rpl.rpl_gtid_delete_domain rpl.rpl_get_lock rpl.rpl_incident rpl.rpl_autogen_query_multi_byte_char rpl.rpl_create_drop_event rpl.rpl_drop_db rpl.rpl_charset_sjis rpl.rpl_colSize rpl.rpl_function_defaults rpl.rpl_domain_id_filter_restart rpl.rpl_auto_increment_bug33029 rpl.rpl_insert rpl.rpl_ignore_table rpl.rpl_EE_err rpl.rpl_create_drop_trigger rpl.rpl_bit rpl.rpl_create_drop_procedure rpl.rpl_gtid_mdev4820 rpl.rpl_grant rpl.rpl_dump_request_retry_warning rpl.rpl_auditing rpl.rpl_change_master rpl.rpl_alter_db rpl.replace rpl.rpl_create_drop_role rpl.rpl_ctype_latin1 rpl.ignore_table_autoinc-9737 rpl.rpl_heartbeat_ssl rpl.rpl_create_drop_db rpl.rpl_idempotency rpl.rpl_heartbeat_debug rpl.grant_replication_slave rpl.rpl_delete_no_where rpl.rpl_create_drop_function
|
rpl.rpl_row_conflicts rpl.rpl_row_delayed_ins rpl.rpl_row_blob_myisam rpl.rpl_row_USER rpl.rpl_row_UUID rpl.rpl_row_create_select rpl.rpl_row_001 rpl.rpl_row_NOW rpl.rpl_row_colSize rpl.rpl_row_basic_2myisam
|
rpl.rpl_insert_delayed
|
rpl.rpl_stm_multi_query rpl.rpl_stm_max_relay_size rpl.rpl_stm_no_op rpl.rpl_stm_reset_slave rpl.rpl_stm_EE_err2 rpl.rpl_stm_conflicts rpl.rpl_switch_stm_row_mixed rpl.rpl_stm_mix_show_relaylog_events rpl.rpl_stm_until rpl.rpl_stm_maria rpl.rpl_stm_flsh_tbls
|
innodb.innodb
|
binlog.binlog_stm_binlog
|
rpl.rpl_stm_maria rpl.rpl_stm_flsh_tbls rpl.rpl_set_null_myisam rpl.rpl_stm_until rpl.rpl_stm_mix_show_relaylog_events rpl.rpl_switch_stm_row_mixed rpl.rpl_stm_conflicts rpl.rpl_stm_EE_err2 rpl.rpl_stm_reset_slave rpl.rpl_stm_max_relay_size rpl.rpl_stm_no_op rpl.rpl_stm_multi_query
|
binlog.binlog_innodb_row binlog.binlog_bug23533
|
binlog.binlog_unsafe
|
versioning.replace
|
period.update
|
versioning.replace
|
binlog.binlog_row_binlog
|
versioning.replace
|
versioning.replace
|
period.update
|
versioning.replace
|
versioning.replace
|
versioning.replace
|
versioning.replace
|
versioning.replace
|
versioning.select versioning.update versioning.select2
|
versioning.update versioning.select2 versioning.select
|
versioning.replace
|
versioning.select versioning.update versioning.select2
|
versioning.select versioning.select2 versioning.update
|
versioning.update
|
innodb.instant_alter_bugs
|
innodb.temp_table_savepoint innodb.instant_alter_rollback innodb.instant_alter_upgrade
|
type_inet.binlog_table_map_optional_metadata_type_inet6 binlog.show_concurrent_rotate vcol.update_binlog compat/oracle.sequence
|
innodb.instant_alter_upgrade innodb.temp_table_savepoint innodb.instant_alter_rollback
|
innodb.instant_alter_upgrade innodb.temp_table_savepoint innodb.instant_alter_rollback
|
main.commit_1innodb main.bug39022
|
main.concurrent_innodb_unsafelog main.column_compression main.concurrent_innodb_safelog main.ctype_upgrade main.explain_json_innodb main.innodb_group main.deadlock_innodb main.cache_innodb main.insert_innodb main.flush_read_lock main.check_constraint_innodb main.group_min_max_innodb main.information_schema_inno main.default_innodb main.func_group_innodb main.innodb_icp_debug main.func_rollback main.flush_block_commit main.func_analyse main.function_defaults_innodb main.bootstrap_innodb main.fast_prefix_index_fetch_innodb main.flush-innodb main.flush-innodb-notembedded main.endspace main.ctype_uca_innodb main.gis-alter_table_online main.group_by_innodb main.derived_cond_pushdown_innodb main.explain_innodb main.flush_read_lock_kill main.ctype_filename_innodb main.foreign_key main.drop main.index_intersect_innodb main.events_trans_notembedded main.innodb_utf8 main.default main.commit main.ctype_utf32_innodb main.innodb_mrr_cpk main.innodb_bug878769 main.events_trans main.consistent_snapshot main.ignored_index_innodb main.ext_key_noPK_6794 main.information_schema_db
|
main.partition
|
main.log_tables_debug main.long_unique_delayed main.long_unique_update main.long_unique_debug main.log_slow main.long_host main.long_unique_bugs_no_sp_protocol
|
main.memory_used main.merge main.merge_debug main.mix2_myisam main.metadata main.mdev_22370
|
main.mysqldump-system main.ps_innodb main.ps_missed_cmds_not_embedded main.reopen_temp_table main.ps_qc_innodb main.query_cache_innodb main.parser_bug21114_innodb main.ssl_and_innodb main.mysql_upgrade_ssl main.locking_clause main.subselect-crash_15755 main.system_mysql_db_fix50117 main.system_mysql_db_fix50030 main.lock_kill main.leaks main.stat_tables_disabled main.ps_missed_cmds_bin_prot_not_embedded main.join_outer_innodb main.system_mysql_db_fix50568 main.locked_temporary-5955 main.subselect2 main.range_mrr_icp main.keyread main.read_only_innodb main.single_delete_update_innodb main.merge_innodb main.simultaneous_assignment main.log_tables_upgrade main.opt_trace_index_merge_innodb main.rowid_order_innodb main.mrr_derived_crash_4610 main.loaddata_autocom_innodb main.servers main.kill_debug main.test main.join_cache_notasan main.percona_nonflushing_analyze_debug main.strict_autoinc_2innodb main.system_mysql_db_fix40123 main.progress_976225 main.range main.ps_missed_cmds_bin_prot main.mysql_upgrade_noengine main.sp-innodb main.mysql_tzinfo_to_sql_symlink main.ps_missed_cmds main.show_explain_non_select main.multi_update_innodb main.sp-group main.mdev13607
|
It look like it fails inside that handler::prepare_for_insert() call
#4 0x00007ffff7816177 in __assert_fail () from /usr/lib/libc.so.6
|
#5 0x000055555683c135 in ha_innobase::external_lock (this=0x7fffc40168f0, thd=0x7fffc4000dc8, lock_type=0) at /home/sanja/maria/git/10.6/storage/innobase/handler/ha_innodb.cc:16341
|
#6 0x0000555556388b8a in handler::ha_external_lock (this=0x7fffc40168f0, thd=0x7fffc4000dc8, lock_type=0) at /home/sanja/maria/git/10.6/sql/handler.cc:7226
|
#7 0x000055555637af38 in handler::create_lookup_handler (this=0x7fffb8023d48) at /home/sanja/maria/git/10.6/sql/handler.cc:3326
|
#8 0x000055555638a9e2 in handler::prepare_for_insert (this=0x7fffb8023d48, do_create=true) at /home/sanja/maria/git/10.6/sql/handler.cc:7689
|
#9 0x00005555560fa404 in mysql_update (thd=0x7fffc4000dc8, table_list=0x7fffc40157e8, fields=..., values=..., conds=0x0, order_num=1, order=0x7fffc4016200, limit=1, ignore=false, found_return=0x7ffff00adc70, updated_return=0x7ffff00adde0) at /home/sanja/maria/git/10.6/sql/sql_update.cc:1024
|
#10 0x0000555555faa314 in mysql_execute_command (thd=0x7fffc4000dc8, is_called_from_prepared_stmt=false) at /home/sanja/maria/git/10.6/sql/sql_parse.cc:4477
|
#11 0x0000555555fb6f49 in mysql_parse (thd=0x7fffc4000dc8, rawbuf=0x7fffc40156e0 "UPDATE t3 SET f = 'foo' ORDER BY f LIMIT 1", length=42, parser_state=0x7ffff00ae270) at /home/sanja/maria/git/10.6/sql/sql_parse.cc:8208
|
#12 0x0000555555fa2100 in dispatch_command (command=COM_QUERY, thd=0x7fffc4000dc8, packet=0x7fffc400baf9 "UPDATE t3 SET f = 'foo' ORDER BY f LIMIT 1", packet_length=42, blocking=true) at /home/sanja/maria/git/10.6/sql/sql_parse.cc:1908
|
#13 0x0000555555fa09d5 in do_command (thd=0x7fffc4000dc8, blocking=true) at /home/sanja/maria/git/10.6/sql/sql_parse.cc:1421
|
#14 0x000055555617c6f9 in do_handle_one_connection (connect=0x555558d3fd58, put_in_cache=true) at /home/sanja/maria/git/10.6/sql/sql_connect.cc:1386
|
#15 0x000055555617c47f in handle_one_connection (arg=0x555558d012e8) at /home/sanja/maria/git/10.6/sql/sql_connect.cc:1298
|
And adding check of result of it can not help
OK, claims by marko that the problem is in unchecked handler call result appeared to be a bit misleading, something other is wrong before the call.
commit 522364c6cfd416d874d888d2e75f454b7da0b930 (HEAD -> bb-10.6-MDEV-35944, origin/bb-10.6-MDEV-35944)
|
Author: Oleksandr Byelkin <sanja@mariadb.com>
|
Date: Mon Jan 27 15:21:15 2025 +0100
|
|
|
MDEV-35944 Assertion failures in ha_innobase::external_lock or in trx_t::free
|
|
Process errors of read_record()
|
+ if (error)
+ goto terminate_delete;
This is wrong, as error is set to -1 oif the read loop is sucessfull.
If there was an error, thd->is_error() is set.
Better to do:
+ if (thd->is_error())
+ goto terminate_delete;
However before doing that, the cleanups on the following lines needs to be done!
I have now created a 'final' patch for the first part (checking error after read loop) and created a separate patch for this.
Now working on another patch that changes prepare_for_insert() to generate errors for failures and also adding checking of the return value for prepare_for_insert() everywhere.
I hope that the final version will include the assertion change that I suggested adding to ha_innobase::external_lock(), so that any further cases like this will fail in a more obvious way.
The following assertion would fail, indicating an API violation:
diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.ccindex 4dd7a9405dd..aeccf3fec17 100644--- a/storage/innobase/handler/ha_innodb.cc+++ b/storage/innobase/handler/ha_innodb.cc@@ -16311,6 +16311,7 @@ ha_innobase::external_lock(case F_UNLCK:DEBUG_SYNC_C("ha_innobase_end_statement");m_mysql_has_locked = false;+ ut_ad(trx->n_mysql_tables_in_use);if (--trx->n_mysql_tables_in_use) {10.6 d77b9a4925c971364707d435028add41e8015173 with the patch
#5 0x0000562fe743d2b1 in ha_innobase::external_lock (this=0x7f9c88016c88, thd=0x7f9c88001168, lock_type=0x2) at /mariadb/10.6m/storage/innobase/handler/ha_innodb.cc:16314#6 0x0000562fe70ac05e in handler::ha_external_lock (this=0x7f9c88016c88, thd=0x7f9c88001168, lock_type=0x2) at /mariadb/10.6m/sql/handler.cc:7226#7 0x0000562fe6e1b4c0 in handler::ha_external_unlock (this=0x7f9c88016c88, thd=0x7f9c88001168) at /mariadb/10.6m/sql/handler.h:3562#8 0x0000562fe70ac476 in handler::ha_reset (this=0x7f9c8805fee8) at /mariadb/10.6m/sql/handler.cc:7291#9 0x0000562fe6c5f5b2 in close_thread_table (thd=0x7f9c88001168, table_ptr=0x7f9c88001260) at /mariadb/10.6m/sql/sql_base.cc:1028#10 0x0000562fe6c5f15d in close_thread_tables (thd=0x7f9c88001168) at /mariadb/10.6m/sql/sql_base.cc:968#11 0x0000562fe6d0df17 in mysql_execute_command (thd=0x7f9c88001168, is_called_from_prepared_stmt=0x0) at /mariadb/10.6m/sql/sql_parse.cc:6230#12 0x0000562fe6d13712 in mysql_parse (thd=0x7f9c88001168, rawbuf=0x7f9c88014a30 "DELETE FROM t2 FOR PORTION OF p FROM '2000-01-01' TO '2000-01-02'", length=0x41, parser_state=0x7f9cb44cd3f0)at /mariadb/10.6m/sql/sql_parse.cc:8208This is duplicating an earlier call during the execution of the same statement:
10.6 d77b9a4925c971364707d435028add41e8015173 with the patch
#0 ha_innobase::external_lock (this=0x7f9c8805fee8, thd=0x7f9c88001168, lock_type=0x2) at /mariadb/10.6m/storage/innobase/handler/ha_innodb.cc:16163#1 0x0000562fe70ac05e in handler::ha_external_lock (this=0x7f9c8805fee8, thd=0x7f9c88001168, lock_type=0x2) at /mariadb/10.6m/sql/handler.cc:7226#2 0x0000562fe6e1b4c0 in handler::ha_external_unlock (this=0x7f9c8805fee8, thd=0x7f9c88001168) at /mariadb/10.6m/sql/handler.h:3562#3 0x0000562fe71fcebc in unlock_external (thd=0x7f9c88001168, table=0x7f9c88015558, count=0x1) at /mariadb/10.6m/sql/lock.cc:730#4 0x0000562fe71fc39f in mysql_unlock_tables (thd=0x7f9c88001168, sql_lock=0x7f9c88015538, free_lock=0x0) at /mariadb/10.6m/sql/lock.cc:435#5 0x0000562fe71fc30d in mysql_unlock_tables (thd=0x7f9c88001168, sql_lock=0x7f9c88015538) at /mariadb/10.6m/sql/lock.cc:418#6 0x0000562fe6c5f12f in close_thread_tables (thd=0x7f9c88001168) at /mariadb/10.6m/sql/sql_base.cc:960#7 0x0000562fe6d0df17 in mysql_execute_command (thd=0x7f9c88001168, is_called_from_prepared_stmt=0x0) at /mariadb/10.6m/sql/sql_parse.cc:6230#8 0x0000562fe6d13712 in mysql_parse (thd=0x7f9c88001168, rawbuf=0x7f9c88014a30 "DELETE FROM t2 FOR PORTION OF p FROM '2000-01-01' TO '2000-01-02'", length=0x41, parser_state=0x7f9cb44cd3f0)at /mariadb/10.6m/sql/sql_parse.cc:8208If I revert the
MDEV-24035change and add the corresponding debug assertion, it will not fail. I see that in that case, the two calls with F_UNLCK are preceded by one call with F_WRLCK and F_RDLCK each, in that order. I suspect that one of the preceding calls will work differently in the presence of theMDEV-24035change.