PHP调用存储过程返回值不一致的问题

作者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注明作/译者和出处,并且不能用于商业用途,违者必究.
今天遇一个同学聊存储过程返回值经常得到意外的值为null, 因为白天有事,晚上给做一个实验放在这里供有相应问题的同学查看一下。
存储过程:

delimiter //
create procedure usp_s2(out par1 int)
begin
	select inet_ntoa(ip) , port from proxy_list limit 5;
	select count(*) into par1 from proxy_list;
END//
delimiter ;

session 1执行:

mysql> call usp_s2(@a);
+---------------+------+
| inet_ntoa(ip) | port |
+---------------+------+
| 1.34.21.86    | 8088 |
| 1.34.59.50    | 8088 |
| 1.34.69.15    | 8088 |
| 1.34.73.110   | 8088 |
| 1.34.76.218   | 8088 |
+---------------+------+
5 rows in set (0.00 sec)

Query OK, 1 row affected (0.01 sec)

mysql> select @a;
+------+
| @a   |
+------+
| 4430 |
+------+
1 row in set (0.00 sec)

session 2执行:

mysql> select @a;
+------+
| @a   |
+------+
| NULL |
+------+
1 row in set (0.00 sec)

可见两个session得到的结果不一致。 基本可以肯定两次调用落入不同的会话中会得到不同的值。
为了一致可以如用如下调用:

multi_query("call usp_s2(@total); select @total;");

if ($result) {
        do {
        if ($r = $db->store_result()) {
                if ( $r->field_count == 2){
                        while( $row = $r->fetch_row() ){
                                print "ip: $row[0], port: $row[1]\n";
                        }
                }else{
                        $row  = $r->fetch_row();
                        print "total: $row[0]\n";
                }
        }
        } while ( $db->next_result() );
}
$db->close();
?>
$php t_proc_return.php 
ip: 1.34.21.86, port: 8088
ip: 1.34.59.50, port: 8088
ip: 1.34.69.15, port: 8088
ip: 1.34.73.110, port: 8088
ip: 1.34.76.218, port: 8088
total: 4430

Good luck.

记录一次truncate操作数据恢复

作者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注明作/译者和出处,并且不能用于商业用途,违者必究.

实际线上的场景比较复杂,当时涉及了truncate, delete 两个操作,经确认丢数据差不多7万多行,等停下来时,差不多又有共计1万多行数据写入。 这里为了简单说明,只拿弄一个简单的业务场景举例。

测试环境: Percona-Server-5.6.16
日志格式: mixed 没起用gtid

表结构如下:

CREATE TABLE `tb_wubx` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`name` varchar(32) DEFAULT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=2 DEFAULT CHARSET=utf8

基于某个时间点有一个备份或是有全量的binlog是能恢复数据的一个唯一保证。 例如我们的备份就是一个表结构创建语句,binlog pos相关信息: mysql-bin.000004 , 4,然后进行了如下:

–t1时间 程序写入:
insert into tb_wubx(name) values(‘张三’),(‘李四’);
insert into tb_wubx(name) values(‘隔壁老王’);
–t2时间 某个人员失误
truncate table tb_wubx;
–t3时间 程序写入
insert into tb_wubx(name) values(‘老赵’);
update tb_wubx set name=’老赵赵’ where id=1;

现在表里的数据情况:

mysql>select * from tb_wubx;
+----+-----------+
| id | name |
+----+-----------+
| 1 | 老赵赵 |
+----+-----------+
1 row in set (0.00 sec)

可以见truncate table操作后,表的自增id又变更为从1开始,原来写入的数据应该是:
+—-+———–+
| id | name |
+—-+———–+
| 1 | 张三 |
+—-+———–+
| 2 | 李四 |
+—-+———–+
| 3 | 隔壁老王 |
+—-+———–+

如果没生truncate table操作,实际的数据应该为:
+—-+———–+
| id | name |
+—-+———–+
| 1 | 张三 |
+—-+———–+
| 2 | 李四 |
+—-+———–+
| 3 | 隔壁老王 |
+—-+———–+
| 4 | 老赵赵 |
+—-+———–+

