[MDEV-29913] Assertion `thd->stmt_arena != thd->progress.arena' failed in thd_progress_init upon bulk load Created: 2022-10-29  Updated: 2023-12-15  Resolved: 2023-11-28

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.7, 10.8, 10.9, 10.10, 10.11, 11.0, 11.1, 11.2, 11.3
Fix Version/s: 10.4.33, 10.5.24, 10.6.17, 10.11.7, 11.0.5, 11.1.4, 11.2.3

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: affects-tests, performance, regression-10.7

Issue Links:
Relates
relates to MDEV-6172 Monitor progress of ALTER TABLE ... A... Closed
relates to MDEV-8179 Absent progress report for operations... Closed

 Description    

--source include/have_sequence.inc
 
--source include/have_innodb.inc
 
 
 
SELECT * INTO OUTFILE 'numbers' FROM seq_1_to_20165;
 
 
 
CREATE TABLE t (
 
  pk int,
 
  f1 varchar(4) DEFAULT 'foo',
 
  f2 varchar(16) DEFAULT 'foobarqux',
 
  f3 bigint default 0,
 
  f4 timestamp default '2000-01-01',
 
  f5 tinyint default 0,
 
  KEY(pk)
 
) ENGINE=InnoDB;
 
 
 
SET FOREIGN_KEY_CHECKS=0, UNIQUE_CHECKS=0, AUTOCOMMIT=0;
 
LOAD DATA INFILE 'numbers' INTO TABLE t (pk);
 
 
 
# Cleanup
 
--let $datadir= `select @@datadir`
 
--remove_file $datadir/test/numbers
 
DROP TABLE t;

10.7 dd9da61d

 
mariadbd: /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_class.cc:4730: void thd_progress_init(THD*, uint): Assertion `thd->stmt_arena != thd->progress.arena' failed.
 
221029 22:11:09 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f9ebc70d662 in __GI___assert_fail (assertion=0x55fa5248f3c0 "thd->stmt_arena != thd->progress.arena", file=0x55fa5248ac40 "/home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_class.cc", line=4730, function=0x55fa5248f420 "void thd_progress_init(THD*, uint)") at assert.c:101
 
#8  0x000055fa5044ca27 in thd_progress_init (thd=0x62b00017a218, max_stage=1) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_class.cc:4730
 
#9  0x000055fa51b159f4 in row_merge_sort (trx=0x7f9eb326b340, dup=0x7f9ea91e6e90, file=0x608000012c38, block=0x7f9ea7fa3000 "\004\t\003", tmpfd=0x60d0000101e8, update_progress=true, pct_progress=0, pct_cost=0, crypt_block=0x0, space=5, stage=0x0) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/storage/innobase/row/row0merge.cc:3577
 
#10 0x000055fa51b21fa1 in row_merge_bulk_t::write_to_index (this=0x60d0000101d0, index_no=0, trx=0x7f9eb326b340) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/storage/innobase/row/row0merge.cc:5352
 
#11 0x000055fa51b222ef in row_merge_bulk_t::write_to_table (this=0x60d0000101d0, table=0x61800004b920, trx=0x7f9eb326b340) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/storage/innobase/row/row0merge.cc:5379
 
#12 0x000055fa517e1ab1 in trx_mod_table_time_t::write_bulk (this=0x608000012be0, table=0x61800004b920, trx=0x7f9eb326b340) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/storage/innobase/include/trx0trx.h:522
 
#13 0x000055fa517e2cad in trx_t::bulk_insert_apply (this=0x7f9eb326b340) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/storage/innobase/include/trx0trx.h:1163
 
#14 0x000055fa517bf07a in ha_innobase::extra (this=0x61d0002ec2b8, operation=HA_EXTRA_NO_IGNORE_DUP_KEY) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/storage/innobase/handler/ha_innodb.cc:15721
 
#15 0x000055fa50550852 in mysql_load (thd=0x62b00017a218, ex=0x629000109328, table_list=0x6290001093d0, fields_vars=..., set_fields=..., set_values=..., handle_duplicates=DUP_ERROR, ignore=false, read_file_from_client=false) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_load.cc:704
 
#16 0x000055fa5057f844 in mysql_execute_command (thd=0x62b00017a218, is_called_from_prepared_stmt=false) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_parse.cc:5021
 
#17 0x000055fa5059361d in mysql_parse (thd=0x62b00017a218, rawbuf=0x629000109238 "LOAD DATA INFILE 'numbers' INTO TABLE t (pk)", length=44, parser_state=0x7f9ea91e8990) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_parse.cc:8014
 
#18 0x000055fa50569fb7 in dispatch_command (command=COM_QUERY, thd=0x62b00017a218, packet=0x62900028f219 "", packet_length=44, blocking=true) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_parse.cc:1894
 
#19 0x000055fa50566d8a in do_command (thd=0x62b00017a218, blocking=true) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_parse.cc:1407
 
#20 0x000055fa509f9522 in do_handle_one_connection (connect=0x6080000032b8, put_in_cache=true) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_connect.cc:1416
 
