List:General Discussion« Previous MessageNext Message »
From:Grover Blue Date:September 22 2009 7:59pm
Subject:SQL Error: 1205 - Lock exception with a tuned MySQL install
View as plain text  
I'm trying to get to the bottom of the 1205 exceptions I've been getting.  I
understand it's a lock, but I don't understand exactly why it's happening
and how I can fix (either by recoding, table restructure, or mysql
configuration).  Also, I should note that I'm a Java developer using JPA,
and not a MySQL admin, but I'll provide as much info as I can.  Any help
would be appreciated.

MySQL config:
[client]
port            = 3306
socket          = /tmp/mysql.sock

[mysqld]
port            = 3306
socket          = /tmp/mysql.sock
skip-locking
key_buffer_size = 384M
max_allowed_packet = 1M
table_open_cache = 512
sort_buffer_size = 2M
read_buffer_size = 2M
read_rnd_buffer_size = 8M
myisam_sort_buffer_size = 64M
thread_cache_size = 8
query_cache_size = 32M
thread_concurrency = 16

innodb_additional_mem_pool_size = 16M
innodb_buffer_pool_size = 512M
innodb_file_io_threads = 4
innodb_thread_concurrency = 16
innodb_flush_log_at_trx_commit = 2
innodb_log_buffer_size = 8M
innodb_log_file_size = 128M
innodb_max_dirty_pages_pct = 90
innodb_lock_wait_timeout = 120
innodb_flush_method = O_DIRECT

[mysqldump]
quick
max_allowed_packet = 16M

[mysql]
no-auto-rehash

[myisamchk]
key_buffer_size = 256M
sort_buffer_size = 256M
read_buffer = 2M
write_buffer = 2M

[mysqlhotcopy]
interactive-timeout


Most of the configuration above is based on articles provided at
mysqlperformanceblog.com.

Here is a count of records in my tables:
mysql> select count(*) from EXTERNALIPADDRESSBINDING;
+----------+
| count(*) |
+----------+
| 135846 |
+----------+
1 row in set (0.08 sec)

mysql> select count(*) from INTERNALIPADDRESSBINDING;
+----------+
| count(*) |
+----------+
| 3865629 |
+----------+
1 row in set (1.33 sec)

mysql> select count(*) from NETWORKUSERBINDING;
+----------+
| count(*) |
+----------+
| 82601 |
+----------+
1 row in set (0.20 sec)


