MySQL: SELECT GET_LOCK slow/timeout

Question

I am using "Zebra Session" as a replacement for PHP's built-in session management. Zebra Session stores sessions in a MySQL database, and uses "session locking" in order to ensure that data is correctly handled in a scenario with multiple concurrent AJAX requests.

Session locking is implemented by using the SELECT GET_LOCK sql command within Zebra_Session's read function. Usually this works fine, but for the last few days these sql statements have been filling up my slow-log. Some of these statements have timed out at very inopportune moments. Here is an example statement from my slow log:

# Query_time: 60.000150  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SELECT GET_LOCK("session_p494bdabuh56tddmbv19g8i9d7", 60);

I realize that if the session had been previously locked the SELECT GET LOCK command will hang until the lock is released or the command times out, but I can't think of a situation where this would actually occur.

I am using InnoDB - and here is the output of SHOW ENGINE INNODB STATUS:

=====================================
150224 11:55:16 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 38 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 72097 1_second, 72077 sleeps, 7094 10_second, 1251 background, 1250 flush
srv_master_thread log flush and writes: 74597
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 18608, signal count 79708
Mutex spin waits 238350, rounds 331918, OS waits 6599
RW-shared spins 33512, rounds 348663, OS waits 10791
RW-excl spins 15495, rounds 99335, OS waits 1173
Spin rounds per wait: 1.39 mutex, 10.40 RW-shared, 6.41 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 19BC0896
Purge done for trx's n:o < 19BC0836 undo n:o < 0
History list length 999
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 144709, OS thread handle 0x7fdac5fc5700, query id 2569619 localhost root
show engine innodb status
---TRANSACTION 0, not started
MySQL thread id 140098, OS thread handle 0x7fdac6c36700, query id 2510580 38.105.174.189 root
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
101050 OS file reads, 767519 OS file writes, 210806 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 9.37 writes/s, 3.21 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 82794, seg size 82796, 1782 merges
merged operations:
 insert 1718, delete mark 123, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 21249871, node heap has 1239 buffer(s)
11479.22 hash searches/s, 1909.58 non-hash searches/s
---
LOG
---
Log sequence number 53832600944
Log flushed up to   53832600944
Last checkpoint at  53832546459
0 pending log writes, 0 pending chkp writes
159378 log i/o's done, 2.74 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 10989076480; in additional pool allocated 0
Dictionary memory allocated 1152378
Buffer pool size   655360
Free buffers       542707
Database pages     111414
Old database pages 41146
Modified db pages  58
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 65, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 100882, created 10532, written 591116
0.00 reads/s, 0.00 creates/s, 6.45 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 111414, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 22747, id 140577666729728, state: sleeping
Number of rows inserted 415334, updated 148965, deleted 29844, read 1412355001
0.55 inserts/s, 2.05 updates/s, 0.03 deletes/s, 31796.27 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT

Here is the MySQL configuration file (my.cnf):

[mysql]

# CLIENT #
port                           = 3306
socket                         = /var/lib/mysql/mysql.sock

[mysqld]
# GENERAL #
user                           = root
default-storage-engine         = InnoDB
socket                         = /var/lib/mysql/mysql.sock
pid-file                       = /var/lib/mysql/mysql.pid

# SAFETY #
max-allowed-packet             = 16M
max-connect-errors             = 1000000

# DATA STORAGE #
datadir                        = /var/lib/mysql/

# CACHES AND LIMITS #
tmp-table-size                 = 32M
max-heap-table-size            = 32M
query-cache-type               = 1
query-cache-size               = 2M
query-cache-limit              = 2M
max-connections                = 500
thread-cache-size              = 50
open-files-limit               = 65535
table-definition-cache         = 4096
table-open-cache               = 512

# INNODB #
innodb-flush-method            = O_DIRECT
innodb-log-files-in-group      = 2
innodb-log-file-size           = 256M
innodb-flush-log-at-trx-commit = 1
innodb-file-per-table          = 1
innodb-buffer-pool-size        = 10G

# LOGGING #
log-error                      = /var/log/mysql-error.log
log-queries-not-using-indexes  = 0
long_query_time                = 3
slow-query-log                 = 1
slow-query-log-file            = /var/log/mysql-slow.log

I would appreciate some help in getting to the bottom of this.

Answer 1

sorry for that late answer and my bad english :)

currently i am working on a session-hybrid with ZebraSession and my own ClientCookie-Session Class. I nerver heard about GET_LOCK so i started to search for its usage. Now i am stumbled into your post.

Maybe your (or all ZebraSession Users) Problem

a) depends on the MySql Version you are running. b) You are using persistent connections (search in php-manual for persistent mysql conns)

If you visit the following page:

http://techblog.procurios.nl/k/news/view/41405/14863/mysql-get_lock%28%29-explained.html

and scroll down to the last comment (by GDmac - Placed on: 09-10-2012 21:14) you can read about it.

I hope it helped a bit ;)

Answer 2

I've clicked this question because I didn't know there was a GET_LOCK() function in MySQL.

As far as I get it, it just creates a named lock if that lock doesn't exist yet. If it exists, the statement makes the MySQL client session wait until the lock is released.

So, if all your calls uses the same name in this function call (ie: all logs are SELECT GET_LOCK("session_p494bdabuh56tddmbv19g8i9d7", 60)) then it means you have a lot of concurrent requests, and the latest ones must wait for all of these requests to be done before proceeding.

If the name is unique for each session, then the same would apply, but only concerning every user's session individually.

So if I were you, I would check the complete query log of MySQL: pick a dead lock (timedout GET_LOCK) from you slow query log, then look in the general query log to get every GET_LOCK call for the same session name, then look at the queries these MySQL sessions run: they probably are lengthy (because nowadays, you have more data in your DB than in the beginging) and take more than 60seconds. If all the queries do not take about 60seconds, then check if your client code properly releases the locks and properly releases the MySQL session (ie: Java might leave a resource opened to MySQL when an exception/SIGNAL occurs, leaving the MySQL session opened, so leaving the lock unreleased, so locking down all other GET_LOCK calls).