而且线上的恢复那个表时和序序开发人员了解才知道,原来那个id和缓存及其它地方有依赖,因为id乱了,也会造成程序错乱。这个时间修复id在程序层错乱的事,留给开发人员了关建是给他们讲明白恢复的结果是什么样,我们的关建任务是把数据恢复出来。好,接下来的工作是开始从binlog中恢复数据。
利用: show binary logs; 查看当的log文件分布, 然后利用show binlog events in ‘binary log文件’; 查看log文件的内容,目的是找到truncate发生的日志位置。
另外因为基于备份(由log的启始位置)或是从量log, 如果基于备份有log的起始位置,我们需要处理的log文件是启始位置到发生truncate的日值(后面的数据处理不了,会发生主建冲突的错误造成truncate后的数据不能恢复),
如果是全量日志,需要从创建完mysql后库后的日志去处理到当前的发生truncate的位置(后面数据会因为主建冲突写不进去)
恢复准备工作,创建一个库用于恢复数据,这里创建了一个re_wubx, 及原结构的表: tb_wubx (相当于恢复了备份,过程省略)
作者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注明作/译者和出处,并且不能用于商业用途,违者必究.

mysql> show binary logs;
+------------------+-----------+
| Log_name | File_size |
+------------------+-----------+
| mysql-bin.000001 | 143 |
| mysql-bin.000002 | 261 |
| mysql-bin.000003 | 562 |
| mysql-bin.000004 | 1144 |
+------------------+-----------+
4 rows in set (0.00 sec)

我这里有一个备份文件就是那个创建表的sql语句,位置是mysql-bin.000004 , 4
在这个案例里我只用cover住mysql-bin.000004这个文件。

mysql>show binlog events in 'mysql-bin.000004';
+------------------+------+-------------+-----------+-------------+----------------------------------------------------+
| Log_name         | Pos | Event_type    | Server_id   | End_log_pos | Info |
+------------------+------+-------------+-----------+-------------+----------------------------------------------------+
| mysql-bin.000004 | 4   | Format_desc   | 753306 | 120 | Server ver: 5.6.16-64.2-rel64.2-log, Binlog ver: 4 |
| mysql-bin.000004 | 120 | Query         | 753306 | 209 | use `wubx`; truncate table tb_wubx |
| mysql-bin.000004 | 209 | Query         | 753306 | 281 | BEGIN |
| mysql-bin.000004 | 281 | Table_map     | 753306 | 334 | table_id: 91 (wubx.tb_wubx) |
| mysql-bin.000004 | 334 | Write_rows    | 753306 | 393 | table_id: 91 flags: STMT_END_F |
| mysql-bin.000004 | 393 | Xid           | 753306 | 424 | COMMIT /* xid=1073 */ |
| mysql-bin.000004 | 424 | Query         | 753306 | 496 | BEGIN |
| mysql-bin.000004 | 496 | Table_map     | 753306 | 549 | table_id: 91 (wubx.tb_wubx) |
| mysql-bin.000004 | 549 | Write_rows    | 753306 | 602 | table_id: 91 flags: STMT_END_F |
| mysql-bin.000004 | 602 | Xid           | 753306 | 633 | COMMIT /* xid=1074 */ |
| mysql-bin.000004 | 633 | Query         | 753306 | 722 | use `wubx`; truncate table tb_wubx |
| mysql-bin.000004 | 722 | Query         | 753306 | 794 | BEGIN |
| mysql-bin.000004 | 794 | Table_map     | 753306 | 847 | table_id: 92 (wubx.tb_wubx) |
| mysql-bin.000004 | 847 | Write_rows    | 753306 | 894 | table_id: 92 flags: STMT_END_F |
| mysql-bin.000004 | 894 | Xid           | 753306 | 925 | COMMIT /* xid=1081 */ |
| mysql-bin.000004 | 925 | Query         | 753306 | 997 | BEGIN |
| mysql-bin.000004 | 997 | Table_map     | 753306 | 1050 | table_id: 92 (wubx.tb_wubx) |
| mysql-bin.000004 | 1050 | Update_rows  | 753306 | 1113 | table_id: 92 flags: STMT_END_F |
| mysql-bin.000004 | 1113 | Xid          | 753306 | 1144 | COMMIT /* xid=1084 */ |
+------------------+------+-------------+-----------+-------------+----------------------------------------------------+
19 rows in set (0.00 sec)

