Bug #101799 Sysbench Benchmark (Point Selects) TPS/QPS was 50M,less than expected100M
Submitted: 30 Nov 2020 10:43 Modified: 7 Dec 2020 2:57
Reporter: chao wang Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S5 (Performance)
Version:mysql 5.7.32 OS:CentOS (7.8)
Assigned to: CPU Architecture:Any (AMD 7702)
Tags: other version test

[30 Nov 2020 10:43] chao wang
Description:
set slow_query_log = 0 to turn off slow_query_log. Then I can get more than 150M qps for Sysbench Benchmark (Point Selects). Is there something wrong for the module of slow_query_log? 

At 34s I set slow_query_log = 1,then the qps is form 160M to 50M.
sysbench /usr/share/sysbench/oltp_point_select.lua --db-driver=mysql --mysql-host=192.168.1.20 --mysql-port=3306  --mysql-user=sbtest --mysql-password=sbtest --mysql-db=sbtest --tables=10 --table-size=10000000 --time=300 --report-interval=10 --threads=512 run 
[ 10s ] thds: 512 tps: 1650241.84 qps: 1650241.84 (r/w/o: 1650241.84/0.00/0.00) lat (ms,95%): 1.03 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 512 tps: 1648605.66 qps: 1648605.56 (r/w/o: 1648605.56/0.00/0.00) lat (ms,95%): 1.03 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 512 tps: 1661280.12 qps: 1661280.02 (r/w/o: 1661280.02/0.00/0.00) lat (ms,95%): 1.03 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 512 tps: 1496199.78 qps: 1496199.98 (r/w/o: 1496199.98/0.00/0.00) lat (ms,95%): 1.25 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 512 tps: 553805.47 qps: 553805.37 (r/w/o: 553805.37/0.00/0.00) lat (ms,95%): 1.79 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 512 tps: 549367.49 qps: 549367.49 (r/w/o: 549367.49/0.00/0.00) lat (ms,95%): 1.79 err/s: 0.00 reconn/s: 0.00

when slow_query_log = 1. perf top like this:
Samples: 2M of event 'cycles', 4000 Hz, Event count (approx.): 1515544514770 lost: 0/0 drop: 0/0                                                                                                                                        
Overhead  Shared Object        Symbol                                                                                                                                                                                                   
  60.99%  [kernel]             [k] native_queued_spin_lock_slowpath
  13.67%  libpthread-2.17.so   [.] pthread_mutex_lock
   0.47%  [kernel]             [k] ixgbe_poll
   0.47%  mysqld               [.] btr_search_guess_on_hash

when slow_query_log = 0. perf top like this:
Samples: 3M of event 'cycles', 4000 Hz, Event count (approx.): 1645656939556 lost: 0/0 drop: 0/0                                                                                                                                        
Overhead  Shared Object        Symbol                                                                                                                                                                                                   
   2.64%  [kernel]             [k] ixgbe_poll
   1.93%  mysqld               [.] btr_search_guess_on_hash
   1.87%  mysqld               [.] dispatch_command
   1.52%  mysqld               [.] srv_conc_enter_innodb
   1.10%  [kernel]             [k] ixgbe_xmit_frame_ring

How to repeat:
when sysbench running ,turn off/on for slow_query_log on mysql server.
[30 Nov 2020 10:44] chao wang
add mysql version
[30 Nov 2020 14:46] Mark Callaghan
Hierarchical profiling via perf or PMP would make this easier to debug
[30 Nov 2020 15:15] Justin Swanhart
Marl: slow query log holds a mutex when printing to the log.  This is a known performance problem and is mitigated in non-upstream distributions with slow query log sampling options (log every N sessions or every N queries).  This should probably be a feature request for a better slow query log implementation that doesn't have this known problem.
[1 Dec 2020 2:37] chao wang
perf top

Attachment: perftop.txt (text/plain), 36.26 KiB.

[3 Dec 2020 14:17] MySQL Verification Team
Hi,

I'm having an issue reproducing this on basic test equipment. 
Can you please share
 - your full config
 - your test setup (what hardware you are testing this on)

Also, have you tried this on some previous 5.7 or maybe on a new 8.0.22?

