INNODB,INSERT进入慢查询的问题

Question

mysql> select version();
+----------------------+
| version()            |
+----------------------+
| 5.1.56-community-log |
+----------------------+
1 row in set (0.00 sec)mysql> select count(*) from smw_ids;
+----------+
| count(*) |
+----------+
|  1494191 |
+----------+
1 row in set (2.05 sec)engine=innodb
慢查询如下：
# Time: 110811  1:00:24
# User@Host: dev[dev] @  [192.168.1.1]
# Query_time: 12.190885  Lock_time: 0.000089 Rows_sent: 0  Rows_examined: 0
SET timestamp=1313042424;
INSERT /* SMW::makeSMWPageID Lucia Galarza */  INTO `smw_ids` (smw_id,smw_title,smw_namespace,smw_iw,smw_sortkey) VALUES (NULL,'global_coordinates','1196','','GLOBAL COORDINATES   global coordinates');表对smw_namespace 做了分区，分区个数有60几个。
mysql> show index from smw_ids;
+---------+------------+-----------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+
| Table   | Non_unique | Key_name        | Seq_in_index | Column_name   | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment |
+---------+------------+-----------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+
| smw_ids |          0 | PRIMARY         |            1 | smw_id        | A         |     1503932 |     NULL | NULL   |      | BTREE      |         |
| smw_ids |          0 | PRIMARY         |            2 | smw_namespace | A         |     1503932 |     NULL | NULL   |      | BTREE      |         |
| smw_ids |          1 | smw_title       |            1 | smw_title     | A         |     1503932 |       50 | NULL   |      | BTREE      |         |
| smw_ids |          1 | idx_smw_sortkey |            1 | smw_sortkey   | A         |     1503932 |     NULL | NULL   |      | BTREE      |         |
+---------+------------+-----------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+
4 rows in set (0.06 sec)索引也很少，都是小索引。INNODB下的插入是不会阻塞的，不锁表的。为什么写入花了13秒这么长啊？
不是第一次出现了，经常有，有的花2S，有的3,4S各位帮我看看啥原因

Answer 1

检查了BINLOG日志，在这个插入的前后，都没有对SMW_IDS表的UPDATE,DELETE操作。

Answer 2