Next, I took a look at the InnoDB status (not during the lock,
unfortunately):
mysql> SHOW INNODB STATUS;
| InnoDB |      |
=====================================
090922 15:03:50 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 35 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 574703, signal count 560578
Mutex spin waits 0, rounds 222148828, OS waits 40830
RW-shared spins 1023334, OS waits 398354; RW-excl spins 540552, OS waits
21948
------------
TRANSACTIONS
------------
Trx id counter 0 2102243
Purge done for trx's n:o < 0 2102003 undo n:o < 0 0
History list length 3
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 2100999, not started, OS thread id 34370254288
MySQL thread id 313, query id 660301 localhost root
SHOW INNODB STATUS
---TRANSACTION 0 2102240, not started, OS thread id 34370247888
MySQL thread id 15, query id 659542 localhost 127.0.0.1 guser
---TRANSACTION 0 2102208, not started, OS thread id 34370247088
MySQL thread id 13, query id 659408 localhost 127.0.0.1 guser
---TRANSACTION 0 2102219, not started, OS thread id 34370246688
MySQL thread id 12, query id 659527 localhost 127.0.0.1 guser
---TRANSACTION 0 2102239, not started, OS thread id 34370245488
MySQL thread id 8, query id 659454 localhost 127.0.0.1 guser
---TRANSACTION 0 2102238, not started, OS thread id 34370245088
MySQL thread id 9, query id 659453 localhost 127.0.0.1 guser
---TRANSACTION 0 2102195, ACTIVE 48 sec, OS thread id 34370253488
starting index read, thread declared inside InnoDB 266
mysql tables in use 3, locked 0
31 lock struct(s), heap size 6752, 176 row lock(s), undo log entries 224
MySQL thread id 218, query id 660300 localhost 127.0.0.1 guser
Sending data
SELECT t0.ID, t0.BINDTIMESTAMP, t0.MACADDRESS_MACADDRESS,
t0.internalIpAddress_ipAddress FROM INTERNALIPADDRESSBINDING t0,
MACADDRESS t2, INTERNALIPADDRESS t1 WHERE ((((t1.IPADDRESS =
'4.4.4.4') AND (t2.MACADDRESS = 'ZZ:ZZ:ZZ:ZZ:ZZ:ZZ')) AND
(t0.BINDTIMESTAMP = '2009-09-22 15:01:53.0')) AND ((t1.IPADDRESS =
t0.internalIpAddress_ipAddress) AND (t2.MACADDRESS =
t0.MACADDRESS_MACADDRESS)))
Trx read view will not see trx with id >= 0 2102196, sees < 0 2101972
---TRANSACTION 0 2101972, ACTIVE 102 sec, OS thread id 34370246288 ,
thread declared inside InnoDB 294
mysql tables in use 3, locked 0
38 lock struct(s), heap size 6752, 144 row lock(s), holds adaptive hash
latch, undo log entries 255
MySQL thread id 11, query id 660297 localhost 127.0.0.1 guser
Sending data
SELECT t0.ID, t0.BINDTIMESTAMP, t0.MACADDRESS_MACADDRESS,
t0.internalIpAddress_ipAddress FROM INTERNALIPADDRESSBINDING t0,
MACADDRESS t2, INTERNALIPADDRESS t1 WHERE ((((t1.IPADDRESS =
'3.3.3.3') AND (t2.MACADDRESS = 'CC:CC:CC:CC:CC:CC')) AND
(t0.BINDTIMESTAMP = '2009-09-22 14:57:33.0')) AND ((t1.IPADDRESS =
t0.internalIpAddress_ipAddress) AND (t2.MACADDRESS =
t0.MACADDRESS_MACADDRESS)))
Trx read view will not see trx with id >= 0 2101973, sees < 0 2101973
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
206266 OS file reads, 88034 OS file writes, 16196 OS fsyncs
138.60 reads/s, 16961 avg bytes/read, 2.57 writes/s, 1.31 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5, seg size 7,
74 inserts, 74 merged recs, 55 merges
Hash table size 1106407, node heap has 5899 buffer(s)
207110.57 hash searches/s, 4830.43 non-hash searches/s
---
LOG
---
Log sequence number 0 3781613349
Log flushed up to   0 3781611114
Last checkpoint at  0 3781560806
0 pending log writes, 0 pending chkp writes
13373 log i/o's done, 1.23 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 608675752; in additional pool allocated 3250432
Dictionary memory allocated 92120
Buffer pool size   32768
Free buffers       1
Database pages     26868
Modified db pages  309
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 235947, created 870, written 86221
143.54 reads/s, 0.06 creates/s, 1.91 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
2 queries inside InnoDB, 0 queries in queue
3 read views open inside InnoDB
Main thread id 34370244288, state: sleeping
Number of rows inserted 102150, updated 506, deleted 0, read 9979592534
7.83 inserts/s, 0.06 updates/s, 0.00 deletes/s, 673708.69 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

I have to admit, I don't understand too much of what the above is stating.
I'm currently doing some reading to get me up to speed in that regard,
though.

My table structures for the three problem tables are essentially similar to:
id (primary key - auto_increment)
foreignKey1 -> primaryTable1.id
foreignKey2 -> primaryTable2.id
timestamp

My code is made up of two types of threads.  The first thread (and note that
there exists only one active thread of this type), does a delete based on
timestamp once a hour for each of my 3 binding tables.  The other type (and
currently there are 5 threads), writes to one of these 3 tables exclusively.

