MySQL instance stalling "doing SYNC index"

Question

Problem

An instance of MySQL 5.6.20 running (mostly just) a database with InnoDB tables is exhibiting occasional stalls for all update operations for the duration of 1-4 minutes with all INSERT, UPDATE and DELETE queries remaining in "Query end" state. This obviously is most unfortunate. The MySQL slow query log is logging even the most trivial queries with insane query times, hundreds of them with the same timestamp corresponding to the point in time where the stall has been resolved:

# Query_time: 101.743589  Lock_time: 0.000437 Rows_sent: 0  Rows_examined: 0
SET timestamp=1409573952;
INSERT INTO sessions (redirect_login2, data, hostname, fk_users_primary, fk_users, id_sessions, timestamp) VALUES (NULL, NULL, '192.168.10.151', NULL, 'anonymous', '64ef367018099de4d4183ffa3bc0848a', '1409573850');

And the device statistics are showing increased, although not excessive I/O load in this time frame (in this case updates were stalling 14:17:30 - 14:19:12 according to the timestamps from the statement above):

# sar -d
[...]
02:15:01 PM       DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util
02:16:01 PM    dev8-0     41.53    207.43   1227.51     34.55      0.34      8.28      3.89     16.15
02:17:01 PM    dev8-0     59.41    137.71   2240.32     40.02      0.39      6.53      4.04     24.00
02:18:01 PM    dev8-0    122.08   2816.99   1633.44     36.45      3.84     31.46      1.21      2.88
02:19:01 PM    dev8-0    253.29   5559.84   3888.03     37.30      6.61     26.08      1.85      6.73
02:20:01 PM    dev8-0    101.74   1391.92   2786.41     41.07      1.69     16.57      3.55     36.17
[...]
# sar
[...]
02:15:01 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
02:16:01 PM     all     15.99      0.00     12.49      2.08      0.00     69.44
02:17:01 PM     all     13.67      0.00      9.45      3.15      0.00     73.73
02:18:01 PM     all     10.64      0.00      6.26     11.65      0.00     71.45
02:19:01 PM     all      3.83      0.00      2.42     24.84      0.00     68.91
02:20:01 PM     all     20.95      0.00     15.14      6.83      0.00     57.07

More often than not, I notice in the mysql slow log that the oldest query stalling is an INSERT into a large-ish (~10 M rows) table with a VARCHAR primary key and a full-text search index:

CREATE TABLE `files` (
  `id_files` varchar(32) NOT NULL DEFAULT '',
  `filename` varchar(100) NOT NULL DEFAULT '',
  `content` text,
  PRIMARY KEY (`id_files`),
  KEY `filename` (`filename`),
  FULLTEXT KEY `content` (`content`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

Further investigation (i.e. SHOW ENGINE INNODB STATUS) has shown that it indeed always is an update to a table using full-text indexes which is causing the stall. The respective TRANSACTIONS section of "SHOW ENGINE INNODB STATUS" has entries like these two for the oldest running transactions:

---TRANSACTION 162269409, ACTIVE 122 sec doing SYNC index
6 lock struct(s), heap size 1184, 0 row lock(s), undo log entries 19942
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_1" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_2" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_3" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_4" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_5" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_6" trx id 162269409 lock mode IX
---TRANSACTION 162269408, ACTIVE (PREPARED) 122 sec committing
mysql tables in use 1, locked 1
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 165998, OS thread handle 0x7fe0e239c700, query id 91208956 192.168.10.153 root query end
INSERT INTO files (id_files, filename, content) VALUES ('f19e63340fad44841580c0371bc51434', '1237716_File_70380a686effd6b66592bb5eeb3d9b06.doc', '[...]
TABLE LOCK table `vw`.`files` trx id 162269408 lock mode IX

So there is some heavy full text index action going on there (doing SYNC index) stopping ALL SUBSEQUENT updates to ANY table.

From the logs it seems a bit like the undo log entries number for doing SYNC index is advancing at ~150/s until it reaches 20,000, at which point the operation is done.

The FTS size of this specific table is quite impressive:

# du -c FTS_000000000000224a_00000000000036b9_*
614404  FTS_000000000000224a_00000000000036b9_INDEX_1.ibd
2478084 FTS_000000000000224a_00000000000036b9_INDEX_2.ibd
1576964 FTS_000000000000224a_00000000000036b9_INDEX_3.ibd
1630212 FTS_000000000000224a_00000000000036b9_INDEX_4.ibd
1978372 FTS_000000000000224a_00000000000036b9_INDEX_5.ibd
1159172 FTS_000000000000224a_00000000000036b9_INDEX_6.ibd
9437208 total

although the issue is also triggered by tables with significantly less massive FTS data size like this one:

# du -c FTS_0000000000002467_0000000000003a21_INDEX*
49156   FTS_0000000000002467_0000000000003a21_INDEX_1.ibd
225284  FTS_0000000000002467_0000000000003a21_INDEX_2.ibd
147460  FTS_0000000000002467_0000000000003a21_INDEX_3.ibd
135172  FTS_0000000000002467_0000000000003a21_INDEX_4.ibd
155652  FTS_0000000000002467_0000000000003a21_INDEX_5.ibd
106500  FTS_0000000000002467_0000000000003a21_INDEX_6.ibd
819224  total

The time of the stall in those cases is roughly the same, too. I have opened a bug on bugs.mysql.com so the devs could look into this.

The nature of the stalls first made me suspect log flushing activity to be the culprit and this Percona article on log flushing performance issues with MySQL 5.5 is describing very similar symptoms, but further occurrences have shown that INSERT operations into the single MyISAM table in this database are affected by the stall as well, so this does not seem like an InnoDB-only issue.

Nonetheless, I decided to track the values of Log sequence number and Pages flushed up to from the "LOG" section outputs of SHOW ENGINE INNODB STATUS every 10 seconds. It indeed does look like flushing activity is ongoing during the stall as the spread between the two values is decreasing :

Mon Sep 1 14:17:08 CEST 2014 LSN: 263992263703, Pages flushed: 263973405075, Difference: 18416 K
Mon Sep 1 14:17:19 CEST 2014 LSN: 263992826715, Pages flushed: 263973811282, Difference: 18569 K
Mon Sep 1 14:17:29 CEST 2014 LSN: 263993160647, Pages flushed: 263974544320, Difference: 18180 K
Mon Sep 1 14:17:39 CEST 2014 LSN: 263993539171, Pages flushed: 263974784191, Difference: 18315 K
Mon Sep 1 14:17:49 CEST 2014 LSN: 263993785507, Pages flushed: 263975990474, Difference: 17377 K
Mon Sep 1 14:17:59 CEST 2014 LSN: 263994298172, Pages flushed: 263976855227, Difference: 17034 K
Mon Sep 1 14:18:09 CEST 2014 LSN: 263994670794, Pages flushed: 263978062309, Difference: 16219 K
Mon Sep 1 14:18:19 CEST 2014 LSN: 263995014722, Pages flushed: 263983319652, Difference: 11420 K
Mon Sep 1 14:18:30 CEST 2014 LSN: 263995404674, Pages flushed: 263986138726, Difference: 9048 K
Mon Sep 1 14:18:40 CEST 2014 LSN: 263995718244, Pages flushed: 263988558036, Difference: 6992 K
Mon Sep 1 14:18:50 CEST 2014 LSN: 263996129424, Pages flushed: 263988808179, Difference: 7149 K
Mon Sep 1 14:19:00 CEST 2014 LSN: 263996517064, Pages flushed: 263992009344, Difference: 4402 K
Mon Sep 1 14:19:11 CEST 2014 LSN: 263996979188, Pages flushed: 263993364509, Difference: 3529 K
Mon Sep 1 14:19:21 CEST 2014 LSN: 263998880477, Pages flushed: 263993558842, Difference: 5196 K
Mon Sep 1 14:19:31 CEST 2014 LSN: 264001013381, Pages flushed: 263993568285, Difference: 7270 K
Mon Sep 1 14:19:41 CEST 2014 LSN: 264001933489, Pages flushed: 263993578961, Difference: 8158 K
Mon Sep 1 14:19:51 CEST 2014 LSN: 264004225438, Pages flushed: 263993585459, Difference: 10390 K

And at 14:19:11 the spread has reached its minimum, so flushing activity seems to have ceased here, just coinciding with the end of the stall. But these points made me dismiss the InnoDB log flushing as the cause:

• for the flushing operation to block all updates to the database it needs to be "synchronous", which means that 7/8 of the log space has to be occupied
• it would be preceded by an "asynchronous" flushing phase starting at innodb_max_dirty_pages_pct fill level - which I am not seeing
• the LSNs keep increasing even during the the stall, so log activity is not ceasing completely
• MyISAM table INSERTs are affected as well
• the page_cleaner thread for adaptive flushing seems to do its work and flush the logs without causing DML queries to stop:

^{(numbers are ([Log Sequence Number] - [Pages flushed up to]) / 1024 from SHOW ENGINE INNODB STATUS)}

The issue seems somewhat alleviated by setting innodb_adaptive_flushing_lwm=1, forcing the page cleaner to do more work than before.

The error.log has no entries coinciding with the stalls. SHOW INNODB STATUS excerpts after approximately 24 hours of operation look like this:

SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 789330
OS WAIT ARRAY INFO: signal count 1424848
Mutex spin waits 269678, rounds 3114657, OS waits 65965
RW-shared spins 941620, rounds 20437223, OS waits 442474
RW-excl spins 451007, rounds 13254440, OS waits 215151
Spin rounds per wait: 11.55 mutex, 21.70 RW-shared, 29.39 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
2014-09-03 10:33:55 7fe0e2e44700
[...]
--------
FILE I/O
--------
[...]
932635 OS file reads, 2117126 OS file writes, 1193633 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 17.00 writes/s, 1.20 fsyncs/s
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Main thread process no. 54745, id 140604272338688, state: sleeping
Number of rows inserted 528904, updated 1596758, deleted 99860, read 3325217158
5.40 inserts/s, 10.40 updates/s, 0.00 deletes/s, 122969.21 reads/s

So, yes, the database does have deadlocks, but they are very infrequent (the "latest" has been handled around 11 hours before the stats have been read).

I tried tracking the "SEMAPHORES" section values over a period of time, especially in a situation of normal operation and during a stall (I wrote a small script checking the MySQL server's processlist and running a couple of diagnostic commands into a log output in case of an obvious stall). As the numbers have been taken over different time frames, I have normalized the results to events/second:

                          normal   stall
                          1h avg  1m avg
OS WAIT ARRAY INFO: 
    reservation count      5,74    1,00
    signal count          24,43    3,17
Mutex spin waits           1,32    5,67
    rounds                 8,33   25,85
    OS waits               0,16    0,43
RW-shared spins            9,52    0,76
    rounds               140,73    13,39
    OS waits               2,60    0,27
RW-excl spins              6,36    1,08
    rounds               178,42   16,51
    OS waits               2,38    0,20

I am not quite sure about what I am seeing here. Most numbers have dropped by an order of magnitude - probably due to ceased update operations, "Mutex spin waits" and "Mutex spin rounds" however have both increased by the factor of 4.

Investigating this further, the list of mutexes (SHOW ENGINE INNODB MUTEX) has ~480 mutex entries listed both in normal operation as well as during a stall. I have enabled innodb_status_output_locks to see if it is going to give me more detail.

Configuration variables

(I've tinkered with most of them without definite success):

mysql> show global variables where variable_name like 'innodb_adaptive_flush%';
+------------------------------+-------+
| Variable_name                | Value |
+------------------------------+-------+
| innodb_adaptive_flushing     | ON    |
| innodb_adaptive_flushing_lwm | 1     |
+------------------------------+-------+
mysql> show global variables where variable_name like 'innodb_max_dirty_pages_pct%';
+--------------------------------+-------+
| Variable_name                  | Value |
+--------------------------------+-------+
| innodb_max_dirty_pages_pct     | 50    |
| innodb_max_dirty_pages_pct_lwm | 10    |
+--------------------------------+-------+
mysql> show global variables where variable_name like 'innodb_log_%';
+-----------------------------+-----------+
| Variable_name               | Value     |
+-----------------------------+-----------+
| innodb_log_buffer_size      | 8388608   |
| innodb_log_compressed_pages | ON        |
| innodb_log_file_size        | 268435456 |
| innodb_log_files_in_group   | 2         |
| innodb_log_group_home_dir   | ./        |
+-----------------------------+-----------+
mysql> show global variables where variable_name like 'innodb_double%';
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| innodb_doublewrite | ON    |
+--------------------+-------+
mysql> show global variables where variable_name like 'innodb_buffer_pool%';
+-------------------------------------+----------------+
| Variable_name                       | Value          |
+-------------------------------------+----------------+
| innodb_buffer_pool_dump_at_shutdown | OFF            |
| innodb_buffer_pool_dump_now         | OFF            |
| innodb_buffer_pool_filename         | ib_buffer_pool |
| innodb_buffer_pool_instances        | 8              |
| innodb_buffer_pool_load_abort       | OFF            |
| innodb_buffer_pool_load_at_startup  | OFF            |
| innodb_buffer_pool_load_now         | OFF            |
| innodb_buffer_pool_size             | 29360128000    |
+-------------------------------------+----------------+
mysql> show global variables where variable_name like 'innodb_io_capacity%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| innodb_io_capacity     | 200   |
| innodb_io_capacity_max | 2000  |
+------------------------+-------+
mysql> show global variables where variable_name like 'innodb_lru_scan_depth%';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| innodb_lru_scan_depth | 1024  |
+-----------------------+-------+

Things already tried

• disabling the query cache by SET GLOBAL query_cache_size=0
• increasing innodb_log_buffer_size to 128M
• playing around with innodb_adaptive_flushing, innodb_max_dirty_pages_pct and the respective _lwm values (they were set to defaults prior to my changes)
• increasing innodb_io_capacity (2000) and innodb_io_capacity_max (4000)
• setting innodb_flush_log_at_trx_commit = 2
• running with innodb_flush_method = O_DIRECT (yes, we do use a SAN with a persistent write cache)
• setting the /sys/block/sda/queue/scheduler to noop or deadline

Answer 1

We were seeing the same issue on two servers on versions 5.6.12 and 5.6.16 running on Windows, with a pair of slaves each. We were stumped, like you, for almost two months.

Solution:

set global binlog_order_commits = 0;

See https://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#sysvar_binlog_order_commits for details of the variable.

Explanation:

InnoDB full-text uses a cache (by default 8M in size) containing changes that need to be applied to the actual full-text index on disk.

Once the cache fills up, a couple of transactions are created to perform the work of merging the data that was contained in the cache - this tends to be a large amount of random IO, so unless your entire full-text index can be loaded into the buffer pool, it's a long and slow transaction.

With binlog_order_commits set to true, all transactions containing inserts and updates, started after the long-running fts_sync_index transaction, must wait until it has completed before they can commit.

This is only an issue if binary logging is enabled

Answer 2

Let me maybe try and describe the historical problem with log flushing and how adaptive flushing works:

• The redo logs are a ring buffer design. They are only ever written to (never read from in normal operation) and provide in crash recovery. I like to describe a ring buffer as similar to the tread of a tank.

• InnoDB will not be able to overwrite log file space if it contains changes that have not been modified on disk yet. So historically, what would happen is that InnoDB would attempt a certain amount of work per second (configured by innodb_io_capacity) and if that was not enough, you would reach full log space. A stall would occur as synchronous flushing needed to occur to suddenly free space, making what is usually a background task suddenly foreground.

• To address this issue, adaptive flushing was introduced. Where by at 10% (default) log space consumed, the background work starts getting progressively more aggressive. The aim of this is rather than a sudden stall, you have more of a 'short dip' in performance.

• Independent of adaptive flushing, it is important to have sufficient log space for your workload (innodb_log_file_size values of 4G are now quite safe), and make sure that innodb_io_capacity and innodb_lru_scan_depth are set to realistic values. The adaptive flushing 10% innodb_adaptive_flushing_lwm is something you don't stretch very far into, it's more of a defence mechanism against out of space.

Answer 3

Just to bring InnoDB some contention relief, you could play with innodb_purge_threads.

Before MySQL 5.6, the Master Thread did all the page flushing. In MySQL 5.6, a separate thread can handle it. The default value for innodb_purge_threads in MySQL 5.5 was 0 with a maximum of 1. In MySQL 5.6, the default is 1 with a maximum of 32.

What does setting innodb_purge_threads actually do ?

Non-zero values runs the purge operation in one or more background threads, which can reduce internal contention within InnoDB, improving scalability. Increasing the value to greater than 1 creates that many separate purge threads, which can improve efficiency on systems where DML operations are performed on multiple tables.

I would start off by setting innodb_purge_threads to 4 and see if InnoDB page flushing is reduced.

UPDATE 2014-09-02 12:33 EDT

Morgan Tocker pointed out in the comment below that the page cleaner is the victim and MySQL 5.7 can address it. Notwithstanding, your situation is in MySQL 5.6.

I took a second look and noticed that you have innodb_max_dirty_pages_pct at 50.

The default for innodb_max_dirty_pages_pct in MySQL 5.5+ is 75. Lowering it would increase the incidence of stalls from flushing. I would do three(3) things

• Increase innodb_max_dirty_pages_pct to 90 (That was the default for MySQL 5.1)
• Set innodb_max_dirty_pages_pct_lwm = 0 (the default) or remove it from my.cnf
• Increase innodb_log_buffer_size to 128M (half of your innodb_log_file_size)

UPDATE 2014-09-03 11:06 EDT

You may need to change your flushing behavior

Try setting the following dynamically

SET GLOBAL flush = 1;
SET GLOBAL flush_time = 10;

These variables, flush and flush_time, will make flushing more aggressive by closing open file handles on tables every 10 seconds. MyISAM can definitely benefit from it because it does not cache data. All writes to MyISAM tables require full table locks, followed by atomic writes, and depend on the OS for disk changes.

Flushing InnoDB that way would require a mysql restart. The options to see are innodb_flush_log_at_trx_commit and innodb_flush_method.

Before you restart, please add these

[mysqld]
flush = 1
flush_time = 10
innodb_flush_log_at_trx_commit = 0
innodb_flush_method = O_DIRECT

Before going this route, you should check if journaling is an issue. I saw this cool mysqlperformanceblog post on O_DIRECT being faked because of the kernel. The same post also mentions MyISAM being affected.

I wrote about this post before : ib_logfile opened with O_SYNC when innodb_flush_method=O_DSYNC

Give it a Try !!!