#21 0x000055fa509f8eb8 in handle_one_connection (arg=0x608000003238) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/sql/sql_connect.cc:1318
 
#22 0x000055fa515a57a2 in pfs_spawn_thread (arg=0x617000007418) at /home/jenkins/workspace/sandbox-elenst/Nightly-Build-CS/src/storage/perfschema/pfs.cc:2201
 
#23 0x00007f9ebcbebea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#24 0x00007f9ebc7d8aef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95



 Comments   
Comment by Matthias Leich [ 2023-02-10 ] 

This bug affects testing. When running the RQG test battery conf/mariadb/InnoDB_CR_RC_MB.cc which has a focus on
 
        intentional crash+recovery, shutdown+restart, mariabackup
 
~ 50 of 5000 tests fail with that bug.

Comment by Roel Van de Paar [ 2023-03-04 ]

I also ran into this one

SET unique_checks=0,foreign_key_checks=0;
 
CREATE TABLE t (b INT) ENGINE=InnoDB;
 
INSERT t SELECT SEQ FROM seq_1_to_128000;
 
CREATE TABLE t3 (c INT) ENGINE=InnoDB;
 
SELECT * FROM t INTO OUTFILE 'a';
 
LOAD DATA INFILE 'a' INTO TABLE t3;

Leads to:

11.0.1 f2dc4d4c10ac36a73b5c1eb765352d3aee808d66 (Debug)

 
mariadbd: /test/11.0_dbg/sql/sql_class.cc:4728: void thd_progress_init(THD*, uint): Assertion `thd->stmt_arena != thd->progress.arena' failed.

11.0.1 f2dc4d4c10ac36a73b5c1eb765352d3aee808d66 (Debug)

 
Core was generated by `/test/MD180223-mariadb-11.0.1-linux-x86_64-dbg/bin/mariadbd --no-defaults --cor'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22504783754816)
 
    at ./nptl/pthread_kill.c:44
 
[Current thread is 1 (Thread 0x1477cda43640 (LWP 4118864))]
 
(gdb) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22504783754816) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=22504783754816) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=22504783754816, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x00001477e6ac6476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x00001477e6aac7f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x00001477e6aac71b in __assert_fail_base (fmt=0x1477e6c61150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x555934fdcd38 "thd->stmt_arena != thd->progress.arena", file=0x555934fdc0a8 "/test/11.0_dbg/sql/sql_class.cc", line=4728, function=<optimized out>) at ./assert/assert.c:92
 
#6  0x00001477e6abde96 in __GI___assert_fail (assertion=0x555934fdcd38 "thd->stmt_arena != thd->progress.arena", file=0x555934fdc0a8 "/test/11.0_dbg/sql/sql_class.cc", line=4728, function=0x555934fdcd60 "void thd_progress_init(THD*, uint)") at ./assert/assert.c:101
 
#7  0x00005559344797f7 in thd_progress_init (thd=0x14778c000d58, max_stage=1) at /test/11.0_dbg/sql/sql_class.cc:4728
 
#8  0x0000555934bbe655 in row_merge_sort (trx=trx@entry=0x1477e4aedb80, dup=dup@entry=0x1477cda41530, file=file@entry=0x14778c071c70, block=0x1477cd6f9000 "\002", tmpfd=tmpfd@entry=0x14778c072108, update_progress=update_progress@entry=true, pct_progress=pct_progress@entry=0, pct_cost=pct_cost@entry=0, crypt_block=0x0, space=9, stage=0x0) at /test/11.0_dbg/storage/innobase/row/row0merge.cc:3548
 
#9  0x0000555934bc2efc in row_merge_bulk_t::write_to_index (this=this@entry=0x14778c0720f0, index_no=index_no@entry=0, trx=trx@entry=0x1477e4aedb80) at /test/11.0_dbg/storage/innobase/row/row0merge.cc:5322
 
#10 0x0000555934bc3072 in row_merge_bulk_t::write_to_table (this=0x14778c0720f0, table=<optimized out>, trx=trx@entry=0x1477e4aedb80) at /test/11.0_dbg/storage/innobase/row/row0merge.cc:5349
 
#11 0x0000555934bc30b8 in trx_mod_table_time_t::write_bulk (this=this@entry=0x14778c0220d8, table=<optimized out>, trx=trx@entry=0x1477e4aedb80) at /test/11.0_dbg/storage/innobase/row/row0merge.cc:5362
 
#12 0x0000555934bc324b in trx_t::bulk_insert_apply_low (this=this@entry=0x1477e4aedb80) at /test/11.0_dbg/storage/innobase/row/row0merge.cc:5376
 
#13 0x0000555934a9c9d3 in trx_t::bulk_insert_apply (this=0x1477e4aedb80) at /test/11.0_dbg/storage/innobase/include/trx0trx.h:1168
 
#14 ha_innobase::extra (this=0x14778c16fde0, operation=<optimized out>) at /test/11.0_dbg/storage/innobase/handler/ha_innodb.cc:15626
 
