请问为啥MySQL使用游标进行insert操作时，末行会被插入两次？下附代码

Posted 2023-03-25

drop procedure if exists cur;
delimiter //

create procedure cur(
in id char(10)
)
begin

##Declare Some Variables
declare done boolean default 0;
declare tmp char(200);

##Declare the cursor
declare cur_tmp cursor
for
select concat(stu_id,' ',stu_name,' ',sex,' ',birthday,' ',hometown_county,' ',hometown_city,' ',hometown_province)
from stu_info
where stu_id like id
;

##Declare Continue handler
declare continue handler for sqlstate '02000' set done=1;

##Create a table
create table if not exists stu_tmp(
stu_id int not null auto_increment,
stu_com char(200) not null,
primary key(stu_id)
)engine=innodb auto_increment=100001;

##Open cursor
open cur_tmp;

##Loop
repeat

##get stu_comment
fetch cur_tmp into tmp;

##Insert it
insert into stu_tmp (stu_com) values (tmp);

##End of loop
until done end repeat;

##close cursor
close cur_tmp;

end//

delimiter ;

最后一条的cur能取得，然后正确插入，然后取下一条，出错，你的错误控制设置了done然后让它继续做，那么下面的insert就会执行，而且是最后一条，之后不满足循环条件，程序结束 参考技术A

测试场景

MySQL 5.7.12

主要测试 不同刷盘参数 对性能的影响, 使用以下三个场景:

sync_binlog=1, innodb_flush_log_at_trx_commit=1, 简写为b1e1 (binlog-1-engine-1)

sync_binlog=0, innodb_flush_log_at_trx_commit=1, 简写为b0e1

sync_binlog=0, innodb_flush_log_at_trx_commit=0, 简写为b0e0

MySQL 环境搭建使用 MySQL sandbox, 对应三个场景的启动参数如下:
1. ./start --sync-binlog=1 --log-bin=bin --server-id=5712 --gtid-mode=ON --enforce-gtid-consistency=1 --log-slave-updates=1
2. ./start --sync-binlog=0 --log-bin=bin --server-id=5712 --gtid-mode=ON --enforce-gtid-consistency=1 --log-slave-updates=1
3. ./start --sync-binlog=0 --log-bin=bin --server-id=5712 --gtid-mode=ON --enforce-gtid-consistency=1 --log-slave-updates=1 --innodb-flush-log-at-trx-commit=0

压力生成使用sysbench:

mysql -h127.0.0.1 -P5712 -uroot -pmsandbox -e"truncate table test.sbtest1";
/opt/sysbench-0.5/dist/bin/sysbench --test=/opt/sysbench-0.5/dist/db/insert.lua --mysql-table-engine=innodb --mysql-host=127.0.0.1 --mysql-user=root --mysql-password=msandbox --mysql-port=5712 --oltp-table-size=1000000 --mysql-db=test --oltp-table-name=stest --num-threads=1 --max-time=30 --max-requests=1000000000 --oltp-auto-inc=off --db-driver=mysql run


性能观测工具使用systemtap(简称stap), version 2.7/0.160

基准

在没有观测压力的情况下, 对三种场景分别进行基准测试, 用以矫正之后测试的误差:

场景

sysbench事务数

b1e1    67546    

b0e1    125699    

b0e0    181612    

火焰图与offcpu

火焰图

火焰图是Brendan Gregg首创的表示性能的图形方式, 其可以直观的看到压力的分布. Brendan提供了丰富的工具生成火焰图.

火焰图比较b0e1和b0e0

使用stap脚本获取CPU profile, 并生成火焰图(火焰图生成的命令略, 参看Brendan的文档)

stap脚本

global tids
probe process("/home/huangyan/sandboxes/5.7.12/bin/mysqld").function("mysql_execute_command")
       if (pid() == target() && tids[tid()] == 0)
               tids[tid()] = 1;
       


global oncpu
probe timer.profile
       if (tids[tid()] == 1)
               oncpu[ubacktrace()] <<< 1;
       


probe timer.s(10)
       exit();


probe end
       foreach (i in oncpu+)
               print_stack(i);
               printf("\\t%d\\n", @count(oncpu[i]));
       



