MySQL：不是MySQL問題的MySQL問題
一、自定義函數的BUG導致的問題
這個問題是跑一條如下的的SQL
update test set p_id=getPid(c_id);
這個表只有10w條數據，但是語句卻一直不能完成，如果將語句加上limit，當limit 50000的時候是可以執行完成的，但是當limit 80000的時候就一直不能完成。并且有一個現象，就是語句會不斷會出現opening tables的狀態。
既然語句不能執行完成，那么就需要找到為什么不能完成，先把等待的原因找到，比如：
- 鎖等待？
- CPU打滿？
- IO打滿？
排查下來發現這個語句在實際執行的時候占用了大量的CPU，因此我們分別采集了正常執行和異常的情況，發現異常的時候正常的邏輯幾乎成了一根線，而非正常的邏輯占用了大量的CPU如下：
那么很顯然，實際上本語句執行異常的情況下，CPU都沒有處理正常的邏輯。而其上層調用sp_head::execute_function就是執行函數的上層調用，而這里只有一個自定義函數，因此幾乎可以判定是自定義函數內部邏輯遇到了什么問題。接著我們使用pstack對異常情況的執行棧進行了查看，并且多次測試正常邏輯的pstack執行棧，發現其中有一個邏輯入參不斷在膨脹，且內存長度不斷增加(length)，
當然這里所有的都是我的測試環境的構建，不是線上環境。那么就可以確認函數內部在做拼接的時候遇到了問題，繼而我們打開自定義函數getPid，發現其中有一個while循環，循環內部在做字段的拼接，拼接完成后返回值，就是這個while循環，在滿足一定情況下會出現死循環，而且根據pstack入參這個字符串，實際上就是不斷在拼接某個字段，這個字段的值為1，由于死循環拼接了很長很長，這里看到就是1,1,1,1,1,1......，這樣我們也拿到了這個出現問題行的字段值 1，并且我們通過死循環條件也能判斷出另外一個字段的值，接下來就根據這兩個字段在表里面查一下就可以找到導致死循環的行，當然這里只是講一個思路，不方便給出這個自定義函數。出現死循環的問題也剛好符合CPU打滿的情況。
其次由于自定義函數內存有select 語句，這個語句在遇到自定義函數死循環的情況下要不斷的循環跑，因此就觀察到update 語句執行異常期間，觀察到opening tables的情況。
二、應用代碼static 變量導致的死鎖
這個問題在MySQL層的表現就是出現了死鎖，但是這個死鎖表很簡單，簡單到只有少量的記錄，而且只有主鍵，并且沒有其他的索引這里假定主鍵就是id，且為RC隔離級別，每次執行的語句也是根據主鍵來查詢和更新的，如下：
begin;
select * from test where id=1 for update；
update test set name='a' where id=1;
commit;
死鎖如下（這里刪除了詳細數據）：
------------------------
LATEST DETECTED DEADLOCK
------------------------
2022-07-06 19:48:38 0x7efc44162700
*** (1) TRANSACTION:
TRANSACTION 12739556, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 627119, OS thread handle 139619931977472, query id 129095157 192.168.1.81 root updating
update test set name='a' where id=1
*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 388279 page no 4 n bits 152 index PRIMARY of table `test`.`test` trx id 12739556 lock_mode X locks rec but not gap
Record lock, heap no 82 PHYSICAL RECORD: n_fields 16; compact format; info bits 0
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 388279 page no 4 n bits 152 index PRIMARY of table `test`.`test` trx id 12739556 lock_mode X locks rec but not gap waiting
Record lock, heap no 55 PHYSICAL RECORD: n_fields 16; compact format; info bits 0
*** (2) TRANSACTION:
TRANSACTION 12739557, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 627114, OS thread handle 139621354526464, query id 129095158 192.168.1.81 root updating
update test set name='o' where id=2
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 388279 page no 4 n bits 152 index PRIMARY of table `test`.`test` trx id 12739557 lock_mode X locks rec but not gap
Record lock, heap no 55 PHYSICAL RECORD: n_fields 16; compact format; info bits 0
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 388279 page no 4 n bits 152 index PRIMARY of table `test`.`test` trx id 12739557 lock_mode X locks rec but not gap waiting
Record lock, heap no 82 PHYSICAL RECORD: n_fields 16; compact format; info bits 0
*** WE ROLL BACK TRANSACTION (2)
那么出現這種死鎖問題，一般分析路徑為：
- 業務代碼是否有問題。
- 執行計劃是否有問題。
- 最后才是重現，分析MySQL本身的問題。
當我們分析第一點的時候，業務代碼寫得很簡單，也很清晰就是前面的事務邏輯，這種事務說實話出現死鎖貌似不太可能，因為很簡單查詢是查詢的主鍵，更新的時候也是通過主鍵更新一個字段的值而已，且除了主鍵沒有其他的索引，這種情況一般只會是堵塞而不會出現死鎖。
然后我們在測試環境模擬死鎖的時候打開了general log，發現并不是我們想象的，多線程的各個語句和事務是在一個session 交替進行的，這就奇怪了，言外之意就是多個業務線程對應了一個session，大概如下：
begin；
update set name='o' where id=2
commit；
begin；
select * from test where id=1 for update；
select * from test where id=3 for update；
select * from test where id=4 for update；
update test set name='a' where id=3；
update test set name='a' where id=1；
commit；
update set name='o' where id=4；
反正沒什么規律，這貌似很像多線程并發并且所有語句堆到了同一個session。
那么進而分析，代碼變量的定義我們才發現代碼中將連接變量的屬性設置為了static類型的，開發環境當然是java的 ，我們可以類比C++，C++中如果將類變量的屬性加上static代表是靜態變量，這種變量的值不是存在棧上的，而是存在靜態全局區，所有通過本類實例化的對象，都共享了這個靜態變量，換一句話說，如果某個實例化的對象修改了這個靜態變量那么所有的實例化對象都會修改，當然java/python 都有類似的使用方法。主要還是看內存到底是棧內存/堆內存/全局內存。那么這個問題就變得簡單了，當多個線程同時初始化建立好連接過后，所有的線程實際上最后得到連接只有一個。類似如下:
最后為了驗證我寫了一個測試用例（見末尾），很難跑成功，因為4個線程同時使用了一個connect，感覺應該是C下面這樣在獲取結果（mysql_store_result）和free結果（mysql_free_result）的時候可能的情況是未知的，當然也沒去仔細研究lib庫函數的使用方式可能寫的方式也有問題，反正各種crash（core dump）。但是在偶爾能夠成功的時候可以在general log中看到如下日志，這里就是所有線程的語句堆到同一個session：
static變量：
2022-07-08T07:07:50.364174Z 173 Query select 1
2022-07-08T07:07:50.365168Z 173 Query select 2
2022-07-08T07:07:50.365903Z 173 Query select 3
2022-07-08T07:07:50.370390Z 173 Query select 0
2022-07-08T07:07:51.367748Z 173 Query select 2
2022-07-08T07:07:51.367903Z 173 Query select 1
2022-07-08T07:07:51.368161Z 173 Query select 3
顯然這是一個session id 為173，而實際上測試用例4個線程會不斷的跑select 0/select 1/select 2/select 3。但是4個線程對應了同一個session，這也和我們實際情況一致，這樣如果多個應用各自啟動了多個線程，那么混跑語句就會出現下面的情況：
app1 多線程：
begin;
select * from test where id=1 for update；
select * from test where id=2 for update；
select * from test where id=3 for update；
update set name='a' where id=1;
update set name='a' where id=2;
commit;
app2 多線程:
begin;
select * from test where id=2 for update；
select * from test where id=1 for update；
select * from test where id=3 for update；
update set name='a' where id=2;
update set name='a' where id=3;
commit;
事務被無序的擴大了，死鎖概率當然大大增加。這也是我們實際環境中看到的情況。當然如果測試用例使用局部變量就沒有問題，改為局部變量后正常執行如下：
2022-07-08T07:18:22.582624Z 225 Query select 0
2022-07-08T07:18:22.582732Z 222 Query select 2
2022-07-08T07:18:22.582638Z 223 Query select 1
2022-07-08T07:18:22.583214Z 224 Query select 3
2022-07-08T07:18:23.583894Z 225 Query select 0
2022-07-08T07:18:23.583973Z 222 Query select 2
2022-07-08T07:18:23.583915Z 223 Query select 1
2022-07-08T07:18:23.584315Z 224 Query select 3
這里就是4個thread對應了4個session，各自跑的各自的語句。
附件
C++ 測試用例，如果改成局部變量后4個線程對應4個session，可以正常跑沒有問題如下，static 變量容易導致各種crash。
#include<stdio.h>
#include<stdlib.h>
#include<iostream>
#include "/opt/mysql/mysql3306/install/include/mysql.h"
#include <time.h>
#include <unistd.h>
using namespace std;
class My_Con
{
public:
MYSQL conn_ptr;
My_Con(const char *host,const char *user,const char *passwd,unsigned int port)
{
mysql_init(&conn_ptr);
if(mysql_real_connect(&conn_ptr,host,user,passwd,NULL,port,NULL,0)==NULL)
{
printf("err: mysql_real_connect() error %s\n",mysql_error(&conn_ptr));
exit(1);
}
}
MYSQL* get_conn()
{
return &conn_ptr;
}
//~My_Con(){mysql_close(&conn_ptr);cout<<"close connect"<<endl;}
};
class My_Test
{
public:
static MYSQL* conn_ptr; //靜態指針
static My_Con* test; //靜態指針
int myid;
MYSQL_RES *query_res;
char strtest[30];
My_Test(const int i)
{
test = new My_Con("192.168.1.61","testuser","gelc123",3306);
conn_ptr = test->get_conn();
myid = i ;
query_res = NULL;
}
void* get_string(int id)
{
sprintf(strtest, "select %d ;", id);
cout<<strtest<<endl;
}
void test_query()
{
get_string(myid);
if(mysql_query(conn_ptr,strtest) != 0)
{
printf("err: mysql_query() error %s %s\n",mysql_error(conn_ptr),strtest);
//exit(1);
}
query_res=mysql_store_result(conn_ptr);
if(query_res == NULL)
{
;
}
mysql_free_result(query_res);
}
//TIPS: static variables
// ~My_Test(){delete []test;}
};
My_Con* My_Test::test = NULL;
MYSQL* My_Test::conn_ptr = NULL;
void* test_func(void* arg)
{
My_Test a(*((int*)arg)); //建立連接
struct timespec n_sec;
n_sec.tv_sec = 1;
n_sec.tv_nsec = 0;
for(;;)
{
nanosleep(&n_sec,NULL);
a.test_query();
}
}
int main()
{
pthread_t tid[4];
int tid_num = 0;
int i = 0;
int ret = 0;
int seq[4] = {0,1,2,3};
pthread_create(tid+tid_num,NULL,test_func,(void*)seq);
tid_num++;
pthread_create(tid+tid_num,NULL,test_func,(void*)(seq+1));
tid_num++;
pthread_create(tid+tid_num,NULL,test_func,(void*)(seq+2));
tid_num++;
pthread_create(tid+tid_num,NULL,test_func,(void*)(seq+3));
tid_num++;
//堵塞回收
for(i = 0;i<=tid_num;i++)
{
ret = pthread_join( *(tid+i) , NULL );
}
return 0 ;
}
