MySQL Bugs: #59384: slow INSERTs, sometimes

Bug #59384	slow INSERTs, sometimes
Submitted:	10 Jan 2011 5:05	Modified:	25 Mar 2012 21:27
Reporter:	Greg Hazel	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S4 (Feature request)
Version:	5.5.8, 5.5.11	OS:	Linux
Assigned to:		CPU Architecture:	Any

Description:
Using InnoDB on MySQL 5.5.8 on XFS on an EBS volume.

Usually, an INSERT INTO of only one row for a particular table takes <1 millisecond. Sometimes, however, the insert takes over 1000 milliseconds. The MySQL profile for the query says:

["starting", "0.00003200"],
["checking permissions", "0.00000900"],
["Opening tables", "0.00001400"],
["System lock", "0.00000800"],
["init", "0.00001100"],
["update", "1.12118300"],
["Waiting for query cache lock", "0.00002100"],
["update", "0.00000900"],
["end", "0.00000500"],
["query end", "0.00000700"],
["closing tables", "0.00000800"],
["freeing items", "0.00002400"],
["logging slow query", "0.00000500"],
["cleaning up", "0.00001000"]

As you can see, all the time is spent in "update".

Schema:

CREATE TABLE `reaction_events` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `type` varchar(255) DEFAULT NULL,
  `mailing_id` int(11) DEFAULT NULL,
  `anchor_text` varchar(255) DEFAULT NULL,
  `referer` varchar(1024) DEFAULT NULL,
  `ip` varchar(255) DEFAULT NULL,
  `created_at` datetime DEFAULT NULL,
  `updated_at` datetime DEFAULT NULL,
  `user_agent` varchar(1024) DEFAULT NULL,
  `url` varchar(1024) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `index_reaction_events_on_type` (`type`),
  KEY `index_reaction_events_on_mailing_id` (`mailing_id`),
  KEY `index_reaction_events_on_anchor_text` (`anchor_text`),
  KEY `index_reaction_events_on_referer` (`referer`(255)),
  KEY `index_reaction_events_on_ip` (`ip`),
  KEY `index_reaction_events_on_created_at` (`created_at`),
  KEY `index_reaction_events_on_updated_at` (`updated_at`),
  KEY `index_reaction_events_on_user_agent` (`user_agent`(255)),
  KEY `index_reaction_events_on_url` (`url`(255))
) ENGINE=InnoDB AUTO_INCREMENT=11874212 DEFAULT CHARSET=utf8 

How to repeat:
INSERT INTO many times in a row, see that one query sometimes takes 100 times longer.

I wonder if this is related to the allocation of yet another extent for the .ibd file (see http://dev.mysql.com/doc/refman/5.5/en/innodb-file-space.html). 

Can you, please, check if slow inserts happen at the same time as your .ibd file grow 1M in size?

I forgot to mention, I'm using innodb_file_per_table=1.

It does seem that these slow inserts coincide with the .ibd file growing. I think it grew by 4MB all at once. The documentation seems to confirm that 4MB is the size at which tables grow when using file_per_table.

So, assuming that's the cause, is there any way to prevent the INSERT from waiting on the extent allocation? Similar to innodb_flush_log_at_trx_commit=0 (as I have it set) I would like to avoid any waiting on disk during the INSERT.

I wanted to suggest you to check different innodb_autoextent_increment setting (http://dev.mysql.com/doc/refman/5.5/en/innodb-parameters.html#sysvar_innodb_autoextend_inc...) but it will not help with file per table. 

Eventually new data have to be written to disk, and if there is not enough space in allocated extents new allocation at the filesystem level is unavoidable. If it is slow, maybe some tuning of XFS may help, or some (battery-backed) write cache settings. You can also try to insert a lot of rows into the table during some maintenance period and then delete them all (but leave extents allocated), or tune my.cnf somewhat to try to make writes to disk less often.

In any case, I see no subject for a bug report here - InnoDB works as designed. We can ask for a more flexible autoextend management in case of innodb_file_per_table is set, but this will be a new feature request.

Write cache settings are not an option since this disk is an EBS volume which Amazon manages. Which my.cnf settings are you proposing I tune? I would gladly postpone disk writes more if it meant an INSERT would never block like this.

I look at this behavior as a bug in the implementation, since there is no need to block an INSERT while this allocation takes place if there was no promise of immediate persistence to begin with. But, if the ticket should be changed to a feature request that doesn't make much difference to me.

Using InnoDB on MySQL 5.5.11 on XFS on an EBS 500Gb volume.

Here is the table :

CREATE TABLE  `test`.`event_value` (
  `event_id` varchar(245) CHARACTER SET latin1 NOT NULL,
  `property_id` int(10) unsigned NOT NULL,
  `value` varchar(245) CHARACTER SET latin1 NOT NULL,
  UNIQUE KEY `index` (`event_id`,`property_id`,`value`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC

A simple insert into event_value values (xx, xx, xx); takes 120 sec.
There are only 2 million entries in the table.

Here is my.cnf config file :

key_buffer_size = 1000M
max_allowed_packet = 1M
table_open_cache = 2000
sort_buffer_size = 512M
net_buffer_length = 100K
read_buffer_size = 256M
read_rnd_buffer_size = 512M
myisam_sort_buffer_size = 200M
event_scheduler = 1

innodb_data_home_dir = /var/lib/mysql
#innodb_data_file_path = ibdata1:10M:autoextend
innodb_log_group_home_dir = /var/lib/mysql
innodb_buffer_pool_size = 12000M
innodb_autoextend_increment=1000
innodb_log_file_size = 2000M
innodb_log_buffer_size = 500M
#innodb_flush_log_at_trx_commit = 0
#innodb_lock_wait_timeout = 300
#innodb_flush_method = O_DIRECT
innodb_change_buffering=all
#innodb_thread_concurrency=10

Do you have any explanation to that?
It was doing it with the 5.1 so we tryied the 5.5 without any success...

Please, check if recent server version, 5.5.22, is still affected. If it does, please, send the output of:

uname -a
getconf GNU_LIBC_VERSION

Linux commands.

This was found to be due to packet loss on the local network. Retransmission times in TCP are such that they could quickly add up to the delays seen. It was fixed by patching the kernel to greatly reduce the retransmission time.