注意:
1. 脚本只抓取MySQL的用户线程的CPU profile, 不抓取后台进程.
2. 脚本只抓取10s, 相当于对整个sysbench的30s过程进行了短期抽样.

b0e1生成的火焰图

请点击输入图片描述

性能

在开启观测的情况下, 观察性能:

场景

sysbench事务数

b0e1    119274    

b0e0    166424    

分析

在生成的火焰图中, 可以看到:

在b0e1场景中, _ZL27log_write_flush_to_disk_lowv的占比是12.93%, 其绝大部分时间是用于将innodb的log刷盘.

在b0e0场景中, _ZL27log_write_flush_to_disk_lowv的开销被节省掉, 理论上的事务数比例应是1-12.93%=87.07%, 实际事务数的比例是119274/166424=71.67%, 误差较大

误差较大的问题, 要引入offcpu来解决.

offcpu

在之前的分析中我们看到理论和实际的事务数误差较大. 考虑_ZL27log_write_flush_to_disk_lowv的主要操作是IO操作, IO操作开始, 进程就会被OS进行上下文切换换下台, 以等待IO操作结束, 那么只分析CPU profile就忽略了IO等待的时间, 也就是说_ZL27log_write_flush_to_disk_lowv的开销被低估了.

offcpu也是Brendan Gregg提出的概念. 对于IO操作的观测, 除了CPU profile(称为oncpu时间), 还需要观测其上下文切换的代价, 即offcpu时间.

修改一下stap脚本可以观测offcpu时间. 不过为了将oncpu和offcpu的时间显示在一张火焰图上作对比, 我对于Brendan的工具做了微量修改, 本文将不介绍这些修改.

stap脚本

global tids
probe process("/home/huangyan/sandboxes/5.7.12/bin/mysqld").function("mysql_execute_command")
   if (pid() == target() && tids[tid()] == 0)
       tids[tid()] = 1;
   


global oncpu, offcpu, timer_count, first_cpu_id = -1;
probe timer.profile
   if (first_cpu_id == -1)
       first_cpu_id = cpu();
   
   if (tids[tid()] == 1)
       oncpu[ubacktrace()] <<< 1;
   
   if (first_cpu_id == cpu())
       timer_count++;
   


global switchout_ustack, switchout_timestamp
probe scheduler.ctxswitch
   if (tids[prev_tid] == 1)
       switchout_ustack[prev_tid] = ubacktrace();
       switchout_timestamp[prev_tid] = timer_count;
   
   if (tids[next_tid] == 1 && switchout_ustack[next_tid] != "")
       offcpu[switchout_ustack[next_tid]] <<< timer_count - switchout_timestamp[next_tid];
       switchout_ustack[next_tid] = "";
   


probe timer.s(10)
   exit();


probe end
   foreach (i in oncpu+)
       print_stack(i);
       printf("\\t%d\\n", @sum(oncpu[i]));
   
   foreach (i in offcpu+)
       printf("---");
       print_stack(i);
       printf("\\t%d\\n", @sum(offcpu[i]));
   



注意: timer.profile的说明中是这样写的:

Profiling timers are available to provide probes that execute on all CPUs at each system tick.



也就是说在一个时间片中, timer.profile会对每一个CPU调用一次. 因此代码中使用了如下代码, 保证时间片技术的正确性:

   if (first_cpu_id == cpu())
       timer_count++;
   


b0e1生成的带有offcpu的火焰图

请点击输入图片描述

性能

由于变更了观测脚本, 需要重新观测性能以减小误差:

场景

sysbench事务数

b0e1    105980    

b0e0    164739    

分析

在火焰图中, 可以看到:
1. _ZL27log_write_flush_to_disk_lowv的占比为31.23%
2. 理论上的事务数比例应是1-31.23%=68.77%, 实际事务数的比例是105980/164739=64.33%, 误差较小.

观测误差的矫正

在比较b0e1和b0e0两个场景时, 获得了比较好的结果. 但同样的方法在比较b1e1和b0e1两个场景时, 出现了一些误差.

误差现象

b1e1的火焰图如图:

请点击输入图片描述

其中_ZN13MYSQL_BIN_LOG16sync_binlog_fileEb(sync_binlog的函数)占比为26.52%.