So, the deadlock must be happening when deletion starts, as indicated
below.  However, once it occurs, the deadlock seems to remain.

Here are the jdbc exception I'm getting (note, everything appears to be good
for a few days until all goes crazy):

INFO   | jvm 1    | 2009/09/19 19:20:32 | [TopLink Warning]: 2009.09.19
07:20:32.139--UnitOfWork(810972238)--Exception [TOPLINK-4002] (Oracle
TopLink Essentials - 2.0.1 (Build b09d-fcs (12/06/2007))):
oracle.toplink.essentials.exceptions.DatabaseException
INFO   | jvm 1    | 2009/09/19 19:20:32 | Internal Exception:
java.sql.SQLException: Lock wait timeout exceeded; try restarting
transaction
INFO   | jvm 1    | 2009/09/19 19:20:32 | Error Code: 1205
INFO   | jvm 1    | 2009/09/19 19:20:32 | Call: DELETE FROM
INTERNALIPADDRESSBINDING WHERE (BINDTIMESTAMP < ?)
INFO   | jvm 1    | 2009/09/19 19:20:32 |     bind => [2009-03-23
19:18:29.207]
INFO   | jvm 1    | 2009/09/19 19:20:32 | Query: DeleteAllQuery()
INFO   | jvm 1    | 2009/09/19 19:21:02 | [TopLink Warning]: 2009.09.19
07:21:02.115--UnitOfWork(598977121)--Exception [TOPLINK-4002] (Oracle
TopLink Essentials - 2.0.1 (Build b09d-fcs (12/06/2007))):
oracle.toplink.essentials.exceptions.DatabaseException
INFO   | jvm 1    | 2009/09/19 19:21:02 | Internal Exception:
java.sql.SQLException: Lock wait timeout exceeded; try restarting
transaction
INFO   | jvm 1    | 2009/09/19 19:21:02 | Error Code: 1205
INFO   | jvm 1    | 2009/09/19 19:21:02 | Call: INSERT INTO
EXTERNALIPADDRESSBINDING (BINDTIMESTAMP, EXTERNALIPADDRESS_IPADDRESS,
INTERNALIPADDRESS_IPADDRESS) VALUES (?, ?, ?, ?)
INFO   | jvm 1    | 2009/09/19 19:21:02 |     bind => [2009-09-19
19:18:40.0, 1.1.1.1, 3.3.3.3]
INFO   | jvm 1    | 2009/09/19 19:21:02 | Query:
InsertObjectQuery(edu.blah.entity.ExternalIPAddressBinding[id=null])
INFO   | jvm 1    | 2009/09/19 19:21:02 | [TopLink Warning]: 2009.09.19
07:21:02.115--UnitOfWork(1752619158)--Exception [TOPLINK-4002] (Oracle
TopLink Essentials - 2.0.1 (Build b09d-fcs (12/06/2007))):
oracle.toplink.essentials.exceptions.DatabaseException
INFO   | jvm 1    | 2009/09/19 19:21:02 | Internal Exception:
java.sql.SQLException: Lock wait timeout exceeded; try restarting
transaction
INFO   | jvm 1    | 2009/09/19 19:21:02 | Error Code: 1205
INFO   | jvm 1    | 2009/09/19 19:21:02 | Call: INSERT INTO
EXTERNALIPADDRESSBINDING (BINDTIMESTAMP, EXTERNALIPADDRESS_IPADDRESS,
INTERNALIPADDRESS_IPADDRESS) VALUES (?, ?, ?, ?)
INFO   | jvm 1    | 2009/09/19 19:21:02 |     bind => [2009-09-19
19:18:40.0, 2.2.2.2, 4.4.4.4]
INFO   | jvm 1    | 2009/09/19 19:21:02 | Query:
InsertObjectQuery(edu.blah.entity.ExternalIPAddressBinding[id=null])

Thread
SQL Error: 1205 - Lock exception with a tuned MySQL installGrover Blue22 Sep