MySQL Bugs: #113312: Server stall during Alter/Drop table while clearing AHIs from the buffer pool

Bug #113312	Server stall during Alter/Drop table while clearing AHIs from the buffer pool
Submitted:	1 Dec 2023 22:48	Modified:	8 Feb 2024 13:18
Reporter:	Mershad Irani	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	8.0.35, 8.1.0	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Dropping/Altering a table can cause semaphore waits while deleting adaptive hash pages in the buffer pool. The issue does not occur, when adaptive hash indexes are disabled(innodb_adaptive_hash_index=OFF). 

Below is the output of the InnoDB monitor

---TRANSACTION 17347556, ACTIVE 21 sec dropping table
0 lock struct(s), heap size 1128, 0 row lock(s)
MySQL thread id 11, OS thread handle 22814031947520, query id 602977674 172.31.57.46 reinvent checking permissions
drop table tpcc.stock

# We see that the hash buffer has grown to 94623

Hash table size 24437351, node heap has 153 buffer(s)
Hash table size 24437351, node heap has 7 buffer(s)
Hash table size 24437351, node heap has 8 buffer(s)
Hash table size 24437351, node heap has 94623 buffer(s)
Hash table size 24437351, node heap has 4266 buffer(s)
Hash table size 24437351, node heap has 60 buffer(s)
Hash table size 24437351, node heap has 5 buffer(s)
Hash table size 24437351, node heap has 5 buffer(s)
1 row in set (0.01 sec)

# We see semaphore waits 
OS WAIT ARRAY INFO: reservation count 3457397
--Thread 22705000605440 has waited at fts0opt.cc line 2698 for 17 seconds the semaphore:
Mutex at 0x14bfbba6d420, Mutex DICT_SYS created dict0dict.cc:1018, locked by 22814031947520

--Thread 22705004807936 has waited at srv0srv.cc line 1996 for 21 seconds the semaphore:
X-lock on RW-latch at 0x14bfbae91f00 created in file dict0dict.cc line 1026
a writer (thread id 22814031947520) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file /local/p4clients/pkgbuild-UJRXn/workspace/src/RDSMySQL/storage/innobase/row/row0mysql.cc line 3770
--Thread 22704996402944 has waited at row0purge.cc line 917 for 21 seconds the semaphore:
Mutex at 0x14bfbba6d420, Mutex DICT_SYS created dict0dict.cc:1018, locked by 22814031947520

Below is the call stack while the drop is in progress. 

Thread 35 (Thread 0x1482aca7f700 (LWP 21046)):
#0 0x000000000255b9f0 in ha_delete_hash_node(hash_table_t*, ha_node_t*) ()
#1 0x000000000242197a in btr_search_drop_page_hash_index(buf_block_t*, bool) ()
#2 0x00000000024234b7 in btr_search_drop_page_hash_when_freed(page_id_t const&, page_size_t const&) ()
#3 0x000000000242664b in btr_drop_next_batch(page_size_t const&, dict_index_t const**, dict_index_t const**) ()
#4 0x00000000024268b4 in btr_drop_ahi_for_table(dict_table_t*) ()
#5 0x000000000232e8e3 in row_drop_table_for_mysql(char const*, trx_t*, bool, dict_table_t*) ()
#6 0x00000000022033c5 in int innobase_basic_ddl::delete_impl<dd::Table>(THD*, char const*, dd::Table const*, TABLE const*) ()
#7 0x0000000001175119 in ha_delete_table(THD*, handlerton*, char const*, char const*, char const*, dd::Table const*, bool) ()
#8 0x0000000000fa2f52 in drop_base_table(THD*, Drop_tables_ctx const&, Table_ref*, bool, std::set<handlerton*, std::less<handlerton*>, std::allocator<handlerton*> >*, Foreign_key_parents_invalidator*, std::vector<MDL_ticket*, std::allocator<MDL_ticket*> >*, MEM_ROOT*) ()
#9 0x0000000000faa093 in mysql_rm_table_no_locks(THD*, Table_ref*, bool, bool, bool, bool*, std::set<handlerton*, std::less<handlerton*>, std::allocator<handlerton*> >*, Foreign_key_parents_invalidator*, std::vector<MDL_ticket*, std::allocator<MDL_ticket*> >*) ()
#10 0x0000000000fac581 in mysql_rm_table(THD*, Table_ref*, bool, bool) ()
#11 0x0000000000f108c3 in mysql_execute_command(THD*, bool) ()
#12 0x0000000000f11f84 in dispatch_sql_command(THD*, Parser_state*) ()
#13 0x0000000000f13415 in dispatch_command(THD*, COM_DATA const*, enum_server_command) ()
#14 0x0000000000f15927 in do_command(THD*) ()
#15 0x000000000105e730 in handle_connection ()
#16 0x0000000002654025 in pfs_spawn_thread ()
#17 0x00001482ae5fe44b in start_thread () from target:/lib64/libpthread.so.0
#18 0x00001482adde352f in clone () from target:/lib64/libc.so.6

