0

Server Details

  • MySQL 5.6.22
  • 256GB RAM
  • 4TB SSD
  • 32 Core

Background Information

There is a delete process which does about 3 deletes per second. 2-3k QPS per second. Mostly SELECTs. No long running queries.

Problem

At times, queries start running in the 1-3 second range instead of milliseconds. Most of them at the "Waiting for query cache lock".

SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count -2033262178
--Thread 6060 has waited at row0purge.cc line 754 for 1.00 seconds the semaphore:
S-lock on RW-latch at 00007FF62B1C9F60 created in file dict0dict.cc line 983
a writer (thread id 9580) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 754
Last time write locked in file ..\..\..\mysqlcom-pro-5.6.22\storage\innobase\row\row0mysql.cc line 3838
--Thread 5204 has waited at row0purge.cc line 754 for 1.00 seconds the semaphore:
S-lock on RW-latch at 00007FF62B1C9F60 created in file dict0dict.cc line 983
a writer (thread id 9580) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 754
Last time write locked in file ..\..\..\mysqlcom-pro-5.6.22\storage\innobase\row\row0mysql.cc line 3838
--Thread 5556 has waited at row0purge.cc line 754 for 1.00 seconds the semaphore:
S-lock on RW-latch at 00007FF62B1C9F60 created in file dict0dict.cc line 983
a writer (thread id 9580) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 754
Last time write locked in file ..\..\..\mysqlcom-pro-5.6.22\storage\innobase\row\row0mysql.cc line 3838
--Thread 6112 has waited at row0purge.cc line 754 for 1.00 seconds the semaphore:
S-lock on RW-latch at 00007FF62B1C9F60 created in file dict0dict.cc line 983
a writer (thread id 9580) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 754
Last time write locked in file ..\..\..\mysqlcom-pro-5.6.22\storage\innobase\row\row0mysql.cc line 3838
--Thread 5868 has waited at dict0dict.cc line 1037 for 1.00 seconds the semaphore:
Mutex at 000000279A10EDA8 created file dict0dict.cc line 974, lock var 1
waiters flag 1
--Thread 5236 has waited at buf0flu.cc line 2077 for 0.00 seconds the semaphore:
Mutex at 00000000345B7F68 created file buf0buf.cc line 1270, lock var 1
waiters flag 1
OS WAIT ARRAY INFO: signal count -1213535755
Mutex spin waits 8166969384, rounds 34032056620, OS waits 750640991
RW-shared spins 3891056500, rounds 50813966471, OS waits 764118585
RW-excl spins 9963649634, rounds 77579501565, OS waits 718551543
Spin rounds per wait: -80.46 mutex, -125.80 RW-shared, 56.47 RW-excl

Question

I am wondering what could be the cause. I'd understand if it was consistent since the DELETE process is ongoing but it is very sporadic. The semaphores that relate to dict0dict.cc and row0purge.cc make me assume that it is related to DELETES that is causing contention. Any thoughts on this would be great.

MYoussef
  • 46
  • 7

1 Answers1

-1

Query cache lock means there is a contention with query cache, it seems delete SQL is invalidating the query cache. Normally I keep query cache off to avoid such issues. Please try disabling the query cache.

Neo
  • 1
  • 1
  • Yes the query cache is a point of contention but it has more advantages than disadvantages in this situation. Turning it off would be a bigger issue. My question is related to the semaphores and what those source files relate to. – MYoussef Mar 11 '16 at 14:31
  • 1
    At least keep `query_cache_size` < 100M -- when a purge is needed (that is, on _every_ `DELETE`), it must scan the entire QC to see what needs purging. Bigger == slower. – Rick James Mar 11 '16 at 19:05
  • Thanks @RickJames I just changed the size from 256M to 100M. I'll wait to see how much the cache actually fills up and see if I can lower it more. – MYoussef Mar 11 '16 at 20:10
  • `SHOW GLOBAL STATUS LIKE 'Qc%';`, together with `SHOW VARIABLES LIKE 'query%';` give some cryptic clues. – Rick James Mar 11 '16 at 20:14
  • @RickJames Just some early observations .. I notice some single row inserts are taking more than a second now. `innodb_max_dirty_pages_pct` is set to 50 – MYoussef Mar 11 '16 at 20:29
  • Also `innodb_flush_log_at_trx_commit = 2` , `innodb_doublewrite = 1` , `sync_binlog = 0` – MYoussef Mar 11 '16 at 20:36
  • `innodb_max_dirty_pages_pct` should be larger. 90 and 75 are typical. 50 _probably_ leads to more I/O because of flushing changes faster. – Rick James Mar 11 '16 at 21:19
  • How many "single row inserts" per second? Do you have lots of indexes? What are the values of `innodb_change%`? – Rick James Mar 11 '16 at 21:24