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.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.042 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.