看到这个表刚开始就发生一次truncate, 那其实也可以说明我就恢复刚开始那个truncate到后来那个误操作的truncate table的语句之间的数据就是丢失的数据。
这个恢复可以从mysql-bin.000004 pos: 4到mysql-bin.000004 pos: 633 即:

mysqlbinlog --rewrite-db='wubx->re_wubx' --start-position=4 --stop-position=633 mysql-bin.000004 |mysql -S /tmp/mysql.sock re_wubx

恢复结果如下:

mysql -S /tmp/mysql.sock re_wubx;
mysql>select count(*) from tb_wubx;
+----------+
| count(*) |
+----------+
| 3 |
+----------+
1 row in set (0.02 sec)

mysql>select * from tb_wubx;
+----+--------------+
| id | name |
+----+--------------+
| 1 | 张三 |
| 2 | 李四 |
| 3 | 隔壁老王 |
+----+--------------+
3 rows in set (0.00 sec)

mysql>insert into tb_wubx(name) select name from wubx.tb_wubx;
Query OK, 1 row affected (0.00 sec)
Records: 1 Duplicates: 0 Warnings: 0

mysql> rename table wubx.tb_wubx to wubx.bak_tb_wubx;
Query OK, 0 rows affected (0.04 sec)

mysql> rename table re_wubx.tb_wubx to wubx.tb_wubx;
Query OK, 0 rows affected (0.03 sec)

mysql> select * from wubx.tb_wubx;
+----+--------------+
| id | name |
+----+--------------+
| 1 | 张三 |
| 2 | 李四 |
| 3 | 隔壁老王 |
| 4 | 老赵赵 |
+----+--------------+
4 rows in set (0.00 sec)

恢复完成。
想一想,如果我跳过那个truncate继续执行那些binlog会怎么样 ?

thread pool 介绍二

作者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注明作/译者和出处,并且不能用于商业用途,违者必究.

原来写过一个MariaDB thread pool介绍: http://www.mysqlsupport.cn/mariadb-thread-pool/

最近发现线上的数据库连接又有所增长,数据库的性能有点下降,所以又进一步的关注了一下thread pool.  大概总结如下:

Thread Pool根据系统的CPU创建出thread_pool_size(该参数不建议调整),也可以把这个参数理解为Thread Pool共分了多少Group, 每个Group里同时可以运行多少个任务由:thread_pool_oversubscribe控制,默认是3. 如果把thread_pool_oversubscribe设置为1,则thread_pool_size是同时允许的活跃任务数.每个Group都是一个epoll的对象.

 

Thread_pool_size  X  Thread_pool_oversubscribe = MySQL内部同时支持运行的最大任务数. 如MySQL-5.5128个任务时运行比较好时,CPU16个核,可以把Thread_pool_oversubscribe更改为: 8或是10都可以.

(实际生产中可以通过调Thread_pool_oversubscribe来防止memcache/Redis倒后的数据库雪崩问题)

Thread_pool现在在Percona中引入了优先级队列,新的连接会根据 thread_pool_high_prio_tickets排出优先级,可可以分为两个队列(这个有点类似于Innodb的tickets)目的是把连接接分一下优先级.

thread_pool_max_threads 用于控制thread pool最大允许有多少连接默认是100000.为了防止socket创建占用太多内存,可以把这个降低一点.

thread_pool_stall_limit 用于防止thread pool里的线程死掉.Thread pool里线程如果超过thread_pool_stall_limit声明的时间没响应降会重新创建.默认是500ms

