MySQL:kill和show命令hang住一列

gaopengtttt發表於2018-10-08

這個問題是一個朋友發給我的@mj環境如下:
MySQL 5.6.25
show processlist和pstack日誌做了大量的刪減,否則篇幅過大

一、問題描述

問題描述是這位朋友發給我的如下:

  • 問題描述
    收到從庫xx.xx.xx.xx報警mysql當機,實際上mysql沒有當機,而是因為下面這條SQL向表tmp_mds_cust_dealer_advisor_rela01插入的資料太多(這個表的資料檔案高達184G,binlog檔案binlog.001675高達138G).在binlog最終刷到磁碟的期間導致 SHOW GLOBAL STATUS 等命令阻塞。觀察了當時的cpu,記憶體,磁碟情況,壓力都不大。為什麼刷binlog到磁碟會阻塞 SHOW GLOBAL STATUS 等命令 ?

  • show processlist如下:

dbadmin@(none) 08:49:50>show processlist;
+---------+-------------+-----------------+--------------------+---------+-------+----------------------------------+------------------------------------------------------------------------------------------------------+-----------+---------------+
| Id      | User        | Host            | db                 | Command | Time  | State                            | Info                                                                                                 | Rows_sent | Rows_examined |
+---------+-------------+-----------------+--------------------+---------+-------+----------------------------------+------------------------------------------------------------------------------------------------------+-----------+---------------+
|  862489 | dbadmin     | 127.0.0.1:41012 | NULL               | Killed  |   413 | executing                        | SHOW GLOBAL STATUS LIKE 'uptime'                                                                     |         0 |             0 |
|  862490 | dbadmin     | 127.0.0.1:41014 | information_schema | Killed  |   902 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
|  862491 | dbadmin     | 127.0.0.1:41015 | information_schema | Killed  |   902 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
|  862493 | dbadmin     | 127.0.0.1:41019 | information_schema | Killed  |   165 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
|  862495 | dbadmin     | 127.0.0.1:41022 | information_schema | Killed  |  1149 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
|  862508 | monitor     | 127.0.0.1:41041 | mysql              | Killed  |   411 | executing                        | show global status
            where Variable_name in
            (                'Threads_connect |         0 |             0 |
| 1140925 | monitor     | 127.0.0.1:64924 | mysql              | Query   |   414 | executing                        | show global status 
    where Variable_name in 
    ('Com_select','Com_insert','Com_update','Com_del |         0 |             0 |
| 1153172 | system user |                 | NULL               | Connect | 82688 | Waiting for master to send event | NULL                                                                                                 |         0 |             0 |
| 1153173 | system user |                 | NULL               | Connect | 55564 | System lock                      | NULL                                                                                                 |         0 |             0 |
| 1168129 | dbadmin     | 127.0.0.1:9377  | information_schema | Killed  |   123 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181458 | dbadmin     | 127.0.0.1:11163 | NULL               | Killed  |   413 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181459 | dbadmin     | 127.0.0.1:11164 | NULL               | Killed  |   406 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181460 | dbadmin     | 127.0.0.1:11166 | NULL               | Killed  |   396 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181461 | dbadmin     | 127.0.0.1:11177 | NULL               | Killed  |   393 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181462 | dbmonitor   | 127.0.0.1:11226 | NULL               | Query   |   387 | executing                        | SHOW /*!50001 GLOBAL */ STATUS                                                                       |         0 |             0 |
| 1181463 | dbadmin     | 127.0.0.1:11242 | NULL               | Killed  |   386 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181464 | dbadmin     | 127.0.0.1:11328 | NULL               | Killed  |   376 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181465 | dbadmin     | 127.0.0.1:11408 | NULL               | Killed  |   366 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181466 | dbadmin     | 127.0.0.1:11436 | NULL               | Killed  |   363 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181467 | dbadmin     | 127.0.0.1:11465 | NULL               | Killed  |   356 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181468 | dbadmin     | 127.0.0.1:11467 | NULL               | Killed  |   346 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181469 | dbadmin     | 127.0.0.1:11469 | NULL               | Killed  |   336 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181470 | dbmonitor   | 127.0.0.1:11471 | NULL               | Query   |   327 | executing                        | SHOW /*!50001 GLOBAL */ STATUS                                                                       |         0 |             0 |
| 1181471 | dbadmin     | 127.0.0.1:11477 | NULL               | Killed  |   326 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181472 | dbadmin     | 127.0.0.1:11478 | NULL               | Killed  |   321 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181473 | dbadmin     | 127.0.0.1:11481 | NULL               | Killed  |   316 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181474 | dbadmin     | 127.0.0.1:11483 | NULL               | Killed  |   306 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181475 | dbadmin     | 127.0.0.1:11484 | NULL               | Killed  |   303 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181476 | dbadmin     | 127.0.0.1:11485 | NULL               | Killed  |   296 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181477 | dbadmin     | 127.0.0.1:11557 | NULL               | Killed  |   286 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181478 | dbadmin     | 127.0.0.1:11640 | NULL               | Killed  |   276 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181479 | dbmonitor   | 127.0.0.1:11711 | NULL               | Query   |   267 | executing                        | SHOW /*!50001 GLOBAL */ STATUS                                                                       |         0 |             0 |
| 1181480 | dbadmin     | 127.0.0.1:11730 | NULL               | Killed  |   266 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181481 | dbadmin     | 127.0.0.1:11783 | NULL               | Killed  |   256 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181482 | dbadmin     | 127.0.0.1:11784 | NULL               | Killed  |   249 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181483 | dbadmin     | 127.0.0.1:11785 | NULL               | Killed  |   246 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181484 | dbadmin     | 127.0.0.1:11786 | NULL               | Killed  |   243 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181485 | dbadmin     | 127.0.0.1:11788 | NULL               | Killed  |   236 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181486 | dbadmin     | 127.0.0.1:11792 | NULL               | Killed  |   226 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
| 1181487 | dbadmin     | localhost       | NULL               | Killed  |   218 | cleaning up                      | NULL                                                                                                 |         0 |             0 |
....
+---------+-------------+-----------------+--------------------+---------+-------+----------------------------------+------------------------------------------------------------------------------------------------------+-----------+---------------+75 rows in set (0.01 sec)
  • pstack
    這位朋友給出了pstack 實際上是最有用的。

.....
Thread 112 (Thread 0x7f75ef237700 (LWP 82013)):#0  0x00007f769d10425d in read () from /lib64/libpthread.so.0#1  0x00000000008f12ba in read (__nbytes=5242880, __buf=0x7f5565800000, __fd=181) at /usr/include/bits/unistd.h:45#2  my_read (Filedes=181, Buffer=0x7f5565800000 "\224\200錦224\234\215錦212℃\234\211閈231\220錦205\217竆b", Count=5242880, MyFlags=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/mysys/my_read.c:50#3  0x00000000008dbd7d in my_b_fill (info=0x7f556546cb80) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/mysys/mf_iocache2.c:226#4  0x000000000089cba9 in MYSQL_BIN_LOG::do_write_cache (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=thd@entry=0x7f55764d6000, cache=cache@entry=0x7f556546cb80) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:6005#5  0x00000000008a5f7b in MYSQL_BIN_LOG::write_cache (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=thd@entry=0x7f55764d6000, cache_data=cache_data@entry=0x7f556546cb78) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:6144#6  0x00000000008a6282 in binlog_cache_data::flush (this=0x7f556546cb78, thd=0x7f55764d6000, bytes_written=0x7f75ef2349e0, wrote_xid=0x7f75ef2349c0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:1261#7  0x00000000008a6336 in flush (wrote_xid=0x7f75ef2349c0, bytes_written=<synthetic pointer>, thd=0x7f55764d6000, this=0x7f556546ca00) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:778#8  MYSQL_BIN_LOG::flush_thread_caches (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=thd@entry=0x7f55764d6000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:6779#9  0x00000000008a6469 in MYSQL_BIN_LOG::process_flush_stage_queue (this=this@entry=0x135e6c0 <mysql_bin_log>, total_bytes_var=total_bytes_var@entry=0x7f75ef234ad0, rotate_var=rotate_var@entry=0x7f75ef234ab0, out_queue_var=out_queue_var@entry=0x7f75ef234ae0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:6835#10 0x00000000008a674c in MYSQL_BIN_LOG::ordered_commit (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=thd@entry=0x7f55764d6000, all=all@entry=true, skip_commit=skip_commit@entry=false) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:7265#11 0x00000000008a7284 in MYSQL_BIN_LOG::commit (this=0x135e6c0 <mysql_bin_log>, thd=0x7f55764d6000, all=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:6738#12 0x00000000005bfa07 in ha_commit_trans (thd=thd@entry=0x7f55764d6000, all=all@entry=true, ignore_global_read_lock=ignore_global_read_lock@entry=false) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/handler.cc:1513#13 0x000000000078722e in trans_commit (thd=thd@entry=0x7f55764d6000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/transaction.cc:230#14 0x0000000000888242 in Xid_log_event::do_commit (this=this@entry=0x7f557591d380, thd=0x7f55764d6000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/log_event.cc:7420#15 0x0000000000888670 in Xid_log_event::do_apply_event (this=0x7f557591d380, rli=0x7f555da1a000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/log_event.cc:7632#16 0x000000000088425a in Log_event::apply_event (this=this@entry=0x7f557591d380, rli=rli@entry=0x7f555da1a000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/log_event.cc:3057#17 0x00000000008bb52e in apply_event_and_update_pos (ptr_ev=ptr_ev@entry=0x7f75ef236860, thd=thd@entry=0x7f55764d6000, rli=rli@entry=0x7f555da1a000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/rpl_slave.cc:3818#18 0x00000000008befbb in exec_relay_log_event (rli=0x7f555da1a000, thd=0x7f55764d6000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/rpl_slave.cc:4315#19 handle_slave_sql (arg=arg@entry=0x7f555da14000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/rpl_slave.cc:6206#20 0x0000000000b050e3 in pfs_spawn_thread (arg=0x7f557009e0c0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/storage/perfschema/pfs.cc:1860#21 0x00007f769d0fddf3 in start_thread () from /lib64/libpthread.so.0#22 0x00007f769b7713dd in clone () from /lib64/libc.so.6...
Thread 80 (Thread 0x7f553916a700 (LWP 1306)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd41 in _L_lock_790 () from /lib64/libpthread.so.0#2  0x00007f769d0ffc47 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x00000000008a0014 in inline_mysql_mutex_lock (src_file=0xc31a00 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc", src_line=7536, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  MYSQL_BIN_LOG::set_status_variables (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:7536#5  0x00000000008a007b in show_binlog_vars (thd=<optimized out>, var=0x7f5539166c70, buff=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:9476#6  0x00000000007375ff in show_status_array (thd=thd@entry=0x7f5573c2c000, wild=wild@entry=0x0, variables=0x7f75f43f9030, value_type=value_type@entry=OPT_GLOBAL, status_var=0x7f55391671b0, prefix=prefix@entry=0xc2ce39 "", table=0x7f556345d010, ucase_names=false, cond=cond@entry=0x7f55636380d0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:2635#7  0x0000000000737f69 in fill_status (thd=thd@entry=0x7f5573c2c000, tables=tables@entry=0x7f5563638578, cond=0x7f55636380d0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7321#8  0x000000000073e692 in do_fill_table (join_table=0x7f5563636610, table_list=0x7f5563638578, thd=0x7f5573c2c000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7986#9  get_schema_tables_result (join=join@entry=0x7f5563638ed8, executed_place=executed_place@entry=PROCESSED_BY_JOIN_EXEC) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:8087#10 0x000000000071f425 in JOIN::prepare_result (this=this@entry=0x7f5563638ed8, columns_list=columns_list@entry=0x7f5539167960) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:823#11 0x00000000006d9e7c in JOIN::exec (this=0x7f5563638ed8) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_executor.cc:116#12 0x0000000000723c05 in mysql_execute_select (free_join=true, select_lex=0x7f5573c2e880, thd=0x7f5573c2c000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:1100#13 mysql_select (thd=thd@entry=0x7f5573c2c000, tables=0x7f5563638578, wild_num=0, fields=..., conds=0x7f55636380d0, order=order@entry=0x7f5573c2ea48, group=group@entry=0x7f5573c2e980, having=0x0, select_options=2684619520, result=result@entry=0x7f5563638eb0, unit=unit@entry=0x7f5573c2e238, select_lex=select_lex@entry=0x7f5573c2e880) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:1221#14 0x0000000000724465 in handle_select (thd=thd@entry=0x7f5573c2c000, result=result@entry=0x7f5563638eb0, setup_tables_done_option=setup_tables_done_option@entry=0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:110#15 0x0000000000581a38 in execute_sqlcom_select (thd=thd@entry=0x7f5573c2c000, all_tables=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:5665#16 0x00000000006fd731 in mysql_execute_command (thd=thd@entry=0x7f5573c2c000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:2952#17 0x0000000000702c98 in mysql_parse (thd=thd@entry=0x7f5573c2c000, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f5539169020) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:6950#18 0x00000000007044ab in dispatch_command (command=<optimized out>, thd=thd@entry=0x7f5573c2c000, packet=<optimized out>, packet_length=739) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:1442#19 0x0000000000706219 in do_command (thd=thd@entry=0x7f5573c2c000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:1054#20 0x000000000078f368 in threadpool_process_request (thd=0x7f5573c2c000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_common.cc:311#21 0x000000000079033d in handle_event (connection=0x7f5573b5b880) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1553#22 worker_main (param=param@entry=0x1351e00 <all_groups+14848>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1606#23 0x0000000000b050e3 in pfs_spawn_thread (arg=0x7f555d6f7ce0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/storage/perfschema/pfs.cc:1860#24 0x00007f769d0fddf3 in start_thread () from /lib64/libpthread.so.0#25 0x00007f769b7713dd in clone () from /lib64/libc.so.6.....
Thread 55 (Thread 0x7f55318b2700 (LWP 2821)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd77 in _L_lock_974 () from /lib64/libpthread.so.0#2  0x00007f769d0ffd20 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x00000000006cde10 in inline_mysql_mutex_lock (src_file=0xbc9938 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc", src_line=1760, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  THD::release_resources (this=this@entry=0x7f557629d000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc:1760#5  0x000000000078f1e7 in threadpool_remove_connection (thd=0x7f557629d000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_common.cc:257#6  0x00000000007902b6 in connection_abort (connection=0x7f556fea9610) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1363#7  handle_event (connection=0x7f556fea9610) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1564#8  worker_main (param=param@entry=0x134f400 <all_groups+4096>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1606#9  0x0000000000b050e3 in pfs_spawn_thread (arg=0x7f555d6f7600) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/storage/perfschema/pfs.cc:1860#10 0x00007f769d0fddf3 in start_thread () from /lib64/libpthread.so.0#11 0x00007f769b7713dd in clone () from /lib64/libc.so.6Thread 54 (Thread 0x7f553898b700 (LWP 2962)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd77 in _L_lock_974 () from /lib64/libpthread.so.0#2  0x00007f769d0ffd20 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x00000000006cde10 in inline_mysql_mutex_lock (src_file=0xbc9938 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc", src_line=1760, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  THD::release_resources (this=this@entry=0x7f557469c000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc:1760#5  0x000000000078f1e7 in threadpool_remove_connection (thd=0x7f557469c000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_common.cc:257#6  0x00000000007902b6 in connection_abort (connection=0x7f556fea9760) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1363#7  handle_event (connection=0x7f556fea9760) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1564#8  worker_main (param=param@entry=0x134f600 <all_groups+4608>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1606#9  0x0000000000b050e3 in pfs_spawn_thread (arg=0x7f555d6f76a0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/storage/perfschema/pfs.cc:1860#10 0x00007f769d0fddf3 in start_thread () from /lib64/libpthread.so.0#11 0x00007f769b7713dd in clone () from /lib64/libc.so.6....
Thread 50 (Thread 0x7f55337ff700 (LWP 3002)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd77 in _L_lock_974 () from /lib64/libpthread.so.0#2  0x00007f769d0ffd20 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x0000000000738116 in inline_mysql_mutex_lock (src_file=0xbd31e8 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc", src_line=7315, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  fill_status (thd=thd@entry=0x7f5576042000, tables=tables@entry=0x7f55d2c1d358, cond=0x0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7315#5  0x000000000073e692 in do_fill_table (join_table=0x7f55d2c1e9e0, table_list=0x7f55d2c1d358, thd=0x7f5576042000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7986#6  get_schema_tables_result (join=join@entry=0x7f55d2c1dcb8, executed_place=executed_place@entry=PROCESSED_BY_JOIN_EXEC) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:8087#7  0x000000000071f425 in JOIN::prepare_result (this=this@entry=0x7f55d2c1dcb8, columns_list=columns_list@entry=0x7f55337fc960) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:823#8  0x00000000006d9e7c in JOIN::exec (this=0x7f55d2c1dcb8) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_executor.cc:116#9  0x0000000000723c05 in mysql_execute_select (free_join=true, select_lex=0x7f5576044880, thd=0x7f5576042000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:1100#10 mysql_select (thd=thd@entry=0x7f5576042000, tables=0x7f55d2c1d358, wild_num=0, fields=..., conds=0x0, order=order@entry=0x7f5576044a48, group=group@entry=0x7f5576044980, having=0x0, select_options=2684652288, result=result@entry=0x7f55d2c1dc90, unit=unit@entry=0x7f5576044238, select_lex=select_lex@entry=0x7f5576044880) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:1221#11 0x0000000000724465 in handle_select (thd=thd@entry=0x7f5576042000, result=result@entry=0x7f55d2c1dc90, setup_tables_done_option=setup_tables_done_option@entry=0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:110#12 0x0000000000581a38 in execute_sqlcom_select (thd=thd@entry=0x7f5576042000, all_tables=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:5665#13 0x00000000006fd731 in mysql_execute_command (thd=thd@entry=0x7f5576042000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:2952#14 0x0000000000702c98 in mysql_parse (thd=thd@entry=0x7f5576042000, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f55337fe020) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:6950#15 0x00000000007044ab in dispatch_command (command=<optimized out>, thd=thd@entry=0x7f5576042000, packet=<optimized out>, packet_length=30) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:1442#16 0x0000000000706219 in do_command (thd=thd@entry=0x7f5576042000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:1054#17 0x000000000078f368 in threadpool_process_request (thd=0x7f5576042000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_common.cc:311#18 0x000000000079033d in handle_event (connection=0x7f556fea9ca0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1553#19 worker_main (param=param@entry=0x134fc00 <all_groups+6144>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1606#20 0x0000000000b050e3 in pfs_spawn_thread (arg=0x7f555e413e80) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/storage/perfschema/pfs.cc:1860#21 0x00007f769d0fddf3 in start_thread () from /lib64/libpthread.so.0#22 0x00007f769b7713dd in clone () from /lib64/libc.so.6.....
Thread 46 (Thread 0x7f5531a79700 (LWP 3181)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd77 in _L_lock_974 () from /lib64/libpthread.so.0#2  0x00007f769d0ffd20 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x0000000000738116 in inline_mysql_mutex_lock (src_file=0xbd31e8 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc", src_line=7315, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  fill_status (thd=thd@entry=0x7f55761e9000, tables=tables@entry=0x7f55d441d358, cond=0x0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7315#5  0x000000000073e692 in do_fill_table (join_table=0x7f55d441e9e0, table_list=0x7f55d441d358, thd=0x7f55761e9000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7986#6  get_schema_tables_result (join=join@entry=0x7f55d441dcb8, executed_place=executed_place@entry=PROCESSED_BY_JOIN_EXEC) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:8087#7  0x000000000071f425 in JOIN::prepare_result (this=this@entry=0x7f55d441dcb8, columns_list=columns_list@entry=0x7f5531a76960) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:823#8  0x00000000006d9e7c in JOIN::exec (this=0x7f55d441dcb8) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_executor.cc:116#9  0x0000000000723c05 in mysql_execute_select (free_join=true, select_lex=0x7f55761eb880, thd=0x7f55761e9000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:1100#10 mysql_select (thd=thd@entry=0x7f55761e9000, tables=0x7f55d441d358, wild_num=0, fields=..., conds=0x0, order=order@entry=0x7f55761eba48, group=group@entry=0x7f55761eb980, having=0x0, select_options=2684652288, result=result@entry=0x7f55d441dc90, unit=unit@entry=0x7f55761eb238, select_lex=select_lex@entry=0x7f55761eb880) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:1221#11 0x0000000000724465 in handle_select (thd=thd@entry=0x7f55761e9000, result=result@entry=0x7f55d441dc90, setup_tables_done_option=setup_tables_done_option@entry=0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_select.cc:110#12 0x0000000000581a38 in execute_sqlcom_select (thd=thd@entry=0x7f55761e9000, all_tables=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:5665#13 0x00000000006fd731 in mysql_execute_command (thd=thd@entry=0x7f55761e9000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:2952#14 0x0000000000702c98 in mysql_parse (thd=thd@entry=0x7f55761e9000, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f5531a78020) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:6950#15 0x00000000007044ab in dispatch_command (command=<optimized out>, thd=thd@entry=0x7f55761e9000, packet=<optimized out>, packet_length=30) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:1442#16 0x0000000000706219 in do_command (thd=thd@entry=0x7f55761e9000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_parse.cc:1054#17 0x000000000078f368 in threadpool_process_request (thd=0x7f55761e9000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_common.cc:311#18 0x000000000079033d in handle_event (connection=0x7f556fec3070) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1553#19 worker_main (param=param@entry=0x1350400 <all_groups+8192>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1606#20 0x0000000000b050e3 in pfs_spawn_thread (arg=0x7f555d6f7b00) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/storage/perfschema/pfs.cc:1860#21 0x00007f769d0fddf3 in start_thread () from /lib64/libpthread.so.0#22 0x00007f769b7713dd in clone () from /lib64/libc.so.6.....
Thread 43 (Thread 0x7f5531b3c700 (LWP 3340)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd77 in _L_lock_974 () from /lib64/libpthread.so.0#2  0x00007f769d0ffd20 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x00000000006cde10 in inline_mysql_mutex_lock (src_file=0xbc9938 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc", src_line=1760, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  THD::release_resources (this=this@entry=0x7f5573f8a000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc:1760#5  0x000000000078f1e7 in threadpool_remove_connection (thd=0x7f5573f8a000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_common.cc:257#6  0x00000000007902b6 in connection_abort (connection=0x7f556fe17ac0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1363#7  handle_event (connection=0x7f556fe17ac0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1564#8  worker_main (param=param@entry=0x1350a00 <all_groups+9728>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1606#9  0x0000000000b050e3 in pfs_spawn_thread (arg=0x7f555e413fc0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/storage/perfschema/pfs.cc:1860#10 0x00007f769d0fddf3 in start_thread () from /lib64/libpthread.so.0#11 0x00007f769b7713dd in clone () from /lib64/libc.so.6Thread 42 (Thread 0x7f5531bbe700 (LWP 3353)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd77 in _L_lock_974 () from /lib64/libpthread.so.0#2  0x00007f769d0ffd20 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x00000000006cde10 in inline_mysql_mutex_lock (src_file=0xbc9938 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc", src_line=1760, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  THD::release_resources (this=this@entry=0x7f55747ed000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc:1760#5  0x000000000078f1e7 in threadpool_remove_connection (thd=0x7f55747ed000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_common.cc:257#6  0x00000000007902b6 in connection_abort (connection=0x7f556fec36a0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1363#7  handle_event (connection=0x7f556fec36a0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1564#8  worker_main (param=param@entry=0x1350c00 <all_groups+10240>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_unix.cc:1606#9  0x0000000000b050e3 in pfs_spawn_thread (arg=0x7f555e414060) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/storage/perfschema/pfs.cc:1860#10 0x00007f769d0fddf3 in start_thread () from /lib64/libpthread.so.0#11 0x00007f769b7713dd in clone () from /lib64/libc.so.6

二、分析大多數執行緒的等待MUTEX

實際上分析pstack可以發現,基本所有的等待執行緒可以分為:

  • KILL SESSION等待

Thread 111 (Thread 0x7f5531afb700 (LWP 15742)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd77 in _L_lock_974 () from /lib64/libpthread.so.0#2  0x00007f769d0ffd20 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x00000000006cde10 in inline_mysql_mutex_lock (src_file=0xbc9938 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc", src_line=1760, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  THD::release_resources (this=this@entry=0x7f55762ba000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_class.cc:1760#5  0x000000000078f1e7 in threadpool_remove_connection (thd=0x7f55762ba000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/threadpool_common.cc:257.....

等待的MUTEX為:

void THD::release_resources()
{
  mysql_mutex_assert_not_owner(&LOCK_thread_count);
  DBUG_ASSERT(m_release_resources_done == false);
  mysql_mutex_lock(&LOCK_status);  //等待的MUTEX
  add_to_status(&global_status_var, &status_var);
  mysql_mutex_unlock(&LOCK_status);
  • SHOW GLOBAL STATUS等待

Thread 91 (Thread 0x7f553373c700 (LWP 17935)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd77 in _L_lock_974 () from /lib64/libpthread.so.0#2  0x00007f769d0ffd20 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x0000000000738116 in inline_mysql_mutex_lock (src_file=0xbd31e8 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc", src_line=7315, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  fill_status (thd=thd@entry=0x7f5573db0000, tables=tables@entry=0x7f55736f6178, cond=0x7f55736f5d70) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7315#5  0x000000000073e692 in do_fill_table (join_table=0x7f5564145c78, table_list=0x7f55736f6178, thd=0x7f5573db0000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7986.....

等待的MUTEX為:

int fill_status(THD *thd, TABLE_LIST *tables, Item *cond){
  .......  /*
    Avoid recursive acquisition of LOCK_status in cases when WHERE clause
    represented by "cond" contains subquery on I_S.SESSION/GLOBAL_STATUS.
  */
  if (thd->fill_status_recursion_level++ == 0) 
    mysql_mutex_lock(&LOCK_status); //等待的MUTEX

實際上我們發現他們的共同點為都需要等待獲取MUTEX:LOCK_status,

三、分析那個執行緒獲取了MUTEX:LOCK_status而又處於等待

那麼可以在整個pstack中試圖找出獲取LOCK_status的執行緒,實際上就是

Thread 80 (Thread 0x7f553916a700 (LWP 1306)):#0  0x00007f769d103f7d in __lll_lock_wait () from /lib64/libpthread.so.0#1  0x00007f769d0ffd41 in _L_lock_790 () from /lib64/libpthread.so.0#2  0x00007f769d0ffc47 in pthread_mutex_lock () from /lib64/libpthread.so.0#3  0x00000000008a0014 in inline_mysql_mutex_lock (src_file=0xc31a00 "/mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc", src_line=7536, that=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/include/mysql/psi/mysql_thread.h:688#4  MYSQL_BIN_LOG::set_status_variables (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:7536#5  0x00000000008a007b in show_binlog_vars (thd=<optimized out>, var=0x7f5539166c70, buff=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:9476#6  0x00000000007375ff in show_status_array (thd=thd@entry=0x7f5573c2c000, wild=wild@entry=0x0, variables=0x7f75f43f9030, value_type=value_type@entry=OPT_GLOBAL, status_var=0x7f55391671b0, prefix=prefix@entry=0xc2ce39 "", table=0x7f556345d010, ucase_names=false, cond=cond@entry=0x7f55636380d0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:2635#7  0x0000000000737f69 in fill_status (thd=thd@entry=0x7f5573c2c000, tables=tables@entry=0x7f5563638578, cond=0x7f55636380d0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7321#8  0x000000000073e692 in do_fill_table (join_table=0x7f5563636610, table_list=0x7f5563638578, thd=0x7f5573c2c000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/sql_show.cc:7986....

顯然這也是一個show global status命令。而他正在等待獲取另外一把MUTEX:LOCK_log如下:

/* fill_status MYSQL_BIN_LOG::ordered_commit
  Copy out current values of status variables, for SHOW STATUS or
  information_schema.global_status.
  This is called only under LOCK_status, so we can fill in a static array.
*/void MYSQL_BIN_LOG::set_status_variables(THD *thd)
{
....
  mysql_mutex_lock(&LOCK_log); //這裡是需要獲取MUTEX LOCK_log
  if (!have_snapshot)
  {
    set_binlog_snapshot_file(log_file_name);
    binlog_snapshot_position= my_b_tell(&log_file); //獲取binlog的位置這裡就是狀態值Binlog_snapshot_position 
  }
  mysql_mutex_unlock(&LOCK_log);
.....

顯然這裡要獲取的狀態值Binlog_snapshot_position ,因此必須獲取LOCK_log MUTEX,來保證沒有併發的執行緒正在寫入binlog物理檔案,當然這裡的寫入是指寫入作業系統的快取而非FSYNC ,:

mysql> show global status like '%pos%';
+--------------------------+-------+| Variable_name            | Value |
+--------------------------+-------+
| Binlog_snapshot_position | 6363  |+--------------------------+-------+1 row in set (2.05 sec)

四、分析堵塞的根源

那麼堵塞執行緒 (LWP 17935) 的很可能是開始說的那個大事物正在做flush了因此我們找到slave的 sql_thread的棧幀如下:

Thread 112 (Thread 0x7f75ef237700 (LWP 82013)):#0  0x00007f769d10425d in read () from /lib64/libpthread.so.0#1  0x00000000008f12ba in read (__nbytes=5242880, __buf=0x7f5565800000, __fd=181) at /usr/include/bits/unistd.h:45#2  my_read (Filedes=181, Buffer=0x7f5565800000 "\224\200錦224\234\215錦212℃\234\211閈231\220錦205\217竆b", Count=5242880, MyFlags=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/mysys/my_read.c:50#3  0x00000000008dbd7d in my_b_fill (info=0x7f556546cb80) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/mysys/mf_iocache2.c:226#4  0x000000000089cba9 in MYSQL_BIN_LOG::do_write_cache (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=thd@entry=0x7f55764d6000, cache=cache@entry=0x7f556546cb80) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:6005#5  0x00000000008a5f7b in MYSQL_BIN_LOG::write_cache (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=thd@entry=0x7f55764d6000, cache_data=cache_data@entry=0x7f556546cb78) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:6144#6  0x00000000008a6282 in binlog_cache_data::flush (this=0x7f556546cb78, thd=0x7f55764d6000, bytes_written=0x7f75ef2349e0, wrote_xid=0x7f75ef2349c0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:1261#7  0x00000000008a6336 in flush (wrote_xid=0x7f75ef2349c0, bytes_written=<synthetic pointer>, thd=0x7f55764d6000, this=0x7f556546ca00) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:778#8  MYSQL_BIN_LOG::flush_thread_caches (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=thd@entry=0x7f55764d6000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:6779#9  0x00000000008a6469 in MYSQL_BIN_LOG::process_flush_stage_queue (this=this@entry=0x135e6c0 <mysql_bin_log>, total_bytes_var=total_bytes_var@entry=0x7f75ef234ad0, rotate_var=rotate_var@entry=0x7f75ef234ab0, out_queue_var=out_queue_var@entry=0x7f75ef234ae0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:6835#10 0x00000000008a674c in MYSQL_BIN_LOG::ordered_commit (this=this@entry=0x135e6c0 <mysql_bin_log>, thd=thd@entry=0x7f55764d6000, all=all@entry=true, skip_commit=skip_commit@entry=false) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/binlog.cc:7265.....#15 0x0000000000888670 in Xid_log_event::do_apply_event (this=0x7f557591d380, rli=0x7f555da1a000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/log_event.cc:7632#16 0x000000000088425a in Log_event::apply_event (this=this@entry=0x7f557591d380, rli=rli@entry=0x7f555da1a000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/log_event.cc:3057#17 0x00000000008bb52e in apply_event_and_update_pos (ptr_ev=ptr_ev@entry=0x7f75ef236860, thd=thd@entry=0x7f55764d6000, rli=rli@entry=0x7f555da1a000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/rpl_slave.cc:3818#18 0x00000000008befbb in exec_relay_log_event (rli=0x7f555da1a000, thd=0x7f55764d6000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/rpl_slave.cc:4315#19 handle_slave_sql (arg=arg@entry=0x7f555da14000) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/sql/rpl_slave.cc:6206#20 0x0000000000b050e3 in pfs_spawn_thread (arg=0x7f557009e0c0) at /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.25-73.0/storage/perfschema/pfs.cc:1860#21 0x00007f769d0fddf3 in start_thread () from /lib64/libpthread.so.0#22 0x00007f769b7713dd in clone () from /lib64/libc.so.6

我們很清楚的看到這裡正處於flush階段

 MYSQL_BIN_LOG::process_flush_stage_queue

原始碼中如下:

/*
    Stage #1: flushing transactions to binary log
    While flushing, we allow new threads to enter and will process
    them in due time. Once the queue was empty, we cannot reap
    anything more since it is possible that a thread entered and
    appointed itself leader for the flush phase.
  */
  if (change_stage(thd, Stage_manager::FLUSH_STAGE, thd, NULL, &LOCK_log)) //這裡獲取MUTEX LOCK_log知道flush 結束
  {
    DBUG_PRINT("return", ("Thread ID: %lu, commit_error: %d",
                          thd->thread_id, thd->commit_error));
    DBUG_RETURN(finish_commit(thd));
  }

五、結論

  • 本例子中等待MUTEX有如下的圖:

MySQL:kill和show命令hang住一列

image.png

因此我們能在show processlist中發現大量的會話都處於掛起狀態。

  • 負載不高是因為這裡基本都是MUTEX等待CPU負載不高,IO不高是因為這裡處於的是flush階段還沒有做到FSYNC階段。

  • 當然大事物是有可能堵塞SHOW GLOBAL STATUS 命令的,如本例。

  • 最後還是那句話MySQL不適合大事物。



作者微信:gp_22389860


來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/7728585/viewspace-2215614/,如需轉載,請註明出處,否則將追究法律責任。

相關文章