Thanks
[4 Dec 2020 3:16] chao wang
Base Board Information
        Manufacturer: Supermicro
        Product Name: H12DST-B
        
cpu:2 * AMD EPYC 7702 64-Core Processor
mem:256G
disk:3 * Samsung SSD PM983 960GB MZQLB960HAJR-00007 2.5" U.2 NVMe (raid0 of mdadm, mount -t xfs -o defaults,rw,noatime,nodiratime,nobarrier,noikeep,attr2,largeio,inode64,swalloc,allocsize=128M)
[4 Dec 2020 3:35] chao wang
I test on the Percona 5.7.32, there is the same like mysql5.7.32.

[mysqldump]
quick
max_allowed_packet = 1G
default-character-set = utf8

[myisamchk]
key_buffer_size = 512M
sort_buffer_size = 512M
read_buffer = 8M
write_buffer = 8M

[mysql]
no-auto-rehash

[client]
port = 3306
socket              = /data/mysql/mytest/tmp/mysql.sock

[mysqld_safe]
pid_file            = /data/mysql/mytest/tmp/mysqld.pid
log_error           = /data/mysql/mytest/log/log-error.log

[mysqld]
#*** basic settings ***
user = mysql
server_id = 330620
bind_address = 192.168.1.20
port = 3306
report_host  = 192.168.1.20
report_port  = 3306
read_only = 0
basedir             = /usr/local/mysql

datadir             = /data/mysql/mytest/data
tmpdir              = /data/mysql/mytest/tmp
socket              = /data/mysql/mytest/tmp/mysql.sock
pid_file            = /data/mysql/mytest/tmp/mysqld.pid

#*** log path options ***
slow_query_log_file = /data/mysql/mytest/log/mysql-slow.log
general_log_file    = /data/mysql/mytest/log/general.log
log_error           = /data/mysql/mytest/log/log-error.log

#*** binlog path options ***
log_bin             = /data/mysql/mytest/binlog/mysql-bin
log_bin_index       = /data/mysql/mytest/binlog/mysql-bin.index

#*** replication log path Specific options ***
relay_log           = /data/mysql/mytest/relaybin/mysql-relay-bin
relay_log_index     = /data/mysql/mytest/relaybin/mysql-relay-bin.index
relay_log_info_file = /data/mysql/mytest/relaybin/relay-log.info

#*** server Specific options ***
#ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
sql_mode = "STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION"
autocommit = 1
character_set_server = utf8mb4
transaction_isolation = READ-COMMITTED
explicit_defaults_for_timestamp = 1
max_allowed_packet = 64M
event_scheduler = 1
query_cache_type = 0
query_cache_size = 0
show_compatibility_56 = on
log_timestamps = SYSTEM
max_length_for_sort_data = 2048
back_log = 4096
#optimizer_search_depth=0
open_files_limit = 65535
max_prepared_stmt_count = 262144

#*** connection Specific options ***
max_connect_errors = 10000000
max_connections = 100000
interactive_timeout = 1800
wait_timeout = 1800
lock_wait_timeout = 1800
skip_external_locking = 1
skip_name_resolve = 1

#*** session thread memory settings ***
read_buffer_size = 8M
read_rnd_buffer_size = 4M
sort_buffer_size = 8M
join_buffer_size = 128M
bulk_insert_buffer_size = 32M

#*** session thread Specific options ***
thread_cache_size=512
thread_handling = one-thread-per-connection 

#*** session tmp_table Specific options ***
max_tmp_tables = 128
tmp_table_size = 128M
max_heap_table_size = 128M

#*** Slow log Specific options ***
slow_query_log = 1
long_query_time = 0.1
log_slow_admin_statements = 1
log_slow_slave_statements = 1
log_queries_not_using_indexes = 1
log_throttle_queries_not_using_indexes = 10
min_examined_row_limit = 100

#*** Binlog Specific options ***
expire_logs_days = 7
sync_binlog = 1
gtid_mode = ON
enforce_gtid_consistency = ON
binlog_gtid_simple_recovery = 1

binlog_format = ROW
binlog_rows_query_log_events = 1
log_bin_trust_function_creators = 1

binlog_cache_size = 8M
binlog_stmt_cache_size = 8M
max_binlog_cache_size = 4G
max_binlog_size = 1G

