Query speeds ok in 5.0 but inserts become very slow in 5.1.25
I've got an application that I've been stress testing with a client simulator I wrote. I've been using the CentOS distribution of 5.0.45 and everything's worked fine, but when I switch to the RHEL 5 RPM distribution for 5.1.25 from the MySQL web site, I started getting periodic extremely long times for inserts and updates: what had been taking on the order of 20ms in 5.0.45 may take on the order of seconds, or even tens of seconds.
All tables are in InnoDB. To make sure my configuration wasn't doing anything odd, I used the my-big.cnf from the distribution (removing the comments from the InnoDB settings). Between tests, I cleared out all data and log files and reloaded from a dumpfile. I tried using myisam on 5.1.25 and everything works fine, with performance comparable to that on InnoDB on 5.0.45. It only seems to have problems with InnoDB on 5.1.25.
The application is pretty straightforward. I select a small amount of data for a subscriber from a few tables, crunch a little, and then update or insert a result row in another table. The result row is also selected in the first step but in the simulation, it's very unlikely that I'll hit the same subscriber twice so I'll never select a subscriber's results while I'm inserting/updating new results for the same subscriber.
Here's an example from the slow queries log:
# Time: 080712 8:43:14
# User@Host: root[root] @ localhost []
# Query_time: 23.991787 Lock_time: 0.000031 Rows_sent: 0 Rows_examined: 0
SET timestamp=1215823394;
insert sub_histories (sub_id, product_id,created_at,delivered_at,updated_at,ntimes)
values (30777, 9, NOW(), NOW(), NOW(), 1);
And here's a snippet from SHOW INNODB STATUS:
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 37, signal count 36
Mutex spin waits 0, rounds 1299, OS waits 28
RW-shared spins 15, OS waits 7; RW-excl spins 2, OS waits 2
------------
TRANSACTIONS
------------
Trx id counter 0 387242
Purge done for trx's n:o < 0 375981 undo n:o < 0 0
History list length 1432
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 7305, OS thread id 1165650240
MySQL thread id 1, query id 38028 localhost root
show innodb status
---TRANSACTION 0 387241, ACTIVE 20 sec, process no 7305, OS thread id 1168312640 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 368, 0 row lock(s), undo log entries 1
MySQL thread id 11, query id 38027 localhost root update
insert sub_histories (sub_id, creative_id,created_at,delivered_at,updated_at,ntimes)
values (111123, 10, NOW(), NOW(), NOW(), 1)
The table has an auto-inc integer ID field, which I assume is causing the lock, but why this should translate to a 20 sec. operation is beyond me (as well as why it works fine on 5.0 but not on 5.1).
Any ideas? I've tried every value of innodb_autoinc_lock_mode as well as every value of every other setting I could think of. The only thing left is to compile 5.1.25 myself and enable the profiler so I can see exactly where the time's going, but after trying dozens of other things over the past few days, I'm hoping that someone will suggest something simpler.
Thanks!
Edited 1 time(s). Last edit at 07/12/2008 05:26AM by Mark Westling.