Sample Header Ad - 728x90

MySQL: SELECT GET_LOCK slow/timeout

0 votes
1 answer
7714 views
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:cur, unzip sum:cur -------------- 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.
Asked by Mike Furlender (291 rep)
Feb 24, 2015, 05:00 PM
Last activity: Mar 18, 2025, 09:02 PM