特殊场景:

Thread pool里被占用满了.管理者操作太慢怎么办?

Thread pool提供一个特殊的参数: extra_port 去监听一个和服务端口不一样的端口,用于Thread pool被占满或是被锁着的情况下用于管理使用.

extra_max_connections 用于声明extra_port最大允许的连接.

这个功能也能用于防止MySQL连接数占满不能进入MySQL进行管理的问题.

 

我大概测了 1000, 2000这样规模的连接,如果不使用thread pool 都跑不起来. 使用thread pool后,性能测试表现都非常不错.

 

测试版本: Percona-Server-5.5.35  1G innodb buffer pool , Tpcc-mysql (20 warehouse)  1.9G数据大小.

普通PC机测试(4个core)

Threadpool配置:

thread_handling=pool-of-threads

thread_pool_oversubscribe=25

 

三次并发200, 1000,2000测试平均tpmC分别为: 3500tpmC, 3414tpmC, 3318tpmC

连接数多后也是有一定的性能下降,但这个下降还能接受. 对于应用连接比较多的场景thread-pool看来还是一个不错的功能.

针对跑MySQL的Linux优化经验

译者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注明作/译者和出处,并且不能用于商业用途,违者必究.

原文: http://www.mysqlperformanceblog.com/2013/12/07/linux-performance-tuning-tips-mysql/
因为很多MySQL的生产环境都在Linux下,我决定指出一些Linux下跑MySQL的很重要的优化点。这些是大家都知道的,也没什么新东西,但我想在这一个blog里收集整理一下Linux相关的配置优化经验。

文件系统:
ext4(or xfs) mount时使用notime选项
文件系统调度策略: 使用deadline or noop

# echo deadline >/sys/block/sda/queue/scheduler
add "elevator=deadline" to grub.conf

译者推荐: XFS , 目前来看Red hat Enterprise 7 后面XFS成为了默认的文件系统。

内存:
Swappiness and NUMA
译者注: 最好禁掉swappiness 或是在系统标识不使用他。

# echo 0 >/proc/sys/vm/swappiness
add "vm.swapiness=0" to /etc/sysctl.conf

使用numa的interleave all 模式
numactl –interleave=all 启动mysqld
如果使用Percona-server 在mysql_safe里有关于使用numa_interleave的选项。更多关于信息可以查看Percona Server对numa的支持

(并且别忘了使用innodb_flush_method=O_DIRECT)rformance/innodb_numa_s

译者注: 内存优化这块可以考虑使用jemalloc( tokudb,percona都有使用这个方式,官方版本需要自已加载)

CPU:
请确认关闭节能模式
检查:

/sys/devices/system/cpu/cpu0/cpufreq/scaling_governor

确认这里显示是不是ondemand,如查是则启用了节能模式。

另外检查/proc/cpuinfo并对比cpu MHZ的数字和”model name”后面显示的数字是否一样
如果使用了ondemand请禁用他。

例如: “ondemand” 在服务器上运行:

$ps ax|grep kondmand|wc -l
65
$ cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
ondemand

另外查看CPU的标注频率是否和实际频率相符:

/proc/cpuinfo:
model name : Intel(R) Xeon(R) CPU E5-4640 0 @ 2.40GHz
..
cpu MHz : 1200.000

如果不符请禁用ondemand(需要更改bois里的配置)

译者注: 如果CPU超过24个核,建议使用MySQL5.6后面的版本。
这是一个简单的针对Linux跑MySQL的一个优化能增强MySQL的性能及更好用。我也你们知道的Linux,MySQL配置优化方法很感兴趣。请在回复里分享一下:)

php连接不上MySQL问题排查

作者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注明作/译者和出处,并且不能用于商业用途,违者必究.