The issue does not occur when AHIs are disabled. Also larger the innodb buffer pool, the more time it takes for the drop/Alter table to complete.

Its it not desirable for the entire database server to be stalled and other queries on other tables to be blocked while DDL is in progress.

This looks similar to https://bugs.mysql.com/bug.php?id=91977

How to repeat:
Database Server Configuration:

VCPUs: 16
Cores: 8
RAM: 128 GB

Database Parameters: 

innodb_log_file_size 64GB
innodb_buffer_pool_size 92 GB
innodb_adaptive_hash_index 1
innodb_adaptive_hash_index_parts 8

Database Version: 8.0.35, 8.1.0

Steps:
1. Install HammerDB 4.4 and MySQL client. HammerDB can be download from https://github.com/TPC-Council/HammerDB/releases/download/v4.4/HammerDB-4.4-Linux.tar.gz

2. Create the build.tcl and test.tcl files. build.tcl will be used to create the schemas , while test.tcl will run the actual hammerDB workload. We use 3500 warehouses for the tests 

<hostname> should be replaced by the IP address/hostname of the database.
<username> should be replaced by the username
<password> should be replaced by the password

cd HammerDB-4.4/

cat << 'EOF' > build.tcl
#!/bin/tclsh
puts "SETTING CONFIGURATION"
global complete
proc wait_to_complete {} {
global complete
set complete [vucomplete]
if {!$complete} {after 5000 wait_to_complete} else { exit }
}
dbset db mysql
dbset bm TPC-C
diset connection mysql_host <hostname>
diset tpcc mysql_user <username>
diset tpcc mysql_pass <password>
diset tpcc mysql_dbase tpcc
diset tpcc mysql_count_ware 3500
diset tpcc mysql_num_vu 32
diset tpcc mysql_partition true
buildschema
wait_to_complete
vwait forever
EOF

cat << 'EOF' > test.tcl
#!/bin/tclsh
proc runtimer { seconds } {
set x 0
set timerstop 0
while {!$timerstop} {
incr x
after 1000
if { ![ expr {$x % 60} ] } {
set y [ expr $x / 60 ]
puts "Timer: $y minutes elapsed"
}
update
if { [ vucomplete ] || $x eq $seconds } { set timerstop 1 }
}
return
}

dbset db mysql
diset connection mysql_host <hostname>
diset tpcc mysql_user <username>
diset tpcc mysql_pass <password>
diset tpcc mysql_dbase tpcc
diset tpcc mysql_driver timed
diset tpcc mysql_allwarehouse true
diset tpcc mysql_raiseerror true
diset tpcc mysql_rampup 5
diset tpcc mysql_duration 25
diset tpcc mysql_timeprofile true
tcset refreshrate 10
print dict
vuset logtotemp 1
loadscript
puts "SEQUENCE STARTED"
print dict
vuset vu 256
vucreate
vurun
runtimer 9000
vudestroy
after 5000
puts "TEST SEQUENCE COMPLETE"
exit
EOF

3. Now that the files have been created, we execute the scripts using HammerDB cli.

# To Load the schema
cd HammerDB-4.4
export LD_LIBRARY_PATH=/usr/lib64/mysql/
./hammerdbcli
source build.tcl

# To Run the HammerDB tests
cd HammerDB-4.4
export LD_LIBRARY_PATH=/usr/lib64/mysql/
./hammerdbcli
source test.tcl

4. While the test.tcl run is in progress, run "show engine InnoDB status" and check the size of the hash buffers. It should increase. In this case we see it increased to 97K

mysql> pager grep "Hash table" ; show engine innodb status \G pager;
PAGER set to 'grep "Hash table"'
Hash table size 24437351, node heap has 7 buffer(s)
Hash table size 24437351, node heap has 97417 buffer(s)
Hash table size 24437351, node heap has 153 buffer(s)
Hash table size 24437351, node heap has 4 buffer(s)
Hash table size 24437351, node heap has 4 buffer(s)
Hash table size 24437351, node heap has 3 buffer(s)
Hash table size 24437351, node heap has 31 buffer(s)
Hash table size 24437351, node heap has 61 buffer(s)
1 row in set (0.01 sec)