但性能差异为:

场景

sysbench事务数

b1e1    53752    

b0e1    105980    

理论的事务数比例为1-26.52%=73.48%, 实际事务数比例为53752/105980=50.71%, 误差较大.

分析压力分布

首先怀疑压力转移, 即当sync_binlog的压力消除后, 服务器压力被转移到了其它的瓶颈上. 但如果压力产生了转移, 那么实际事务数比例应大于理论事务数比例, 即sync_binlog=0带来的性能提升更小.

不过我们还是可以衡量一下压力分布, 看看b1e1和b0e1的压力有什么不同, 步骤如下:

修改stap脚本, 在b1e1中不统计sync_binlog的代价. 生成的火焰图表示消除sync_binlog代价后, 理论上的服务器压力类型.

与b0e1产生的火焰图做比较.

stap脚本

只修改了probe end部分, 略过对my_sync堆栈的统计:

probe end
       foreach (i in oncpu+)
               if (isinstr(sprint_stack(i), "my_sync"))
                       continue;
               
               print_stack(i);
               printf("\\t%d\\n", @sum(oncpu[i]));
       
       foreach (i in offcpu+)
               if (isinstr(sprint_stack(i), "my_sync"))
                       continue;
               
               printf("---");
               print_stack(i);
               printf("\\t%d\\n", @sum(offcpu[i]));
       



结果

b1e1, 理论的服务器压力图:

请点击输入图片描述

b0e1, 实际的服务器压力图:

请点击输入图片描述

可以看到, 压力分布是非常类似, 即没有发生压力分布.

BTW: 这两张图的类似, 具有一定随机性, 需要做多次试验才能产生这个结果.

分析

既然理论和实际的压力分布类似, 那么可能发生的就是压力的整体等比缩小. 推测是两个场景上的观测成本不同, 导致观测影响到了所有压力的观测.

观察stap脚本, 其中成本较大的是ctxswitch, 即上下文切换时的观测成本.

上下文切换的观测成本

如果 “上下文切换的观测成本 影响 场景观测 的公平性” 这一结论成立, 那么我们需要解释两个现象:
1. b1e1和b0e1的比较, 受到了 上下文切换的观测成本 的影响
2. b0e1和b0e0的比较, 未受到 上下文切换的观测成本 的影响

假设 上下文切换的观测成本 正比于 上下文切换的次数, 那么我们只需要:
1. 观测每个场景的上下文切换次数
2. 对于b1e1和b0e1的比较, 由上下文切换次数计算得到理论的降速比, 与实际的降速比进行比较
3. 对于b0e1和b0e0的比较, 由上下文切换次数计算得到是否会带来降速.

stap脚本

在probe scheduler.ctxswitch和probe end 增加了 ctxswitch_times 相关的内容:

global ctxswitch_times
probe scheduler.ctxswitch
       ctxswitch_times++;
       ...


probe end
       ...
       printf("ctxswitch_times=%d\\n", ctxswitch_times);



结果

场景

sysbench事务数

上下文切换次数

sync_binlog占比

b1e1    55352    826370    36.80%    

b0e1    105995    693383    –    

b0e0    162709    675092    –    

分析结果:
1. b1e1与b0e1的比较
1. 理论降速比: 693383/826370 = 83.90%
2. 实际降速比: (实际的事务数比例/由sync_binlog占比推算的理论的事务数比例) = (55352/105995)/(1-36.80%) = 0.5222/0.6320 = 82.63%
3. 误差很小. 即b1e1与b0e1的比较中, 理论值和实际值的误差来自于: IO操作的减少导致上下文切换的数量减小, 使得两个场景的观察成本不同.
2. b0e1与b0e0的比较: 上下文切换次数相近, 即两个场景的观察成本相同.

实验结果符合之前的分析.

结论

利用火焰图, 可以快速诊断出MySQL服务器级别的性能瓶颈, 做出合理的参数调整

对于IO类型的操作的观测, 需要考虑oncpu和offcpu两种情况

由于观测手段中使用了上下文切换作为观测点, 那IO操作数量的不同, 会引起上下文切换次数的不同, 从而引起观测误差.