| 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: | |
| 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
[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 2021 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 2021 9:25]
Demon Chen
perf snapshot:mysql-8.0.20
Attachment: 8.0.png (image/png, text), 393.11 KiB.