5. Once the workload stops and Hash table buffer has grown to more than 90K, you can drop the table.

mysql> drop table tpcc.stock;
Query OK, 0 rows affected (1 min 45.35 sec)

Hello Mershad Irani,

Thank you for the report and feedback.
I'm trying to reproduce with the provided details and would get back to you if anything further needed(surely, going to take a long time in the load step, in test step etc). This reminds me of my former colleague Jesper's Bug #91977 and mostly looks identical as you rightly mentioned. In any case, will try to reproduce. Thank you.

Sincerely,
Umesh

Hello Mershad Irani,

Thank you for the details steps.
Verified as described.

For now, not marking this as a duplicate of Bug #91977 as Bug #91977 was supposed to be fixed per  [30 Oct 2020 15:30] Sunny Bains

The fix has been pushed and should be in the next 8.x release. All truncate/drop tables will be instant. This underlying issues is the same as Bug#98869.

regards,
Umesh

Test results - 8.0.35

Attachment: 113312_8.0.35.log (application/octet-stream, text), 20.79 KiB.

Hi Uday, 

Thank you for the confirmation. Glad to know that the issue will be fixed in next release.  

Would it be possible for you to confirm if this will also fix the issue during the table dropping phase with "Alter tables ?"  For example, Changing the data type of a column.  

I see a bug where, ALTER TABLE...ALGORITHM=INSTANT also stalls on AHI drop.  https://bugs.mysql.com/bug.php?id=107308 

Also, when you mention next 8.x release, would this be 8.0.36 or 8.0.37 ?

Apologies for the typo in the addressed name in the previous comment. I was referring to "Umesh".

I wonder if this is what I have been battling with, for the past weeks.

I'm on 8.0.33, and I have a cronjob that updates the contents of a table from a CSV file.

The cronjob runs a "LOAD DATA LOCAL INFILE" into a new table, then a set of "RENAME TABLE" to swap the tables, and then "DROP TABLE" to delete the renamed old table.

The "DROP TABLE" is taking 3 seconds, and during that time, I get a number of logs saying that a number of concurrent "SELECT" queries took too long. Those "SELECT" tables are on another database (on the same MySQL server), and have absolutely nothing to do with this table.

I've been trying a number of things, such as using "TRUNCATE/OPTIMIZE/DROP" instead (but looks like "TRUNCATE" is an alias to "DROP/CREATE" anyway), add "SLEEP(5)" in between the queries, etc... nothing improves.

The table isn't even that big... just 350MB and 1 secondary index.

Is this the same issue described here?

I've recently migrated from MariaDB to MySQL, and I don't recall ever having this issue with MariaDB.

Thank you very much.

> I've recently migrated from MariaDB to MySQL, and I don't recall ever
having this issue with MariaDB.

The AHI (InnoDB adaptive hash index) is disabled in MariaDB 10.5+ [1] while it is enabled in MySQL 8.0 [2].  I would suggest disabling it in MySQL and seeing if this solves the problem.

[1]: https://mariadb.com/kb/en/innodb-system-variables/#innodb_adaptive_hash_index

[2]: https://dev.mysql.com/doc/refman/8.0/en/innodb-parameters.html#sysvar_innodb_adaptive_hash...

Thank you very much.
I've changed that variable to OFF (dynamically, without restarting), and will let you know what happens next time the cron runs.

Looks like `innodb_adaptive_hash_index = OFF` resolved the issue for me !! Thank you very much!

Hi Umesh, 

Hope you are doing well. 

Do we know which version of MySQL 8 will have this fixed ?

Regards,
Mershad

Please note that in 8.4 we have AHI disabled by default, please see https://dev.mysql.com/doc/relnotes/mysql/8.4/en/news-8-4-0.html
https://dev.mysql.com/doc/refman/8.4/en/innodb-parameters.html#sysvar_innodb_adaptive_hash...

Marcos Albe told me this bug still exists and I was surprised and I told him lazy eviction of dropped tablesapce pages is implemented, so it shouldn't exist.

but alas, I see that btr_drop_ahi_for_table() exists!

The problem is how AHI records are hashed. They don't use the space_id or a table_id when hashing records. AHI uses record field and prefixes to hash.

So even if a page is lazily is evicted, it needs a table definition after its dropped. This is a design problem.

It can be solved either with improved hashing or saving in-memory table definitions (dict_table_t/dict_index_ts) for deferred freeing.

Now the questions, AHI is now OFF by default in 8.4 and I believe this feature might be soon neglected/deprecated/dying.

Is it worth the effort? 

We can turn AHI off and live with these bugs!