正常插入在0.05S以内。
贴出BINLOG日志和SLOWLOG# at 1372838
#110811  1:00:11 server id 21528  end_log_pos 1372866   Intvar
SET INSERT_ID=1547478/*!*/;
# at 1372866
#110811  1:00:11 server id 21528  end_log_pos 1373128   Query   thread_id=5181829       exec_time=13    error_code=0
SET TIMESTAMP=1313042411/*!*/;
INSERT /* SMW::makeSMWPageID Lucia Galarza */  INTO `smw_ids` (smw_id,smw_title,smw_namespace,smw_iw,smw_sortkey) VALUES (NULL,'global_coordinates','1196','','GLOBAL COORDINATES  
 global coordinates')
/*!*/;慢查询：# Time: 110811  1:00:24
# User@Host: dev[dev] @  [192.168.1.1]
# Query_time: 12.190885  Lock_time: 0.000089 Rows_sent: 0  Rows_examined: 0
SET timestamp=1313042424;
INSERT /* SMW::makeSMWPageID Lucia Galarza */  INTO `smw_ids` (smw_id,smw_title,smw_namespace,smw_iw,smw_sortkey) VALUES (NULL,'global_coordinates','1196','','GLOBAL COORDINATES   global coordinates');
插入写BINLOG时间是1:00:11，写入到SLOWLOG时间是1:00:24，Query_time: 12.190885

Answer 3

又看到了自增主键这没有当初的数据库状态不好判断，可能有很多原因，表锁,io高，cpu高

Answer 4

io,cpu都不高，INNODB的，插入是不锁表的，可以并发插入。表锁可能由于其他的UPDATE或者DELETE造成，但是我没有找到这样的SQL语句。

Answer 5

optimize 这种表操作的语句有吗看满查询日志  除了insert的其他的时间长的语句

Answer 6

有慢的select的 IO或者cpu不高是怎么得来的

Answer 7

单独执行这个Insert语句就要2S? 有试过直接在后台执行这个语句么？

Answer 8

一条几条慢查询，IO和CPU是不会升高的。10分钟出现一个慢查询，负载会高么？

Answer 9

表记录还OK，索引也没很多，而且也不至于会影响到insert 一笔会这么长时间。都是1点跑的这个语句？
单独执行不会出现问题说明肯定是在执行的时候有其他并发语句影响了该表的插入，插入是不锁表，但其他的可未必。

Answer 10

不是都在1点，一直都有这样的，INSERT超过3S的。
我也正在检查是不是有其他操作把表锁住了。还没什么结果。INNODB下，如果没有表锁，还有其他什么情况会导致插入等待么？

Answer 11

看看是不是有别的select操作在这个时间段内

Answer 12

没有cacti图，怎么知道瞬间load不高，看看慢查询和慢insert是基本一起出现得吗

Answer 13

嗯。没有CACTI图，我是“自认为”的。现在我开了MORNITOR，看看是不是因为负载高的原因造成的。

Answer 14

别的查询一直都存在，但是这个时间段内，没有慢查询，只有INSERT慢查询。

Answer 15

通过监控，可以看到，出现INSERT慢的时候，不是系统负载造成的。刚才又出现了，系统负载为0.01

Answer 16

你的INSERT语句是SP中的还是单独的？代码是什么

Answer 17

# Time: 110811 20:35:06
# User@Host: dev[dev] @  [192.168.1.1]
# Query_time: 4.581699  Lock_time: 0.000045 Rows_sent: 0  Rows_examined: 0
SET timestamp=1313112906;
INSERT /* Article::insertOn F.Sandburg */ IGNORE INTO `page` (page_id,page_namespace,page_title,page_counter,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES (NULL,'1180','blind_spot_â‚‚','0','','0','1','0.104521793912','20110812013502','0','0');
# Time: 110811 20:35:22
# User@Host: dev[dev] @  [192.168.1.1]
# Query_time: 12.982034  Lock_time: 0.000120 Rows_sent: 0  Rows_examined: 0
SET timestamp=1313112922;
INSERT /* SMW::makeSMWPageID F.Sandburg */  INTO `smw_ids` (smw_id,smw_title,smw_namespace,smw_iw,smw_sortkey) VALUES (NULL,'blind_spot_â‚‚','1180','','BLIND SPOT  B   blind spot  B');

Answer 18

SQL语句很简单。同样的SQL，我单独运行，0.01S就写入了。在上面贴出的2个INSERT这个20：35这段时间里，没有慢的SELECT，就这2个慢的INSERT。

Answer 19

不是，都是单独的SQL语句。现在这个库里，除了表，其他存储过程，触发器啥的，一个都没有。

Answer 20

我在BINLOG里查了，在慢INSERT的前面，也没有发现有什么SQL，会对表进行全表锁的。

Answer 21

有点糊涂了，23楼不是说 同样的SQL，我单独运行，0.01S就写入了？

Answer 22

回24楼：
这个SQL是单独的SQL语句，不是写在EVENT或者SP中的。我把慢查询里的INSERT拿出来，在命令行里执行，只需要0.01S。

Answer 23

纵观 @zuoxingyu 提供的所有信息：1.INSERT插入慢 应该不是INSERT本身的问题；
2.再提供下：服务器是不是内部的开发测试服务器，机器的配置较差，且可能出现大家共用的可能性；3.出现这样非本身执行慢 而导致的慢查询，可能原因：
3.1 分区表有主键，那么分区字段必须写入，为此每次写入都需要检查是否存在相同值，需要IO操作慢，以及主键排序调整（本案例可能性可排除）；3.2 服务器的IO能力差，且配置给innodb_buffer_pool_size的值又较小；3.3 INSERT语句，等待其他事务操作释放锁，尤其是间隙锁，可多查看下该表的前后20秒范围之内的操作；3.4 大批量集中写数据，导致服务器出现性能瓶颈，尤其IO压力；#****************************************#
MySQL技术及运维自动化网：www.mysqlops.com新浪微博账号：http://weibo.com/mysqlops
#****************************************#

Answer 24

回29楼：1：是生产机，数据库操作很平稳，没有高峰。
2：且配置给innodb_buffer_pool_size的值又较小  ==》服务器内存16G，innodb_buffer_pool_size配置2G，mysql> show global variables like '%innodb_buffer%';
+-------------------------+------------+
| Variable_name           | Value      |
+-------------------------+------------+
| innodb_buffer_pool_size | 2147483648 |
+-------------------------+------------+
1 row in set (0.00 sec)mysql> show global status like '%innodb_buffer%';
+---------------------------------------+--------------+
| Variable_name                         | Value        |
+---------------------------------------+--------------+
| Innodb_buffer_pool_pages_data         | 129233       |
| Innodb_buffer_pool_pages_dirty        | 15           |
| Innodb_buffer_pool_pages_flushed      | 8540671      |
| Innodb_buffer_pool_pages_free         | 0            |
| Innodb_buffer_pool_pages_misc         | 1838         |
| Innodb_buffer_pool_pages_total        | 131071       |
| Innodb_buffer_pool_read_ahead         | 96756463     |
| Innodb_buffer_pool_read_ahead_evicted | 20492677     |
| Innodb_buffer_pool_read_requests      | 827711274979 |
| Innodb_buffer_pool_reads              | 142855319    |
| Innodb_buffer_pool_wait_free          | 0            |
| Innodb_buffer_pool_write_requests     | 258647188    |
+---------------------------------------+--------------+3：INSERT语句前后都是INSERT语句，没有别的UPDATE或者DELETE，对同一个表的INSERT,10几个能有1个慢的，超过2S。我把INNODB_BUFFER_POOL_SIZE设置成2G的理由是，读取命中率在99.9以上，热数据只有2G左右，就没有加大着个BUFFER。。

Answer 25

Innodb_buffer_pool_pages_free         | 0 
你数据库服务器专用的物理服务器话，建议 把innodb_buffer_pool_size再调整大点，若是没有特别大或多的MyISAM引擎表数据，设置为 innodb_buffer_pool_size=8G#****************************************#
MySQL技术及运维自动化网：www.mysqlops.com新浪微博账号：http://weibo.com/mysqlops
#****************************************#

Answer 26

innodb_buffer_pool_size值有点小，一般保守都设置成50%。

Answer 27

我改一下看看。
对于这个innodb_buffer_pool_size参数，多大设置算合理的？我看命中率都在99.9%以上了，应该是足够了吧？

Answer 28

现在把INNODB_BUFFER_POOL_SIZE 调整到6G了，还是出现INSERT的慢查询。下面是myslq report的报告
__ InnoDB Buffer Pool __________________________________________________
Usage           6.00G of   6.00G  %Used: 100.00
Read hit      100.00%
Pages
  Free              0            %Total:   0.00
  Data        351.98k                     89.51 %Drty:   0.00
  Misc          41231                     10.49
  Latched                                  0.00
Reads          22.09G  177.5k/s
  From file   277.21k     2.2/s            0.00
  Ahead Rnd                 0/s
  Ahead Sql                 0/s
Writes          2.75M    22.1/s
Flushes       104.42k     0.8/s
Wait Free           0       0/s
mysql> show global status like '%innodb%';
+---------------------------------------+-------------+
| Variable_name                         | Value       |
+---------------------------------------+-------------+
| Innodb_buffer_pool_pages_data         | 351985      |
| Innodb_buffer_pool_pages_dirty        | 1           |
| Innodb_buffer_pool_pages_flushed      | 104528      |
| Innodb_buffer_pool_pages_free         | 1           |
| Innodb_buffer_pool_pages_misc         | 41229       |
| Innodb_buffer_pool_pages_total        | 393215      |
| Innodb_buffer_pool_read_ahead         | 119733      |
| Innodb_buffer_pool_read_ahead_evicted | 123         |
| Innodb_buffer_pool_read_requests      | 22103546894 |
| Innodb_buffer_pool_reads              | 277236      |
| Innodb_buffer_pool_wait_free          | 0           |
| Innodb_buffer_pool_write_requests     | 2755035     |
| Innodb_data_fsyncs                    | 50903       |
| Innodb_data_pending_fsyncs            | 0           |
| Innodb_data_pending_reads             | 0           |
| Innodb_data_pending_writes            | 0           |
| Innodb_data_read                      | 6548721664  |
| Innodb_data_reads                     | 283967      |
| Innodb_data_writes                    | 338159      |
| Innodb_data_written                   | 3905318400  |
| Innodb_dblwr_pages_written            | 104528      |
| Innodb_dblwr_writes                   | 8017        |
| Innodb_have_atomic_builtins           | ON          |
| Innodb_log_waits                      | 0           |
| Innodb_log_write_requests             | 820425      |
| Innodb_log_writes                     | 243699      |
| Innodb_os_log_fsyncs                  | 17348       |
| Innodb_os_log_pending_fsyncs          | 0           |
| Innodb_os_log_pending_writes          | 0           |
| Innodb_os_log_written                 | 477159424   |
| Innodb_page_size                      | 16384       |
| Innodb_pages_created                  | 17448       |
| Innodb_pages_read                     | 399440      |
| Innodb_pages_written                  | 104528      |
| Innodb_row_lock_current_waits         | 0           |
| Innodb_row_lock_time                  | 16906       |
| Innodb_row_lock_time_avg              | 1536        |
| Innodb_row_lock_time_max              | 14849       |
| Innodb_row_lock_waits                 | 11          |
| Innodb_rows_deleted                   | 12867       |
| Innodb_rows_inserted                  | 739480      |
| Innodb_rows_read                      | 94935197818 |
| Innodb_rows_updated                   | 95642       |
+---------------------------------------+-------------+
43 rows in set (0.00 sec)
服务器做了主从配置，从上面没有出现这样的情况。

Answer 29

1.你数据库服务器是几块盘？ 啥型号的盘？做的RAID几？
2.参数检查
2.1 SHOW VARIABLES lIKE 'sync_binlog';
2.2 SHOW VARIABLES lIKE 'sync_binlog'innodb_flush_log_at_trx_commit';
2.3 SHOW VARIABLES lIKE 'innodb_log_buffer_size';
2.4 SHOW VARIABLES lIKE 'innodb_max_dirty_pages_pct';然后你核对下http://www.mysqlops.com/2011/10/26/mysql-variables-one.html 提到的建议合理配置下.