1）檢查當時的主機資源狀態，其cpu 記憶體，磁碟IO 負載實際都並不高。複查主機資源發現當時的load avage指標異常，1分鐘平均負載量達到100以上，5分鐘平均負載量達到90以上，10分鐘平均負載量達到60以上，說明當時cpu的執行佇列出現排隊現象。

2)當時的thread cache size 分別出現兩次耗盡情況，大量的執行緒處於running的狀態。

3）從後臺慢日誌看，show variables 語句每次執行都超過了10秒鐘，該sql正常情況執行時間為不到0.1秒鐘，這是非正常現象。

4）從當時的processlists來看，將近90%的活動會話在執行show variables 語句，其狀態主要是在Sending data （約70%）和preparing （約15%）上。

關於 sending data解析：

sending data 是指在儲存引擎和伺服器上層之間進行資料交換，不只是在向客戶端傳送任何資料階段。當伺服器執行一個查詢時，這主要發生在兩個層面。它發生在 SQL Server 層，在那裡解析查詢，檢索資料，然後可以做進一步的處理（ filter 、 sort 、 group 、 join ），再將結果返回給客戶機以及儲存引擎（ InnoDB ， MyISAM ）層等一系列階段。

在 MYSQL 5.7環境模擬了大量併發的會話執行"show variables"的操作，同樣可以看到大量會話堵塞在Sending data狀態，透過跟蹤執行緒堆疊資訊，發現大量的show variables 語句在Sending data狀態都是在申請執行緒mutex鎖時發生了鎖等待。因此可以說明大量併發的show variables 語句執行時，會因為大量的執行緒mutex鎖爭用，而引起會話阻塞堆積。從上面的主機資源情況也可以看出，cpu並不高，但是load avage 比較高是因為執行緒的鎖申請等待引起的排隊。

測試結果：

+--------------+------+-------------------+-----------+---------+------+--------------+----------------+

+--------------+------+-------------------+-----------+---------+------+--------------+----------------+

Thread 187 (Thread 0x7fa8149c6700 ( LWP 26089)):

#0 0x00007fa8dadb354d in __lll_lock_wait () from /lib64/libpthread.so.0 《《《《《《《 ====== 鎖等待

#1 0x00007fa8dadaeed1 in _L_lock_1093 () from /lib64/libpthread.so.0 《《《《《《《 ====== L_lock_1093 ()

#2 0x00007fa8dadaee72 in pthread_mutex_lock () from /lib64/libpthread.so.0 《《《《《《《 ====== 執行緒互斥鎖

#3 0x00000000011df234 in native_mutex_lock (mutex=<optimized out>) at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/include/thr_mutex.h:91

#4 my_mutex_lock (mp=<optimized out>) at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/include/thr_mutex.h:189

#5 inline_mysql_mutex_lock (src_line=80, src_file=0x17f10f0 "/export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/storage/perfschema/table_session_variables.cc", that=<optimized out>) at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/include/mysql/psi/mysql_thread.h:722

#6 table_session_variables::get_row_count () at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/storage/perfschema/table_session_variables.cc:80

#7 0x0000000001185fdf in ha_perfschema::info (this=0x7fa6c806a000, flag=<optimized out>) at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/storage/perfschema/ha_perfschema.cc:400

#8 0x0000000000d8f125 in make_join_readinfo (join=0x7fa7ec0707d0, no_jbuf_after=<optimized out>) at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/sql/sql_select.cc:2222

。。。。。。

(thd=0x7fa7ec037630, com_data=0x7fa8149c5da0, command=COM_QUERY) at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/sql/sql_parse.cc:1491

#20 0x0000000000d529e4 in do_command (thd=0x7fa7ec037630) at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/sql/sql_parse.cc:1032

#21 0x0000000000e24dcc in handle_connection (arg=<optimized out>) at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/sql/conn_handler/connection_handler_per_thread.cc:313

#22 0x0000000001188c74 in pfs_spawn_thread (arg=0x7d25480) at /export/home/pb2/build/sb_0-37309218-1576676677.02/mysql-5.7.29/storage/perfschema/pfs.cc:2197

#23 0x00007fa8dadacea5 in start_thread () from /lib64/libpthread.so.0

#24 0x00007fa8d98658cd in clone () from /lib64/libc.so.6

5）關於SHOW VARIABLES 的來源，SHOW VARIABLES是MYSQL connector/.NET 預設帶上的，它在每次連線時都會發起一次查詢SHOW VARIABLES去獲取需要的相關資訊。當前的mysql資料庫在高峰期的短連線量較大，隨之而來的是大量的SHOW VARIABLES查詢。

針對 SHOW VARIABLES官方是可以建議關閉該屬性，描述及方法如下：

Configure MySQL Connector/.NET to Avoid Executing SHOW VARIABLES Command with Each New MySQL Connection (Doc ID 2106146.1)

SOLUTION

With following connection string parameter new connections will not execute SHOW VARIABLES command :

CacheServerProperties=true

Also waiting for the feature request to be implemented:

REFERENCES

https://dev.mysql.com/doc/connector-net/en/connector-net-connection-options.html

MYSQL connector/.NET 預設的 show variables 引起的執行緒mutex鎖爭用

相關文章