记录一下今天的一个BUG FIXING。早上收到一个BUG，说有一个到模块A的调用B，多执行几次以后就会出错。错误信息显示SQL ERROR。因为CDC SBE就我最近改过模块A的代码，就把BUG塞给我了。
Trouble Shooting的过程：
- 先检查error log, 没有发现明显问题。于是我把debug log打开后重起模块A，然后手动执行那个调用B，于是我从debug log中拿到了调用B所对应的函数名称。
- 拿到模块A中的函数名称，我搜索源代码，检查最近有没有人修改过这部分代码。发现没有人改过。查看源代码(当然debug log中也有记录)拿到函数调用B所invoke的store procedure call — CALL SP_arrowpig(30, 1, @retCode); 检查最近有没有人修改了和SP_arrowpig有关的SQL，发现也没有。所以我把这个BUG转嫁给别的替罪羊的想法告吹。(因为如果我发现有谁最近修改了跟出错部分相关的代码的话，我就可以把他拖进来跟我一起查)
- 现在只能靠自己了。这时候anusheel同学忽然跳进来，说他已经把那个出错的store procedure在command下运行了好几次，头几次是好的，多运行几次就出错了，怀疑是 mysql本身的bug，并且说以前在production环境下也碰到过，他们解决问题的方法是重新启动mysql服务进程。
- 我也执行了一下，确实像anusheel同学说的那样子，出错信息是这样的：
mysql> CALL SP_arrowpig(30,0,@retCode); select @retCode;
+————–+—————-+———————+
| ErrorPattern | ErrorName | ErrorStr |
+————–+—————-+———————+
| SQL Error | SP_arrowpig | When Doing Task 1 |
+————–+—————————————+
1 row in set (0.01 sec)
Query OK, 0 rows affected, 2 warnings (0.01 sec)
+———-+
| @retCode |
+———-+
| 1 |
+———-+
1 row in set (0.00 sec)
@retCode=1，确实是出错了，我们的编程惯例是retCode=0表示成功的。然后我开始看源代码：
DROP PROCEDURE IF EXISTS SP_arrowpig//
CREATE PROCEDURE SP_arrowpig(IN id INT, IN mode INT, OUT status INT)
…
BEGIN
DECLARE current_id INT;
DECLARE err_str CHAR(255);
DECLARE EXIT HANDLER FOR SQLEXCEPTION BEGIN
SET status = 1;
CALL SP_errmsg("SQL Error","SP_arrowpig",err_str); –和上面的出错信息匹配上了
END;
SET status=0;
SET current_id=id;
arrowpig_label: LOOP
BEGIN
IF mode=1 THEN
SET err_str="When Doing Task 1"; — 出错信息
CREATE TEMPORARY TABLE IF NOT EXISTS sp_output_tmp ENGINE = MEMORY SELECT …from … where ID=current_id;
ELSE
SET err_str="When Doing Task 2"; — 出错信息
CREATE TEMPORARY TABLE IF NOT EXISTS sp_output_tmp ENGINE = MEMORY SELECT ..from … where ID=current_id;
END IF;
SET @parent_id=NULL;
SELECT `Parent` INTO @parent_id FROM … WHERE `Uid`=current_id; — 找到父亲节点后继续循环
SET current_id=@parent_id;
IF ISNULL(current_id) THEN LEAVE arrowpig_label; END IF;
END;
END LOOP; –一个Loop循环
END //
结合源代码和出错信息，我有了以下结论：
- 程序出错是因为遇到了SQL Exception而产生的。
- 出错语句是mode=1中的那个create temporary table if not exists…
- 这里是个Loop循环，为了确定出错的时候current_id的值，我在每次循环进来的地方放了一条select current_id;然后我得到在出错的时候current_id=31。
- 因为SQL Exception没有给我更多的信息，在我得到了current_id=30以后，我手工运行了下面的SQL:
mysql> create temporary table if not exists sp_output_tmp engine=memory select … from … where ID=31;
ERROR 1114 (HY000): The table ‘sp_output_tmp’ is full
- 这个时候Alex上线了，我让他登录到同样的server上看看，但是Alex跟我说运行同样的sp,他没有看到任何错误，我晕！
- 我很奇怪，sp_output_tmp怎么会full的呢，Alex跟我运行同样的东东，怎么就没有错呢？我查了一下mysql的文档，发现create temporary table if not exists … engine=memory select … 有以下特点：
- 跟在create table if not exists sp_output_tmp后面的select语句实际上的效果就是往sp_output_tmp里面插入记录。如果没有sp_output_tmp表，就创建一个，如果该表已经存在，就插入。我用desc sp_output_tmp看了一下，没有任何约束。而且在SP_arrowpig中我没有看到任何drop或者truncate的操作，我不放心，grep了整个SQL文件，都没有看到drop/truncate的操作。这就是说，每次调用SP_arrowpig，sp_output_tmp表都会长大，直到full后报错。
- temporary表只对当前连接有效，也就是说当我log off的时候，从我log in的那刻起所创建的任何temporary table都会报废。temporary table是connection的私有财产。所以说当Alex log in后，他看到的sp_output_tmp和我看到的不是同一个实例，虽然表名字是一样的。于是我要求Alex再多调用几次SP_arrowpig后，他也看到了同样的错误了。
最后的解决其实很简单：我在SP_arrowpig中进入循环之前，放了一条：
DROP TEMPORARY TABLE IF EXISTS sp_output_tmp;
我们就再也没有看到那条错误了，这里要说明一点，我为什么使用drop而不是 truncate呢？原因是在mode=1和<>1的时候，代码中select的字段是不一样的。truncate的时候不会更改表结构，为了能让参数mode在不同的值得时候都能正常工作，我使用了drop。