transaction_write_set_extraction = XXHASH64
binlog_transaction_dependency_history_size = 100000
binlog_transaction_dependency_tracking = WRITESET

#binlog_group_commit_sync_delay = 10000
#binlog_group_commit_sync_no_delay_count = 32

#*** Replication Specific options ***
skip-slave-start = 1
log_slave_updates = 1
relay_log_recovery = 1

relay_log_info_repository = TABLE
master_info_repository    = TABLE

slave_pending_jobs_size_max = 32M
slave_parallel_type = LOGICAL_CLOCK
slave_parallel_workers = 16
slave_preserve_commit_order = 1
slave_transaction_retries = 128

#all,1032,1062,1213
slave_skip_errors = ddl_exist_errors
slave_rows_search_algorithms = 'INDEX_SCAN,HASH_SCAN'

#*** table cache Specific options ***
table_open_cache = 81920
table_definition_cache = 8192
table_open_cache_instances = 128
metadata_locks_hash_instances = 128

#*** perforamnce_schema settings ***
performance-schema-instrument='memory/%=COUNTED'
performance_schema_digests_size = 40000
performance_schema_max_table_instances = 40000
performance_schema_max_sql_text_length = 4096
performance_schema_max_digest_length = 4096

#*** INNODB Specific options ***
loose-innodb_numa_interleave = 1
default_storage_engine = InnoDB
default_tmp_storage_engine = InnoDB
innodb_adaptive_flushing = 1
innodb_adaptive_hash_index = 1
innodb_adaptive_hash_index_parts = 64
innodb_autoinc_lock_mode = 2
innodb_buffer_pool_dump_at_shutdown = 0
innodb_buffer_pool_instances = 64
innodb_buffer_pool_load_at_startup = 0
innodb_buffer_pool_size = 160G
innodb_change_buffer_max_size = 5
innodb_change_buffering = all
innodb_checksum_algorithm = crc32
innodb_deadlock_detect = 1
innodb_doublewrite = 1
innodb_fast_shutdown = 0
innodb_file_per_table = 1
innodb_flush_log_at_timeout = 1
innodb_flush_log_at_trx_commit = 1
innodb_flush_method = O_DIRECT
innodb_flush_neighbors = 0
innodb_io_capacity = 30000
innodb_io_capacity_max = 40000
innodb_large_prefix = 1
innodb_lock_wait_timeout = 10
innodb_locks_unsafe_for_binlog = 0
innodb_log_buffer_size = 32M
innodb_log_file_size = 16G
innodb_log_files_in_group = 2
innodb_lru_scan_depth = 4096
innodb_max_dirty_pages_pct = 75
innodb_max_undo_log_size = 2G
innodb_online_alter_log_max_size = 1G
innodb_open_files = 65535
innodb_page_cleaners = 64
innodb_page_size = 16384
innodb_print_all_deadlocks = 1
innodb_purge_batch_size = 600
innodb_purge_threads = 8
innodb_read_ahead_threshold = 32
innodb_read_io_threads = 16
innodb_sort_buffer_size = 64M
innodb_spin_wait_delay = 6
innodb_stats_on_metadata = 0
innodb_stats_auto_recalc = 1
innodb_stats_persistent = 1
innodb_stats_persistent_sample_pages = 64
innodb_strict_mode = 1
innodb_support_xa = 1
innodb_sync_array_size = 16
innodb_sync_spin_loops = 10
innodb_thread_concurrency = 128
innodb_undo_log_truncate = 1
innodb_undo_logs = 128
innodb_undo_tablespaces = 3
innodb_use_native_aio = 1
innodb_write_io_threads = 16

#*** MyISAM Specific options ***
key_buffer_size = 128M
myisam_sort_buffer_size = 64M
myisam_max_sort_file_size = 8G
concurrent_insert = 2
max_write_lock_count = 1
delay_key_write = 0
myisam_recover_options = FORCE,BACKUP
[4 Dec 2020 4:55] chao wang
I tested 5.7.31 and 8.0.22. And there is the same like 5.7.32.

