MySQL: SELECT GET_LOCK slow/timeout

configurationlockingMySQLPHPsession

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.

Best Answer

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 ;)