一、自定义函数的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 ;
}
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