#15 0x00005559344cdace in mysql_load (thd=thd@entry=0x14778c000d58, ex=0x14778c013200, table_list=table_list@entry=0x14778c013288, fields_vars=@0x14778c005ec0: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14778c013b20, last = 0x14778c013b20, elements = 1}, <No data fields>}, set_fields=@0x14778c005ef0: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x5559359ba440 <end_of_list>, last = 0x14778c005ef0, elements = 0}, <No data fields>}, set_values=@0x14778c005ed8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x5559359ba440 <end_of_list>, last = 0x14778c005ed8, elements = 0}, <No data fields>}, handle_duplicates=DUP_ERROR, ignore=<optimized out>, read_file_from_client=false) at /test/11.0_dbg/sql/sql_load.cc:704
 
#16 0x00005559344de345 in mysql_execute_command (thd=thd@entry=0x14778c000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.0_dbg/sql/sql_parse.cc:5027
 
#17 0x00005559344e27cf in mysql_parse (thd=thd@entry=0x14778c000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1477cda422c0) at /test/11.0_dbg/sql/sql_parse.cc:8002
 
#18 0x00005559344e4963 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14778c000d58, packet=packet@entry=0x14778c00ae19 "", packet_length=packet_length@entry=34, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_class.h:242
 
#19 0x00005559344e67bc in do_command (thd=0x14778c000d58, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_parse.cc:1407
 
#20 0x00005559346376e2 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5559382c8fe8, put_in_cache=put_in_cache@entry=true) at /test/11.0_dbg/sql/sql_connect.cc:1416
 
#21 0x0000555934637941 in handle_one_connection (arg=0x5559382c8fe8) at /test/11.0_dbg/sql/sql_connect.cc:1318
 
#22 0x00001477e6b18b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#23 0x00001477e6baaa00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Bug confirmed present in:
MariaDB: 10.7.8 (dbg), 10.8.8 (dbg), 10.9.6 (dbg), 10.10.4 (dbg), 10.11.2 (dbg), 11.0.1 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.3.38 (dbg), 10.3.38 (opt), 10.4.29 (dbg), 10.4.29 (opt), 10.5.20 (dbg), 10.5.20 (opt), 10.6.13 (dbg), 10.6.13 (opt), 10.7.8 (opt), 10.8.8 (opt), 10.9.6 (opt), 10.10.4 (opt), 10.11.2 (opt), 11.0.1 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.40 (dbg), 5.7.40 (opt), 8.0.31 (dbg), 8.0.31 (opt)

Comment by Thirunarayanan Balathandayuthapani [ 2023-10-24 ]

thd_progress_init() is being called from load inline as well as while applying bulk insert operation.

Comment by Thirunarayanan Balathandayuthapani [ 2023-11-09 ]

https://github.com/MariaDB/server/pull/2825

Comment by Marko Mäkelä [ 2023-11-14 ]

There are failures of the test innodb.insert_into_empty. Also, please rebase this on the current 10.11 branch, now that the release branches have been merged back to the main branches.

Comment by Thirunarayanan Balathandayuthapani [ 2023-11-27 ]

MDEV-8179 doesn't report the progress for online alter table properly. It just report the progress
in row_merge_sort() and it doesn't care about row_merge_read_clustered_index() , row_merge_build_indexes() and nothing in
prepare and commit phase. I think it was added just for namesake. I suggest to remove the code in row_merge_sort()

Comment by Marko Mäkelä [ 2023-11-27 ]

thiru, if you confirmed that the code that was added in MDEV-8179 has no user observable impact (the commit had added a comment mentioning show processlist progress field but not any test case), I think that we’d better remove that dead code from 10.4 already.

Some further progress reporting was added in MDEV-6812. It uses global variables and seems to return bogus data when multiple ALTER TABLE or CREATE INDEX statements are being executed concurrently. We could clean that up separately, ultimately in MDEV-9260.

Comment by Marko Mäkelä [ 2023-12-15 ]

The test in the Description would pass if I apply the following patch to a debug build:

diff --git a/sql/sql_class.cc b/sql/sql_class.cc
 
index 9da1ec54a82..f5099749930 100644
 
--- a/sql/sql_class.cc
 
+++ b/sql/sql_class.cc
 
@@ -4757,9 +4757,9 @@ static void thd_send_progress(THD *thd)
 
 
 extern "C" void thd_progress_init(MYSQL_THD thd, uint max_stage)
 
 {
 
-  DBUG_ASSERT(thd->stmt_arena != thd->progress.arena);
 
   if (thd->progress.arena)
 
     return; // already initialized
 
+  DBUG_ASSERT(thd->stmt_arena != thd->progress.arena);
 
   /*
 
     Send progress reports to clients that supports it, if the command
 
     is a high level command (like ALTER TABLE) and we are not in a

Based on this as well as a review of the contents of thd_progress_report() and thd_progress_end(), I conclude that the redundant calls do not cause any harm in non-debug build.

Removing the incorrectly working progress reporting code fixed the debug assertion and could slightly improve performance.

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