Bug #92133 DICT_SYS mutex contention causes complete stall when running with 40 mill tables
Submitted: 22 Aug 2018 17:43 Modified: 27 Oct 2018 15:02
Reporter: Alexander Rubin Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Data Dictionary Severity:S5 (Performance)
Version:8.0.12 OS:Any
Assigned to: CPU Architecture:Any

[22 Aug 2018 17:43] Alexander Rubin
Description:
When running with millions of tables (and shared tablespaces) I can see the complete stall waiting on DICT_SYS mutex

Sysbench load:

[ 453s ] thds: 32 tps: 1203.96 qps: 1203.96 (r/w/o: 1203.96/0.00/0.00) lat (ms,95%): 41.10 err/s: 0.00 reconn/s: 0.00
[ 454s ] thds: 32 tps: 1202.32 qps: 1202.32 (r/w/o: 1202.32/0.00/0.00) lat (ms,95%): 42.61 err/s: 0.00 reconn/s: 0.00
[ 455s ] thds: 32 tps: 1196.74 qps: 1196.74 (r/w/o: 1196.74/0.00/0.00) lat (ms,95%): 41.10 err/s: 0.00 reconn/s: 0.00
[ 456s ] thds: 32 tps: 1197.18 qps: 1197.18 (r/w/o: 1197.18/0.00/0.00) lat (ms,95%): 41.10 err/s: 0.00 reconn/s: 0.00
[ 457s ] thds: 32 tps: 887.11 qps: 887.11 (r/w/o: 887.11/0.00/0.00) lat (ms,95%): 41.10 err/s: 0.00 reconn/s: 0.00
[ 458s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 459s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 460s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 461s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 462s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 463s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 464s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 465s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 466s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 467s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 468s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 469s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 470s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 471s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 472s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 473s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
[ 474s ] thds: 32 tps: 403.96 qps: 403.96 (r/w/o: 403.96/0.00/0.00) lat (ms,95%): 16819.24 err/s: 0.00 reconn/s: 0.00
[ 475s ] thds: 32 tps: 1196.00 qps: 1196.00 (r/w/o: 1196.00/0.00/0.00) lat (ms,95%): 41.85 err/s: 0.00 reconn/s: 0.00
[ 476s ] thds: 32 tps: 1208.96 qps: 1208.96 (r/w/o: 1208.96/0.00/0.00) lat (ms,95%): 41.85 err/s: 0.00 reconn/s: 0.00
[ 477s ] thds: 32 tps: 1192.06 qps: 1192.06 (r/w/o: 1192.06/0.00/0.00) lat (ms,95%): 41.85 err/s: 0.00 reconn/s: 0.00
[ 478s ] thds: 32 tps: 1173.89 qps: 1173.89 (r/w/o: 1173.89/0.00/0.00) lat (ms,95%): 43.39 err/s: 0.00 reconn/s: 0.00
[ 479s ] thds: 32 tps: 1207.07 qps: 1207.07 (r/w/o: 1207.07/0.00/0.00) lat (ms,95%): 41.85 err/s: 0.00 reconn/s: 0.00

Show engine innodb status shows:

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2195106
--Thread 140451928655616 has waited at fts0opt.cc line 2703 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140451898394368 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140457041856256 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140451897509632 has waited at dict0dd.ic line 273 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140451898689280 has waited at ha_innodb.cc line 5814 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140456571414272 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140456571119360 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140457043920640 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140451896329984 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140451898099456 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140457040971520 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140451897214720 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140456572004096 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140457043035904 has waited at ha_innodb.cc line 6080 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

--Thread 140451899279104 has waited at ha_innodb.cc line 5814 for 13.00 seconds the semaphore:
Mutex at 0x7fbeb83e6bd8, Mutex DICT_SYS created dict0dict.cc:1019, lock var 1

How to repeat:
Create 1 million to 40 million tables with MySQL 8.0.12.
Script to create 40M tables in parallel:
============================
#/bin/bash
function do_db {
        db_exist=$(mysql -A -s -Nbe "select 1 from information_schema.schemata where schema_name = '$db'")
        if [ "$db_exist" == "1" ]; then echo "Already exists $db"; return 0; fi; 
        mysql -vvv -e "create database $db";
        mysql -vvv $db -e "CREATE TABLESPACE $db ADD DATAFILE '$db.ibd' engine=InnoDB;"
        for i in {1..100}
        do
                table="CREATE TABLE sbtest$i ( id int(10) unsigned NOT NULL AUTO_INCREMENT, k int(10) unsigned NOT NULL DEFAULT '0', c varchar(120) NOT NULL DEFAULT '', pad varchar(60) NOT NULL DEFAULT '', PRIMARY KEY (id), KEY k_1 (k) ) ENGINE=InnoDB DEFAULT CHARSET=latin1 tablespace $db;"
                mysql $db -e "$table"
        done
}
c=0
for m in {1..4000000}
do
        for i in {1..40}
        do
                let c=$c+1
                echo $c
                db="sbtest_$c"
                do_db &
        done
        wait
        #if [ $c > 4000000 ]; then exit; fi
done
============================

Run sysbench:
============================
function run_sb() {
conn=" --db-driver=mysql --mysql-socket=/var/lib/mysql-data/mysql.sock  --mysql-db=sbtest_1 --mysql-user=sbtest --mysql-password=abc "
sysbench $conn --oltp_db_count=$db_count --oltp_tables_count=$table_count --oltp-table-size=10000 --report-interval=1 --num-threads=$num_threads --max-requests=0 --max-time=$max_time ./select_custom.lua run | tee -a sysbench_2.txt

}

let db_count=400000
table_count=100
max_time=10000
num_threads=32
run_sb 
============================
[29 Aug 2018 13:46] MySQL Verification Team
Verified but I changed it to S5 (performance).

Thanks for the report
Bogdan
[1 Oct 2018 21:52] Charles Thompson
Any update on this? This is a very concerning issue for my company as we have millions of tables.
[24 Oct 2018 19:39] Alexander Rubin
Scripts to reproduce:

1. Create 20K+ tables first

#/bin/bash
function do_db {
        db_exist=$(mysql -A -s -Nbe "select 1 from information_schema.schemata where schema_name = '$db'")
        if [ "$db_exist" == "1" ]; then echo "Already exists $db"; return 0; fi; 
        mysql -vvv -e "create database $db";
        mysql -vvv $db -e "CREATE TABLESPACE $db ADD DATAFILE '$db.ibd' engine=InnoDB;"
        for i in {1..100}
        do
                table="CREATE TABLE sbtest$i ( id int(10) unsigned NOT NULL AUTO_INCREMENT, k int(10) unsigned NOT NULL DEFAULT '0', c varchar(120) NOT NULL DEFAULT '', pad varchar(60) NOT NULL DEFAULT '', PRIMARY KEY (id), KEY k_1 (k) ) ENGINE=InnoDB DEFAULT CHARSET=latin1 tablespace $db;"
                mysql $db -e "$table"
        done
}
c=0
for m in {1..4000000}
do
        for i in {1..40}
        do
                let c=$c+1
                echo $c
                db="sbtest_$c"
                do_db &
        done
        wait
        #if [ $c > 4000000 ]; then exit; fi
done

2. Run this script:

##### shel script, sysbench_mysql.sh
#####

function run_sb() {
        conn=" --db-driver=mysql --mysql-socket=/var/run/mysqld/mysqld.sock  --mysql-db=mysql --mysql-user=sbtest --mysql-password=abc "
        sysbench $conn --oltp_db_count=$db_count --oltp_tables_count=$table_count --oltp-table-size=10000 --report-interval=1 --num-threads=$num_threads --max-requests=0 --max-time=$max_time ./select_custom.lua run | tee -a sysbench_2.txt
}
let db_count=70000
table_count=1000
max_time=10000
num_threads=32
run_sb

#### select_custom.lua
####

pathtest = "/usr/share/sysbench/tests/include/oltp_legacy/"
if pathtest then
   dofile(pathtest .. "common.lua")
else
   require("common")
end
function thread_init(thread_id)
   set_vars()
end
function event()
   local table_name
   local i
   local c_val
   local k_val
   local pad_val
   oltp_db_count = tonumber(oltp_db_count) or 1
   -- local oltp_db_count = 4
   table_name = "sbtest_" .. sb_rand(100, oltp_db_count)..".sbtest".. sb_rand(1, oltp_tables_count)
   k_val = sb_rand(1, oltp_table_size)
   c_val = sb_rand_str([[
###########-###########-###########-###########-###########-###########-###########-###########-###########-###########]])
   pad_val = sb_rand_str([[
###########-###########-###########-###########-###########]])
      rs = db_query("SELECT id FROM " .. table_name .." LIMIT 1")
end
[24 Oct 2018 19:40] Alexander Rubin
Scripts to reproduce:

1. Create 20K+ tables first

#/bin/bash
function do_db {
        db_exist=$(mysql -A -s -Nbe "select 1 from information_schema.schemata where schema_name = '$db'")
        if [ "$db_exist" == "1" ]; then echo "Already exists $db"; return 0; fi; 
        mysql -vvv -e "create database $db";
        mysql -vvv $db -e "CREATE TABLESPACE $db ADD DATAFILE '$db.ibd' engine=InnoDB;"
        for i in {1..100}
        do
                table="CREATE TABLE sbtest$i ( id int(10) unsigned NOT NULL AUTO_INCREMENT, k int(10) unsigned NOT NULL DEFAULT '0', c varchar(120) NOT NULL DEFAULT '', pad varchar(60) NOT NULL DEFAULT '', PRIMARY KEY (id), KEY k_1 (k) ) ENGINE=InnoDB DEFAULT CHARSET=latin1 tablespace $db;"
                mysql $db -e "$table"
        done
}
c=0
for m in {1..4000000}
do
        for i in {1..40}
        do
                let c=$c+1
                echo $c
                db="sbtest_$c"
                do_db &
        done
        wait
        #if [ $c > 4000000 ]; then exit; fi
done

2. Run this script:

##### shel script, sysbench_mysql.sh
#####

function run_sb() {
        conn=" --db-driver=mysql --mysql-socket=/var/run/mysqld/mysqld.sock  --mysql-db=mysql --mysql-user=sbtest --mysql-password=abc "
        sysbench $conn --oltp_db_count=$db_count --oltp_tables_count=$table_count --oltp-table-size=10000 --report-interval=1 --num-threads=$num_threads --max-requests=0 --max-time=$max_time ./select_custom.lua run | tee -a sysbench_2.txt
}
let db_count=70000
table_count=1000
max_time=10000
num_threads=32
run_sb

#### select_custom.lua
####

pathtest = "/usr/share/sysbench/tests/include/oltp_legacy/"
if pathtest then
   dofile(pathtest .. "common.lua")
else
   require("common")
end
function thread_init(thread_id)
   set_vars()
end
function event()
   local table_name
   local i
   local c_val
   local k_val
   local pad_val
   oltp_db_count = tonumber(oltp_db_count) or 1
   -- local oltp_db_count = 4
   table_name = "sbtest_" .. sb_rand(100, oltp_db_count)..".sbtest".. sb_rand(1, oltp_tables_count)
   k_val = sb_rand(1, oltp_table_size)
   c_val = sb_rand_str([[
###########-###########-###########-###########-###########-###########-###########-###########-###########-###########]])
   pad_val = sb_rand_str([[
###########-###########-###########-###########-###########]])
      rs = db_query("SELECT id FROM " .. table_name .." LIMIT 1")
end
[27 Oct 2018 15:02] Alexander Rubin
perf top with mysql-debug:

  24.41%  mysqld-debug         [.] _Z23dict_table_add_to_cacheP12dict_table_tmP16mem_block_info_t                                                                                                          
  15.13%  mysqld-debug         [.] _ZNK15CheckInFreeListclEPK10buf_page_t                                                                                                                                  
  12.59%  mysqld-debug         [.] _Z16ut_list_validateI12ut_list_baseI10buf_page_tMS1_12ut_list_nodeIS1_EE15CheckInFreeListEvRKT_RT0_
[17 Aug 2022 8:36] Rajesh Chiniwar
is there any updated on the bug, looks like issue is still present in latest versions of mysql
[18 Nov 2022 15:26] Robert Nix
I encountered this bug in a production percona cluster running 8.0.25-15.
After some investigation using the innodb status output, I came across this
bug and corresponding blog post. With that I was able to create a local
testcase that reproduced the issue fairly reliably, and then I did some
profiling to figure out where the mutex holder thread was spending time.

I left some more details on percona's github at the time:
https://github.com/percona/percona-server/pull/4825

But, since this issue is present in upstream MySQL, I'm bringing it here.
The caveat I have is that I have not yet tried reproducing this with latest
MySQL, but the code I identified as causing the performance regression is
still present in tip.

'LatchCounter uses a std::vector for storing registered counters, which
leads to n^2 behavior during dict_make_room_in_cache; this can hold the
dict_sys->mutex for multiple seconds at a time in the case where a very
large number of innodb tables (200,000+) have been opened since the last
cleaning round.'

The 'n^2 behavior' is during deregistering a LatchCounter associated with
a table, which happens when freeing a table entry:

storage/innobase/include/sync0types.h:700:
    m_mutex.enter();

    m_counters.erase(std::remove(m_counters.begin(), m_counters.end(), count),
                     m_counters.end());

    m_mutex.exit();

My 'fix' at the time was to simply use unordered_set instead; this prevented
the stalls in testing, but it seemed to have some performance impact. My
measurements weren't scientific enough for me to say whether that impact was
significant.
[24 Nov 2022 14:33] Robert Nix
Use unordered_set for LatchCounter storage

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: 0001-Use-unordered_set-for-LatchCounter-storage.patch (text/x-patch), 2.28 KiB.

[24 Nov 2022 15:40] Robert Nix
After further performance testing, I have concluded that the impact of using
vector instead of unordered_set for LatchCounter storage is not significant.

The change to unordered_set reduces the stall duration from ~20s to ~2s in my
test case:

https://robert-nix.github.io/mysql-loadgen/stall-measurement.html

This change does have a visible effect on program behavior:  the order of mutex
instances from the same source location in the output of SHOW ENGINE INNODB
MUTEX is no longer the order of mutex creation and is instead 'randomized' by
the hashmap iteration.

I did try an alternative structure which preserves order and has similar memory
overhead to the hashmap, a boost::intrusive::list, but I think the added
complexity isn't worth the order preservation in this case. From my
observations, in practice, most of these table mutexes have no spins/waits and
so won't show up in the output, and the order of mutex creation is not a useful
signal since no other metadata is printed alongside the latch status.

I have also done some profiling during the new 2 seconds of stall, and I can't
see any other 'easy' ways to reduce the stall duration.