MySQL: Very slow update/insert/delete queries hanging on "query end" step

Question

I have a large and heavy loaded mysql database which performs quite fast at times, but some times get terribly slow. All tables are InnoDB, server has 32GB of RAM and database size is about 40GB.

Top 20 queries in my slow_query_log are update, insert and delete queries and I cannot understand why they are so slow (up to 120 seconds sometimes!)

Here is the most frequent query:

UPDATE comment_fallows set comment_cnt_new = 0 WHERE user_id = 1;

Profiling results:

mysql> set profiling = 1;
Query OK, 0 rows affected (0.00 sec)

mysql> update comment_fallows set comment_cnt_new = 0 where user_id = 1;
Query OK, 0 rows affected (2.77 sec)
Rows matched: 18  Changed: 0  Warnings: 0

mysql> show profile for query 1;
+---------------------------+----------+
| Status                    | Duration |
+---------------------------+----------+
| starting                  | 0.000021 |
| checking permissions      | 0.000004 |
| Opening tables            | 0.000010 |
| System lock               | 0.000004 |
| init                      | 0.000041 |
| Searching rows for update | 0.000084 |
| Updating                  | 0.000055 |
| end                       | 0.000010 |
| query end                 | 2.766245 |
| closing tables            | 0.000007 |
| freeing items             | 0.000013 |
| logging slow query        | 0.000003 |
| cleaning up               | 0.000002 |
+---------------------------+----------+
13 rows in set (0.00 sec)

I am using master/server replication, so the binary log is enabled. I've fallowed one advice I've found on the internet and set flush_log_at_trx_commit to 0 but it did not make any difference:

mysql> show variables like '%trx%';
+-------------------------------------------+-------+
| Variable_name                             | Value |
+-------------------------------------------+-------+
| innodb_flush_log_at_trx_commit            | 0     |
| innodb_use_global_flush_log_at_trx_commit | ON    |
+-------------------------------------------+-------+

The table structure:

CREATE TABLE `comment_fallows` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `user_id` int(11) NOT NULL,
  `part_id` int(11) DEFAULT NULL,
  `article_id` int(11) DEFAULT NULL,
  `request_id` int(11) DEFAULT NULL,
  `comment_cnt` int(10) unsigned NOT NULL,
  `comment_cnt_new` int(10) unsigned NOT NULL DEFAULT '0',
  `last_comment_date` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`),
  KEY `user_id` (`user_id`,`last_comment_date`),
  KEY `part_id` (`part_id`),
  KEY `last_comment_date` (`last_comment_date`),
  KEY `request_id` (`request_id`),
  CONSTRAINT `comment_fallows_ibfk_1` FOREIGN KEY (`user_id`) REFERENCES `users` (`id`) ON DELETE CASCADE,
  CONSTRAINT `comment_fallows_ibfk_2` FOREIGN KEY (`part_id`) REFERENCES `fanfic_parts` (`id`) ON DELETE CASCADE,
  CONSTRAINT `comment_fallows_ibfk_3` FOREIGN KEY (`request_id`) REFERENCES `requests` (`id`) ON DELETE CASCADE
) ENGINE=InnoDB AUTO_INCREMENT=2239419 DEFAULT CHARSET=utf8

And all the innodb settings (server has 32 GB of RAM):

mysql> show variables like '%innodb%';
+-------------------------------------------+------------------------+
| Variable_name                             | Value                  |
+-------------------------------------------+------------------------+
| have_innodb                               | YES                    |
| ignore_builtin_innodb                     | OFF                    |
| innodb_adaptive_flushing                  | ON                     |
| innodb_adaptive_flushing_method           | estimate               |
| innodb_adaptive_hash_index                | ON                     |
| innodb_adaptive_hash_index_partitions     | 1                      |
| innodb_additional_mem_pool_size           | 16777216               |
| innodb_autoextend_increment               | 8                      |
| innodb_autoinc_lock_mode                  | 1                      |
| innodb_blocking_buffer_pool_restore       | OFF                    |
| innodb_buffer_pool_instances              | 1                      |
| innodb_buffer_pool_restore_at_startup     | 0                      |
| innodb_buffer_pool_shm_checksum           | ON                     |
| innodb_buffer_pool_shm_key                | 0                      |
| innodb_buffer_pool_size                   | 21474836480            |
| innodb_change_buffering                   | all                    |
| innodb_checkpoint_age_target              | 0                      |
| innodb_checksums                          | ON                     |
| innodb_commit_concurrency                 | 0                      |
| innodb_concurrency_tickets                | 500                    |
| innodb_corrupt_table_action               | assert                 |
| innodb_data_file_path                     | ibdata1:10M:autoextend |
| innodb_data_home_dir                      |                        |
| innodb_dict_size_limit                    | 0                      |
| innodb_doublewrite                        | ON                     |
| innodb_doublewrite_file                   |                        |
| innodb_fake_changes                       | OFF                    |
| innodb_fast_checksum                      | OFF                    |
| innodb_fast_shutdown                      | 1                      |
| innodb_file_format                        | Antelope               |
| innodb_file_format_check                  | ON                     |
| innodb_file_format_max                    | Antelope               |
| innodb_file_per_table                     | ON                     |
| innodb_flush_log_at_trx_commit            | 0                      |
| innodb_flush_method                       |                        |
| innodb_flush_neighbor_pages               | area                   |
| innodb_force_load_corrupted               | OFF                    |
| innodb_force_recovery                     | 0                      |
| innodb_ibuf_accel_rate                    | 100                    |
| innodb_ibuf_active_contract               | 1                      |
| innodb_ibuf_max_size                      | 10737401856            |
| innodb_import_table_from_xtrabackup       | 0                      |
| innodb_io_capacity                        | 10000                  |
| innodb_kill_idle_transaction              | 0                      |
| innodb_large_prefix                       | OFF                    |
| innodb_lazy_drop_table                    | 0                      |
| innodb_lock_wait_timeout                  | 120                    |
| innodb_locks_unsafe_for_binlog            | OFF                    |
| innodb_log_block_size                     | 512                    |
| innodb_log_buffer_size                    | 8388608                |
| innodb_log_file_size                      | 268435456              |
| innodb_log_files_in_group                 | 3                      |
| innodb_log_group_home_dir                 | ./                     |
| innodb_max_dirty_pages_pct                | 90                     |
| innodb_max_purge_lag                      | 0                      |
| innodb_mirrored_log_groups                | 1                      |
| innodb_old_blocks_pct                     | 37                     |
| innodb_old_blocks_time                    | 0                      |
| innodb_open_files                         | 300                    |
| innodb_page_size                          | 16384                  |
| innodb_purge_batch_size                   | 20                     |
| innodb_purge_threads                      | 1                      |
| innodb_random_read_ahead                  | OFF                    |
| innodb_read_ahead                         | linear                 |
| innodb_read_ahead_threshold               | 56                     |
| innodb_read_io_threads                    | 8                      |
| innodb_recovery_stats                     | OFF                    |
| innodb_recovery_update_relay_log          | OFF                    |
| innodb_replication_delay                  | 0                      |
| innodb_rollback_on_timeout                | OFF                    |
| innodb_rollback_segments                  | 128                    |
| innodb_show_locks_held                    | 10                     |
| innodb_show_verbose_locks                 | 0                      |
| innodb_spin_wait_delay                    | 6                      |
| innodb_stats_auto_update                  | 1                      |
| innodb_stats_method                       | nulls_equal            |
| innodb_stats_on_metadata                  | ON                     |
| innodb_stats_sample_pages                 | 8                      |
| innodb_stats_update_need_lock             | 1                      |
| innodb_strict_mode                        | OFF                    |
| innodb_support_xa                         | ON                     |
| innodb_sync_spin_loops                    | 30                     |
| innodb_table_locks                        | ON                     |
| innodb_thread_concurrency                 | 16                     |
| innodb_thread_concurrency_timer_based     | OFF                    |
| innodb_thread_sleep_delay                 | 10000                  |
| innodb_use_global_flush_log_at_trx_commit | ON                     |
| innodb_use_native_aio                     | ON                     |
| innodb_use_sys_malloc                     | ON                     |
| innodb_use_sys_stats_table                | OFF                    |
| innodb_version                            | 1.1.8-rel25.1          |
| innodb_write_io_threads                   | 8                      |
+-------------------------------------------+------------------------+
92 rows in set (0.00 sec)

I've been struggling with this problem for weeks and would be very greatfull for any advice on how to solve this problem.

Why could my update, insert and delete queries be so slow on query end step?

update

I have disabled query cache, but update, insert and delete queries are still very very slow (nothing changed)

show variables like '%cache%';
+------------------------------+----------------------+
| Variable_name                | Value                |
+------------------------------+----------------------+
| binlog_cache_size            | 4194304              |
| binlog_stmt_cache_size       | 32768                |
| have_query_cache             | YES                  |
| key_cache_age_threshold      | 300                  |
| key_cache_block_size         | 1024                 |
| key_cache_division_limit     | 100                  |
| max_binlog_cache_size        | 18446744073709547520 |
| max_binlog_stmt_cache_size   | 18446744073709547520 |
| metadata_locks_cache_size    | 1024                 |
| query_cache_limit            | 16777216             |
| query_cache_min_res_unit     | 4096                 |
| query_cache_size             | 0                    |
| query_cache_strip_comments   | OFF                  |
| query_cache_type             | ON                   |
| query_cache_wlock_invalidate | OFF                  |
| stored_program_cache         | 256                  |
| table_definition_cache       | 400                  |
| table_open_cache             | 2048                 |
| thread_cache_size            | 8                    |
+------------------------------+----------------------+

Answer 1

It is probably due to slow disk writes.

In our case it was because Debian GNU/Linux running mysqld was virtualised in Hyper-V, and even if it was given SSD storage hdparm -t was giving terrible results (10-20MB/s instead of 600MB/s that it gets on raw hardware)

Answer 2

I have the problem in our test environment(Not set up by DBA).Finally I find there is one conf in my.cnf : sync_binlog=1. I change this conf to 0,and it works. You can have a try.

Answer 3

It may be a problem of hardware if you are using DELL server. I resolved this command.

/opt/dell/srvadmin/bin/omconfig storage vdisk action=changepolicy controller=0 vdisk=0 writepolicy=fwb

Answer 4

Try setting values:

innodb_flush_log_at_trx_commit=2
innodb_flush_method=O_DIRECT (for non-windows machine)
innodb_buffer_pool_size=25GB (currently it is close to 21GB)
innodb_doublewrite=0
innodb_support_xa=0
innodb_thread_concurrency=0...1000 (try different values, beginning with 200)

References:

MySQL docs for description of different variables.

MySQL Server Setting Tuning

MySQL Performance Optimization basics

Hope it helps...

Answer 5

Try starting tuning your innodb_buffer_pool_instances according the innodb_buffer_pool_size

Firs of all I think you can increase significantly your innodb_buffer_pool_size...

innodb_buffer_pool_instances sysvar

The size in bytes of the memory buffer InnoDB uses to cache data and indexes of its tables. The default value is 128MB, increased from a historical default of 8MB. The maximum value depends on the CPU architecture, 32-bit or 64-bit. For 32-bit systems, the CPU architecture and operating system sometimes impose a lower practical maximum size.

The larger you set this value, the less disk I/O is needed to access data in tables. On a dedicated database server, you may set this to up to 80% of the machine physical memory size. Be prepared to scale back this value if these other issues occur...

Then you can tune the innodb_buffer_pool_instances, using multiple buffer pools was very important, yuo can read a good test case here:

MySQL Workload test

Answer 6

There appears to be a bug with how MySQL handles the query cache which causes similar behaviour (see http://bugs.mysql.com/bug.php?id=28382).

What is basically happening is that the cache needs to be updated following any query that modifies data (INSERT, UPDATE, DELETE). With a large cache it is taking a long time to do this, if the cache is smaller then its faster.

So the work-around until the engine is fixed is to decrease the cache size.