Diagnosing periodic MySQL hiccups.
Hi all,
We are running MySql 5.5.27 as our production database, and it experiences periodic hiccups in throughput. Normally it is manifested as server-wide stalls of many queries with the following symptoms:
InnoDB status is full of lock contention reports like this:
--Thread 1478437184 has waited at btr0cur.c line 530 for 1.00 seconds the semaphore:
S-lock on RW-latch at 0x2ab82668f7b8 created in file dict0dict.c line 1726
a writer (thread id 1490684224) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0cur.c line 530
The thread that causes contention usually looks like this:
--Thread 1490684224 has waited at btr0cur.c line 523 for 1.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x2ab82668f7b8 created in file dict0dict.c line 1726
a writer (thread id 1490684224) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0cur.c line 530
Last time write locked in file /local/mysqlbuild/mysql-5.5.27.R1/storage/innobase/btr/btr0cur.c line 523
Is it normal for a thread to wait on itself by the way? Is it just a reporting problem?
The thread that keeps the lock always runs a mutating statement:
---TRANSACTION 132A6BEE44, ACTIVE 1 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 5960718079, OS thread handle 0x58da0940, query id 111146225298 ip-10-66-21-195.ec2.internal 10.66.21.195 web_server Updating
/* prod-ws079.ec2,7612 */ /* okvstore.write name */ update okvstore_text set value = 'xxxxxx' where object_id = 9158863941107 and property_id = 28
In this case the same row was updated 500ms before the event, and didn't cause any problems.
Redo log is nowhere near full (~60% in this case).
We don't see any surge in InnoDB reads or writes as reported by Innodb_data_{read,written}.
Yet, InnoDB status reports a lot of pending writes (what are the numbers is braces, by the way?):
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 89 [4, 4, 2, 1, 22, 1, 7, 16, 14, 3, 5, 3, 5, 2]
The way I interpret it that there is sudden hiccup of the underlying I/O system. Does it sound plausible? Or can it be caused by the sudden change of MySQL load/behavior? What else can I look at to investigate the issue further?
Thanks!