现象
在PHP error log里发现:
PHP Warning: mysqli::mysqli(): (HY000/2003): Can’t connect to MySQL server on ‘XXX.XXX.XXX.XXX’ (99) in /u1/www/XXXX.php on line 10
PHP Warning: mysqli::close(): Couldn’t fetch mysqli in /u1/www/XXXX.php on line 11
推断:只有在高并发的环境下出现

诊断分析:
通过MySQL数据库上抓包,没发现异常。又把目标转到php 服务器上。
BTW:
linux开着selinux连接MySQL在测试中基本上属于1ms+,禁掉selinux后在0.96左右。selinux还是要禁掉的。
既然又怀疑是PHP的问题就写一个程序测试(禁掉selinux后):
cat tconn.php

function microtime_float()
{
list($usec, $sec) = explode(" ", microtime());
return ((float)$usec + (float)$sec);
}

$time_start = microtime_float();
for ( $i=0; $i<30000; $i++){  
$dbh=new mysqli("XXX.XXX.XXX.XXX", "wubx", "wubxwubx", "userdb", 3308);
$dbh->close();
}
$time_end= microtime_float();
$time_use= ($time_end - $time_start)/30000;
print "$time_use\n";

#php tconn.php
0.00090954260031382
再次运行就开始大量的报错。

PHP Warning: mysqli::mysqli(): (HY000/2003): Can't connect to MySQL server on 'XXX.XXX.XXX.XXX' (99) in /u1/www/XXXX.php on line 10
PHP Warning: mysqli::close(): Couldn't fetch mysqli in /u1/www/XXXX.php on line 11

中止该程序后,通过
#strace php tconn.php 运行
得到:

connect(3, {sa_family=AF_INET, sin_port=htons(3308), sin_addr=inet_addr("XXX.XXX.XXX.XXX")}, 16) = -1 EADDRNOTAVAIL (Cannot assign requested address)
shutdown(3, 2 /* send and receive */) = -1 ENOTCONN (Transport endpoint is not connected)

看到这个大概明白是本地的网络可能注册不上了,也难怪在MySQL抓包看也正常。
参考:http://www.unixguide.net/network/socketfaq/4.5.shtml

看样子是本地tcp不能重用造成的。改一下在测试
sysctl -w net.ipv4.tcp_tw_reuse=1;
在次测试问题不存在了。在这个上面碰了一下后顺便改一下/etc/sysctl.conf添加:

net.ipv4.tcp_max_syn_backlog = 819200
net.core.netdev_max_backlog = 400000
net.core.somaxconn = 4096
net.ipv4.tcp_tw_reuse=1
net.ipv4.tcp_tw_recycle=0

#sysctl -p

总结:
php连接MySQL的原因有很多,这个只是一个高并发环境会出现的问题也比较难查。其它连不上只要好重现都比较好查,一般通过抓包都能分析出来。 这个同样适用于做为App的Server大量和中间层交互的也需要注意。

慢查询日志使用

作者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注明作/译者和出处,并且不能用于商业用途,违者必究.

MySQL慢日志往往是大家定位SQL性能问题。通过慢日志分析可以调整索引使用。这是使用最多的一个功能。

目前MySQL也支持毫秒级别以下的慢日志记录,这个功能其实有很多用处,这里大概给大家讲解一下。该功能开启参数:long_query_time

通常使用这个参数的几个环境:

需要得到一个业务的所有SQL可以在测试环境中MySQL的long_query_time设置为0.000001:

set global long_query_time=0.000001;

flush logs;

这样基本上所有对MySQL请求的sql都会记录到慢日志中。通过日志分析可以全面了解一下SQL样式及整体运行调用分布。(重要的库可以考虑开启该参数记录相应的log用于审计使用)

同样对于生产环境,可以通过开启该参数,定期收集一下线上的SQL运行情况,做一些对比,方便了解目前线上SQL运行的情况。能更供更多的指导。 有了慢查询日志,通过慢查询日志分析工具很容易得到一份不错的分析结果。 对于慢日志,目前来讲,官方版本还是有点弱,这也是我推荐使用Percona-Server的一个原因之一,该版本的慢日志功能非常强大,有兴趣的同学也可以猛击(Percona Slow Query Log)去学习一下吧。 也建议官方MySQL开发团队能学习一下Percona对Slow Query的处理,对于DBA排查问题非常有帮助。

