记录一下今天的一个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 SQLEXCEPTIONBEGIN

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。