Bug #92274 Question of mysql 8.0 sysbench oltp_point_select test
Submitted: 3 Sep 2018 13:03 Modified: 15 Jun 2020 12:22
Reporter: victor zheng Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server Severity:S7 (Test Cases)
Version:8.0.12 OS:Debian (8)
Assigned to: Dimitri Kravtchuk CPU Architecture:x86 (40 core)

[3 Sep 2018 13:03] victor zheng
Description:
1. install
(mysql-8.0.12.tar.gz)	MD5: 569b6037bad533ad84c2b8d29534a68f

also install  mysql 5.7.12 in the same environment.

2.server env
40 core
96g ram
1.1 T sas 
buffer pool=32g

3. test
sysbench 1.0.10, 10 tables, 1kw each table ,128 thread, oltp_point_select

test result: 
5.7-->52 w qps
8.0 -->15w qps

4.static

5.7 use  cpu 90%=70%(usr)+20%(system)
8.0  use cpu 90%=55%(usr)+35%(system)

and show engine innodb status for mysql 8.0

How to repeat:
just start sysbench
7. use perf to get info of cpu

amples: 4M of event 'cycles', Event count (approx.): 2511371372515
  51.40%           mysqld  [kernel.kallsyms]            [k] _raw_spin_lock
   1.17%           mysqld  [kernel.kallsyms]            [k] futex_wait_setup
   0.79%           mysqld  libcrypto.so.1.0.0           [.] 0x00000000000fd450
   0.68%           mysqld  libpthread-2.19.so           [.] pthread_rwlock_wrlock
   0.54%           mysqld  [kernel.kallsyms]            [k] futex_wake
   0.52%          swapper  [kernel.kallsyms]            [k] mwait_idle
   0.44%           mysqld  mysqld                       [.] btr_search_guess_on_hash(d
   0.37%           mysqld  libcrypto.so.1.0.0           [.] 0x00000000000fd465
   0.35%           mysqld  mysqld                       [.] row_search_mvcc(unsigned c
   0.34%           mysqld  mysqld                       [.] open_table(THD*, TABLE_LIS
   0.30%           mysqld  mysqld                       [.] JOIN::optimize()
   0.29%           mysqld  libpthread-2.19.so           [.] pthread_rwlock_unlock
   0.29%           mysqld  [kernel.kallsyms]            [k] ixgbe_poll
   0.27%           mysqld  [kernel.kallsyms]            [k] get_futex_value_locked
   0.26%           mysqld  mysqld                       [.] dispatch_command(THD*, COM
   0.26%           mysqld  [kernel.kallsyms]            [k] idle_cpu
   0.24%           mysqld  mysqld                       [.] openssl_lock(int, CRYPTO_d
   0.24%           mysqld  libpthread-2.19.so           [.] pthread_mutex_lock
   0.22%           mysqld  libc-2.19.so                 [.] malloc
   0.22%           mysqld  mysqld                       [.] JOIN::make_join_plan()
   0.22%           mysqld  [kernel.kallsyms]            [k] __unqueue_futex
   0.21%           mysqld  libpthread-2.19.so           [.] __pthread_mutex_unlock_use
   0.20%           mysqld  mysqld                       [.] create_metadata_lock(void*
   0.20%           mysqld  libc-2.19.so                 [.] memset
   0.20%           mysqld  [kernel.kallsyms]            [k] __switch_to
   0.19%           mysqld  mysqld                       [.] pfs_start_stage_v1(unsigne
   0.19%           mysqld  [kernel.kallsyms]            [k] __schedule
   0.19%           mysqld  mysqld                       [.] pfs_end_statement_v1(PSI_s
   0.18%           mysqld  libc-2.19.so                 [.] vfprintf
   0.18%           mysqld  [kernel.kallsyms]            [k] tcp_packet
   0.18%           mysqld  [kernel.kallsyms]            [k] tcp_recvmsg
   0.18%           mysqld  [kernel.kallsyms]            [k] __nf_conntrack_find_get
   0.17%           mysqld  [kernel.kallsyms]            [k] ixgbe_xmit_frame_ring
   0.17%           mysqld  [kernel.kallsyms]            [k] get_futex_key_refs.isra.13
   0.17%           mysqld  [kernel.kallsyms]            [k] irq_entries_start
   0.17%           mysqld  mysqld                       [.] THD::enter_stage(PSI_stage
   0.16%           mysqld  [kernel.kallsyms]            [k] tcp_ack
   0.16%           mysqld  mysqld                       [.] btr_cur_search_to_nth_leve
   0.15%           mysqld  [kernel.kallsyms]            [k] _raw_spin_lock_irqsave
   0.15%           mysqld  mysqld                       [.] lock_table_names(THD*, TAB

Suggested fix:
i don't why
[3 Sep 2018 13:05] victor zheng
show engine innodb status ouput

Attachment: show_engine_innodb_status.txt (text/plain), 10.67 KiB.

[3 Sep 2018 14:06] victor zheng
in my opnion,  the sephores in `show engine innodb status' is strange.

file read io and buffer pool read/s
[4 Nov 2018 16:52] Mark Callaghan
Can you add PMP output to show the thread stacks when the mutex contention occurs with 8.0?

https://poormansprofiler.org/
[6 Nov 2018 8:14] victor zheng
16 pthread_cond_wait@@GLIBC_2.3.2,native_cond_wait,<Per_thread_connection_handler::LOCK_thread_cache>,,<Per_thread_connection_handler::LOCK_thread_cache>,,at,handle_connection,pfs_spawn_thread,start_thread,clone
      7 ??,??,??,free_root,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      6 ??,??,??,my_realloc,String::mem_realloc,String::replace,String::replace,Prepared_statement::insert_params,Prepared_statement::set_parameters,Prepared_statement::execute_loop,mysqld_stmt_execute,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      6 ??,??,??,mem_free,__in_chrg=<optimized,stmt_id=<optimized,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      6 ??,??,??,free_root,Prepared_statement::~Prepared_statement,Prepared_statement::~Prepared_statement,my_hash_delete,Prepared_statement_map::erase,Prepared_statement::deallocate,mysqld_stmt_close,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      5 ??,??,malloc,my_raw_malloc,size=size@entry=8160,,alloc_root,Item::operator,MYSQLparse,parse_sql,Prepared_statement::prepare,mysqld_stmt_prepare,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      4 ??,??,malloc,my_raw_malloc,size=size@entry=8208,,init_alloc_root,init_sql_alloc,Prepared_statement::Prepared_statement,mysqld_stmt_prepare,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      3 pthread_cond_wait@@GLIBC_2.3.2,wait,out>,,reset_sig_count=reset_sig_count@entry=0),srv_worker_thread,start_thread,clone
      3 pthread_cond_wait@@GLIBC_2.3.2,wait,out>,,reset_sig_count=reset_sig_count@entry=0),buf_flush_page_cleaner_worker,start_thread,clone
      3 ??,??,malloc,operator,mysqld_stmt_prepare,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      2 ??,??,malloc,my_raw_malloc,size=32,,get_lock_data,mysql_unlock_some_tables,JOIN::optimize,st_select_lex::optimize,handle_query,execute_sqlcom_select,mysql_execute_command,Prepared_statement::execute,Prepared_statement::execute_loop,mysqld_stmt_execute,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      1 st_select_lex::prepare,st_select_lex_unit::prepare,mysql_test_select,at,query_str=query_str@entry=0x7fb4b1b9c761,mysqld_stmt_prepare,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      1 str=0x7fb72f5531f0),Item::send,THD::send_result_set_row,Query_result_send::send_data,end_send,do_select,at,handle_query,execute_sqlcom_select,mysql_execute_command,Prepared_statement::execute,Prepared_statement::execute_loop,mysqld_stmt_execute,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread,clone
      1 ??,sigwaitinfo,timer_notify_thread_func,pfs_spawn_thread,start_thread,clone
[6 Nov 2018 17:24] Mark Callaghan
That shows most threads doing some sort of malloc/free/realloc and nothing in InnoDB.
Regardless, I appreciate all of the details you provided in this report.
[21 Nov 2019 16:21] Dimitri Kravtchuk
I afraid the problem is common with other issues you logged here before, but which were finally related to SSL config..

so, to clarify this all, may you, please :

1) replay the same, but with ssl=0 on both sides ?
2) if the problem is still here, then which malloc lib do you use ? may you replay with jemalloc ?
3) if even after that the problem is still here, may you try to find who is involving this _raw_spin_lock ? ("perf record -g -a" will collect all the needed stacks)

side note: are your threads reconnecting after each point-select query, or connections are remaining persistent ?

Rgds,
-Dimitri
[15 Jun 2020 12:22] MySQL Verification Team
We can't repeat it with latest 8.0.21.