慢日志按时间截取

 

作者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注明作/译者和出处,并且不能用于商业用途,违者必究.

今天处理一个case: 数据库异常,连接数突增。
想着分析一下慢日志,可是一看慢日志都好几G了,而且是短日志格式,找到那个时间点相对比较难。于是写了一个脚本从慢日志按时间提取点日志。脚本:
https://github.com/wubx/mysql-binlog-statistic/blob/master/bin/cutlogbytime

使用方法:
cutlogbytime
#用于从慢日志用截取一个时间段的日志方便分析
./cutlogbytime /path/slowlogfile starttime endtime  > dstfile.log
时间需要写时戳

mysql> select unix_timestamp('2013-04-05');
+------------------------------+
| unix_timestamp('2013-04-05') |
+------------------------------+
| 1365091200 |
+------------------------------+
1 row in set (0.00 sec)

mysql> select unix_timestamp('2013-04-06');
+------------------------------+
| unix_timestamp('2013-04-06') |
+------------------------------+
| 1365177600 |
+------------------------------+
1 row in set (0.00 sec)
./cutlogbytime /path/slowlogfile 1365091200 1365177600 > 20130405_slow.log

这样得到一天的日志文件就小一点的也容易分析了。而且可以根据天的文件,在取一天的某个时间点的日志。

 

内存表在同步环境注意事项

作者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注明作/译者和出处,并且不能用于商业用途,违者必究.

在一些场景想利用MySQL的内存表存一些数据来加快数据的操作。但如果在复制环境中这可不是一个好事情。
主要原因如下:
1. 内存表在数据库重启或是异常down机的情况下内存表的数据会全部丢失。如果从库重启一下则同步就不能进行了。
2. 另一方面,在主从环境下,如果从库上同时有大的操作或是排序工作,有借助于临时表的的场景,同时主库上内存表也有较大的写入,从库有可能会就出现报那个内存表is full (1114)这样的错误。
3. 特别需要注意在使用内存表的场景主库重启会主动发起一次对内存表的truncate table操作

那如何解决呢:
1. 从我对数据库的了解上来看推荐用Innodb表去替代memory表, Innodb表如果一个表的数据经常被访问,就会被加载到内存里,数据和索引都在内存,访问速度是比较快的。
2. 不要复制Innodb表。 利用replication-igore-table=db.tbaname形式声明不同步那个表。 这种情况下如果在statement级别的复制,禁止出现insert into otbname select c1 from tbname这种语句。
3.把监表单独放到一个实例下,和主要业务数据分开。

如何查看mysqld进程的Profiler

作者:吴炳锡 来源:http://www.mysqlsupport.cn/ 联系方式: wubingxi#gmail.com 转载请注:译者和出处,并且不能用于商业用途,违者必究.

在mysqld中运行中有时偶而出有点看不出来原因的问题,想看看MySQLD中在执行什么,可以用下来的脚本查一下profiler

#PMP 
#http://poormansprofiler.org/
#!/bin/bash
nsamples=1
sleeptime=0
pid=$(pidof mysqld)

for x in $(seq 1 $nsamples)
  do
    gdb -ex "set pagination 0" -ex "thread apply all bt" -batch -p $pid
    sleep $sleeptime
  done | \
awk '
  BEGIN { s = ""; } 
  /Thread/ { print s; s = ""; } 
  /^\#/ { if (s != "" ) { s = s "," $4} else { s = $4 } } 
  END { print s }' | \
sort | uniq -c | sort -r -n -k 1,1

Innodb Log写入方式分析

作者/译者:王佳隆 来源: http://www.mysqlsupport.cn/ 联系方式:enjoylonely#live.cn  转载请注:译者和出处,并且不能用于商业用途,违者必究.