8.0.22 like this:set slow_query_log= 1 -> 0 ->1
[ 10s ] thds: 512 tps: 553348.07 qps: 553348.07 (r/w/o: 553348.07/0.00/0.00) lat (ms,95%): 3.07 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 512 tps: 521583.18 qps: 521583.18 (r/w/o: 521583.18/0.00/0.00) lat (ms,95%): 3.19 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 512 tps: 622638.34 qps: 622638.44 (r/w/o: 622638.44/0.00/0.00) lat (ms,95%): 2.76 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 512 tps: 1283391.96 qps: 1283391.96 (r/w/o: 1283391.96/0.00/0.00) lat (ms,95%): 1.14 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 512 tps: 1292753.20 qps: 1292753.00 (r/w/o: 1292753.00/0.00/0.00) lat (ms,95%): 1.14 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 512 tps: 1298065.05 qps: 1298064.85 (r/w/o: 1298064.85/0.00/0.00) lat (ms,95%): 1.14 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 512 tps: 1296934.40 qps: 1296934.70 (r/w/o: 1296934.70/0.00/0.00) lat (ms,95%): 1.14 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 512 tps: 1178207.11 qps: 1178206.91 (r/w/o: 1178206.91/0.00/0.00) lat (ms,95%): 1.27 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 512 tps: 505154.62 qps: 505154.82 (r/w/o: 505154.82/0.00/0.00) lat (ms,95%): 3.19 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 512 tps: 504718.20 qps: 504718.20 (r/w/o: 504718.20/0.00/0.00) lat (ms,95%): 3.19 err/s: 0.00 reconn/s: 0.00
[4 Dec 2020 12:38] MySQL Verification Team
Hi,

Thanks for the additional info.

all best
Bogdan
[4 Dec 2020 16:26] MySQL Verification Team
Hi,

We reproduced the problem.

I will note that your system is a bit "over configured" and we suggest you modify that, maybe contact our supported team to help you properly configure that box. 

Only with your configuration we can reproduce the problem.

We will continue to see what exactly from your configuration is causing the problem and fix the issue. Thanks for the report

all best
Bogdan
[4 Dec 2020 23:34] MySQL Verification Team
Hi,

Until the bug is being fixed we suggest you remove

- log-throttle-queries-not-using-indexes

From your config.

Here is the simple config that is not hit by this bug and that produces higher TPS/QPS than your config by a lot.

kind regards
Bogdan

[mysqld]
back_log=0
character-set-client-handshake=FALSE
disable-log-bin
max_connections=1200
max_prepared_stmt_count=100000
log_error_verbosity=3
loose-local-infile=1
port=3306
secure_file_priv=""
thread_cache_size=1200

performance_schema=ON
innodb_monitor_enable='%'

innodb_buffer_pool_instances=16
innodb_buffer_pool_size=128G
innodb-change-buffering=none
innodb_io_capacity_max=12000
innodb_io_capacity=10000
innodb_log_files_in_group=16
innodb_log_file_size=1G
innodb_numa_interleave=ON
innodb_page_cleaners=16
innodb_read_io_threads=16
innodb_write_io_threads=4
innodb_undo_log_truncate=OFF
range_alloc_block_size=16384
[7 Dec 2020 2:57] chao wang
Hi  thanks for your suggestion。
I test the variable log_throttle_queries_not_using_indexes set to 0, mysql can avoid this bug。

If log_queries_not_using_indexes =0 and log_throttle_queries_not_using_indexes =(not 0),mysql also hit this bug.
[4 Jun 9:23] Demon Chen
Hi,

I also meet this problem. When I test mysql-8.0.20 against mysql-5.7.28 using sysbench with 512/1024 threads. I found mysql-8.0.20 use more cpu on native_queued_spin_lock_slowpath. And mysql 5.7.28 has 45k tps agianst mysql-8.0.20 3w tps. I also tried to stop slow query and the bias still existed.
[4 Jun 9:25] Demon Chen
perf snapshot:mysql-8.0.20

Attachment: 8.0.png (image/png, text), 393.11 KiB.

[4 Jun 9:25] Demon Chen
perf snapshot:mysql-8.0.20

Attachment: 8.0.png (image/png, text), 393.11 KiB.

[4 Jun 9:26] Demon Chen
perf snapshot:mysql-5.7.28

Attachment: 5.7.png (image/png, text), 362.96 KiB.