原文URL:http://www.mysqlperformanceblog.com/2010/07/16/analyzing-the-distribution-of-innodb-log-file-writes/

    最近我分析了一下Innodb是如何写多个日志的。我这里有个流量比较高的MySQL系统,使用的是Percona XtraDB存储引擎,

我使用strace命令分别跟踪了innodb如何去日志文件的。通常来说,innodb是以512bytes的大小来写入日志的。

关于这个可以参考:Mark Callaghan explained this and some of its performance implications 。那么innodb什么时候情况下会以大于512bytes者小于512bytes的请求写到日志里呢?

首先,我通过lsof命令找出日志的文件描述符(handle).

# lsof -p $(pidof mysqld) | grep ib_log
mysqld  29772 mysql    8uW  REG                8,2   268435456   7143989 /var/lib/mysql/ib_logfile0
mysqld  29772 mysql    9uW  REG                8,2   268435456   7143993 /var/lib/mysql/ib_logfile1

我们可以看到2个日志的handle为8和9,现在我们需要捕获innodb是如何写这2个日志的相关信息。Innodb轮循写日志就是通过这个文件描述符.

The following grabs the write sizes out of 100k calls to pwrite() and aggregates them:

# strace -f -p $(pidof mysqld) -e pwrite -s1 -xx 2>&1 \

   | grep ‘pwrite([89],’ |head -n 100000 \

   | awk ‘{writes[$5]++}END{for(w in writes){print w, ” “, writes[w]}}’

本来我可以写一个更好的脚本来捕获信息,但是下面的信息对我来说已经足够了。

bytes        count
512           44067
1024         30740
1536         15221
2048         7094
2560         1810
3072         570
3584         219
4096         112
4608         39
5120         23
5632         16
6144         15
6656         5
7168         3
7680         8
8192         2
8704         2
9216         1
9728         2
10240       1
10752       2
11264       1
11776       1
14848       1
15360       1
15872       2
16384       4
16896       4
17408       2
17920       2
18432       2
18944       8
19456       7
19968       4
20480       4
21504       1
22016       2
24064       1
40960       1

总的来说,大致有3/4是以512和1024字节写入的。那么这到底什么意思呢?这里有很多有趣的而且复杂的东西需要我们去研究。

 1. 我们可以看到,大部分的写入都小于4K。但是我们知道操作系统的page大小是4K的。如果要写入的page不在cache中,那么这个page最开始需要读出,然后再修改,最后再写回到磁盘。vadim曾经过做做一些测试,如果要性能最好,那么日志要在OS的cache中。

 2.这台MySQL的innodb_flush_log_at_trx_commit设置是2.这就说明每个事务都会有一个日志写入请求,这个和设置为1是一样的。但是如果设置成0,那么写入的方法就大不相同—这个时候写入请求会累计到一定程度,然后一起写入。

 3.那么如果说log buffer小于一个事务要写的日志大小怎么办?这是另外一个需要研究的主题了。目前我还不清楚。

4.从上面的信息来看,是否可以很容易知道log buffer大小应该给多少呢?最大的写入小于40K,这好像可以说明分配64K给log buffer就已经足够了。这是真的吗?我们需要去测试才可以知道。peter以前和我谈过这个问题,log buffer背后的机制其实是很复杂的,到底log buffer需要保留多少空间给写操作。这些都需要更深入的研究。但是有一点可以确认,即使最大的写入操作不是很大的情况下,如果log buffer设置太小,性能肯定是不好的,而且会造成而外的锁。这个问题或许我们同样需要去研究。

最后,研究innodb是如何写日志的很容易,但是事实上innodb redo log机制是很复杂的,有时候我们很难说去猜想应该是什么样的,而应该去更深入的研究才可以知道的更多。也许我们可以按照上面这种步骤去研究不同LOG buufer大小,不同的日志参数设置,以及不同的服务器负载的情况下innodb到底是如何来写入日志的。

参考地址:http://mysqlha.blogspot.com/2009/06/buffered-versus-direct-io-for-innodb.html