MySQL issues: Lock wait timeout exceeded;

Support requests, bug reports, etc. go here. Dedicated servers / VDS hosting only
cqrt
Bear Rating Disaster
Bear Rating Disaster
Posts: 70
Joined: 05 Apr 2013, 00:37

MySQL issues: Lock wait timeout exceeded;

Postby cqrt » 18 May 2013, 21:06

I've been struggling with some mysql issues since upgrading to 1.7.9 so I thought I'd share my data in the hope somebody can add some insight my woes.

When scrolling through a feed, auto marking read, I would notice that the process would start to stall. The read count for that feed would remain static and observing the post themselves, they would sometimes take up to 20 - 30 seconds before they would change to 'read'. Continuing to scroll, this process would get slower and slower.

Eventually a red exclamation would appear with the message 'Communication problem with server'. Checking the error log, two different errors appear which seem to correspond with the bottleneck;

Query DELETE FROM ttrss_entries WHERE (SELECT COUNT(int_id) FROM ttrss_user_entries WHERE ref_id = id) = 0 failed: Lock wait timeout exceeded; try restarting transaction


Query UPDATE ttrss_entries SET date_updated = NOW() WHERE id = '129260' failed: Deadlock found when trying to get lock; try restarting transaction


Figuring some mysql madness I performed the following:

CHECK TABLE `ttrss_entries`
ALTER TABLE `ttrss_entries` ENGINE = INNODB
OPTIMIZE TABLE `ttrss_entries`
FLUSH TABLE `ttrss_entries`

The issues persisted. I captured SHOW ENGINE INNODB STATUS; during the process and this was the output.

Code: Select all

mysql> SHOW ENGINE INNODB STATUS;
+--------+------+-----------------------------------------------------------------------+
| Type   | Name | Status                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           |
+--------+------+-----------------------------------------------------------------------+
| InnoDB |      |
=====================================
130519  3:46:05 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 35 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 756 1_second, 755 sleeps, 73 10_second, 30 background, 30 flush
srv_master_thread log flush and writes: 792
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4806, signal count 2441
Mutex spin waits 2484, rounds 82659, OS waits 2214
RW-shared spins 1766, rounds 56474, OS waits 1554
RW-excl spins 178, rounds 31140, OS waits 1024
Spin rounds per wait: 33.28 mutex, 31.98 RW-shared, 174.94 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 2834743
Purge done for trx's n:o < 28346A8 undo n:o < 0
History list length 2109
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 571, OS thread handle 0x7f06c411b700, query id 64863 localhost ubuntu
SHOW ENGINE INNODB STATUS
---TRANSACTION 0, not started
MySQL thread id 619, OS thread handle 0x7f06ca00d700, query id 64818 localhost ubuntu
---TRANSACTION 0, not started
MySQL thread id 618, OS thread handle 0x7f06c41df700, query id 64755 localhost ubuntu
---TRANSACTION 2834731, not started flushing log
MySQL thread id 616, OS thread handle 0x7f06ca03e700, query id 64815 localhost ubuntu
COMMIT
---TRANSACTION 283473A, not started flushing log
MySQL thread id 601, OS thread handle 0x7f06c9f7a700, query id 64862 localhost ubuntu
COMMIT
---TRANSACTION 2834741, ACTIVE 0 sec
MySQL thread id 609, OS thread handle 0x7f06c414c700, query id 64861 localhost ubuntu
Trx read view will not see trx with id >= 2834742, sees < 2834739
---TRANSACTION 2834740, ACTIVE 0 sec
MySQL thread id 602, OS thread handle 0x7f06c40ea700, query id 64860 localhost ubuntu
Trx read view will not see trx with id >= 2834741, sees < 2834739
---TRANSACTION 283473F, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 603, OS thread handle 0x7f06c9fdc700, query id 64858 localhost ubuntu Updating
UPDATE ttrss_counters_cache SET
                                value = '0', updated = NOW() WHERE
                                feed_id = '313' AND owner_uid = '1'
Trx read view will not see trx with id >= 2834740, sees < 2834739
------- TRX HAS BEEN WAITING 0 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 324 n bits 456 index `ttrss_counters_cache_feed_id_idx` of table `ttrssdb`.`ttrss_counters_cache` trx id 283473F lock_mode X waiting
Record lock, heap no 107 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 80000139; asc    9;;
 1: len 6; hex 0000000002a0; asc       ;;

------------------
---TRANSACTION 283473E, ACTIVE 0 sec committing
4 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 1
MySQL thread id 612, OS thread handle 0x7f06ca06f700, query id 64866 localhost ubuntu
COMMIT
Trx read view will not see trx with id >= 283473F, sees < 2834739
---TRANSACTION 283473D, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 1
MySQL thread id 613, OS thread handle 0x7f06c417d700, query id 64856 localhost ubuntu Updating
UPDATE ttrss_counters_cache SET
                                value = '83', updated = NOW() WHERE
                                feed_id = '307' AND owner_uid = '1'
Trx read view will not see trx with id >= 283473E, sees < 2834739
---TRANSACTION 283473C, ACTIVE 0 sec committing
4 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 1
MySQL thread id 617, OS thread handle 0x7f06c9f49700, query id 64867 localhost ubuntu
COMMIT
Trx read view will not see trx with id >= 283473D, sees < 2834739
---TRANSACTION 283473B, ACTIVE 0 sec committing
4 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 1
MySQL thread id 604, OS thread handle 0x7f06c9fab700, query id 64869 localhost ubuntu
COMMIT
Trx read view will not see trx with id >= 283473C, sees < 2834739
---TRANSACTION 2834739, ACTIVE 0 sec committing
4 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 1
MySQL thread id 605, OS thread handle 0x7f06c41ae700, query id 64868 localhost ubuntu
COMMIT
Trx read view will not see trx with id >= 283473A, sees < 283473A
--------
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 (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (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: 1; buffer pool: 0
2638 OS file reads, 13011 OS file writes, 7357 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 14.34 writes/s, 5.57 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5, seg size 7, 2 merges
merged operations:
 insert 14, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 276707, node heap has 155 buffer(s)
8235.88 hash searches/s, 459.73 non-hash searches/s
---
LOG
---
Log sequence number 5385554099
Log flushed up to   5385552571
Last checkpoint at  5385501999
1 pending log writes, 0 pending chkp writes
6960 log i/o's done, 5.11 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137363456; in additional pool allocated 0
Dictionary memory allocated 532986
Buffer pool size   8192
Free buffers       5228
Database pages     2809
Old database pages 1026
Modified db pages  140
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2627, created 182, written 11793
0.00 reads/s, 0.11 creates/s, 16.63 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: 2809, 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
5 read views open inside InnoDB
Main thread process no. 771, id 139666756253440, state: sleeping
Number of rows inserted 4, updated 10409, deleted 4, read 323262893
0.00 inserts/s, 12.51 updates/s, 0.00 deletes/s, 229124.11 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
 |
+--------+------+-----------------------------------------------------------------------+
1 row in set (0.25 sec)

mysql>


And this was SHOW PROCESSLIST;

Code: Select all

mysql> SHOW PROCESSLIST;
+-----+--------+-----------+---------+---------+------+----------------+-------------------------------------------------------+
| Id  | User   | Host      | db      | Command | Time | State          | Info                                                                                                 |
+-----+--------+-----------+---------+---------+------+----------------+-------------------------------------------------------+
| 769 | ubuntu | localhost | ttrssdb | Query   |    0 | NULL           | SHOW PROCESSLIST                                                                                     |
| 901 | ubuntu | localhost | ttrssdb | Query   |    1 | Writing to net | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
| 905 | ubuntu | localhost | ttrssdb | Query   |    6 | Sending data   | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
| 906 | ubuntu | localhost | ttrssdb | Query   |    1 | Sending data   | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
| 907 | ubuntu | localhost | ttrssdb | Query   |    0 | NULL           | COMMIT                                                                                               |
| 908 | ubuntu | localhost | ttrssdb | Query   |    0 | NULL           | COMMIT                                                                                               |
| 909 | ubuntu | localhost | ttrssdb | Query   |    1 | Sending data   | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
| 910 | ubuntu | localhost | ttrssdb | Query   |    1 | Sending data   | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
| 913 | ubuntu | localhost | ttrssdb | Query   |    1 | Sending data   | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
| 917 | ubuntu | localhost | ttrssdb | Query   |    4 | Sending data   | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
| 918 | ubuntu | localhost | ttrssdb | Query   |    1 | Sending data   | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
| 919 | ubuntu | localhost | ttrssdb | Query   |    1 | Sending data   | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
| 920 | ubuntu | localhost | ttrssdb | Query   |    0 | Sending data   | SELECT count(int_id) AS unread
                                FROM ttrss_user_entries WHERE
                                unread = true AND  (feed_id = ' |
+-----+--------+-----------+---------+---------+------+----------------+--------------------------------------------------+
13 rows in set (0.00 sec)

mysql>


I also was recording exceedingly high load averages during these bottlenecks, graph follows:

Image

This seems to correspond with the spikes in the mysql table locks:

Image

Other useful mysql data:

Image

This issues eventually sort themselves out, if I stop interacting with tt-rss for 3-4 mins the unread counts will catch up and the red exclamation will disappear. The biggest concern for me is the load averages. The load average graph above, between 3 - 4am, I was consistently interacting with a feed and collecting this data.

Environment:
Intel(R) Xeon(R) CPU E5430 @ 2.66GHz, 1 cores 512mb ram
Ubuntu Linux 12.04.2
MySQL 5.5.31
PHP 5.3.10

My train of thought is leaning towards the awesomeness and goodness of 1.7.9 is now too much for my environment. My apologies for all the propeller-hat shit.

Thoughts?

User avatar
fox
^ me reading your posts ^
Posts: 6318
Joined: 27 Aug 2005, 22:53
Location: Saint-Petersburg, Russia
Contact:

Re: MySQL issues: Lock wait timeout exceeded;

Postby fox » 18 May 2013, 21:16

What do you think about trying postgresql?

gbcox
Bear Rating Master
Bear Rating Master
Posts: 149
Joined: 25 Apr 2013, 04:52

Re: MySQL issues: Lock wait timeout exceeded;

Postby gbcox » 18 May 2013, 22:13

Just out of curiosity, how many feeds do you have? I'm running with an old AMD Athlon processor with 1.7.9 so find it hard to believe your system is underpowered. It could be you somehow smurf'd
up your database when you did the upgrade. If you're restoring from a 1.7.8 backup I'd recommend you drop and recreate the database first with the 1.7.8 schema, otherwise when you run the 1.7.9 upgrade process
the schema upgrade will hang. Rather than switch to postgresql, I would suggest you switch to mariadb which is a drop-in replacement for mysql. It is suppose to have better performance
and all the major distributions are switching to it anyway... so you might as well give it a try since more than likely you'll be running it eventually anyway. I've posted instructions for Fedora at http://tso.bzb.us
and there are plenty of howto's available for Ubuntu a Google search away. Try the mariadb migration first, and if that doesn't work, keep it with mariadb, drop the ttrss database, recreate from 1.7.8 schema, restore from 1.7.8 backup
upgrade again to 1.7.9 - you should be able to do it all within 30 minutes or so....

cqrt
Bear Rating Disaster
Bear Rating Disaster
Posts: 70
Joined: 05 Apr 2013, 00:37

Re: MySQL issues: Lock wait timeout exceeded;

Postby cqrt » 18 May 2013, 22:30

fox wrote:What do you think about trying postgresql?


I like the way your thinking. When I get back to my workstation I'll set up trunk on a dev installation using postgres and share the results.

Sent from my i9300 Cyanogenmod 10.1

cqrt
Bear Rating Disaster
Bear Rating Disaster
Posts: 70
Joined: 05 Apr 2013, 00:37

Re: MySQL issues: Lock wait timeout exceeded;

Postby cqrt » 18 May 2013, 22:38

@gbcox

Also good suggestions, I'll expand on my reply when I get back to my desk.

Sent from my i9300 Cyanogenmod 10.1

cqrt
Bear Rating Disaster
Bear Rating Disaster
Posts: 70
Joined: 05 Apr 2013, 00:37

Re: MySQL issues: Lock wait timeout exceeded;

Postby cqrt » 18 May 2013, 22:39

Deleted post (f@#&ing tapatalk)

cqrt
Bear Rating Disaster
Bear Rating Disaster
Posts: 70
Joined: 05 Apr 2013, 00:37

Re: MySQL issues: Lock wait timeout exceeded;

Postby cqrt » 19 May 2013, 00:42

gbcox wrote:Just out of curiosity, how many feeds do you have? I'm running with an old AMD Athlon processor with 1.7.9 so find it hard to believe your system is underpowered.


163 feeds

It could be you somehow smurf'd up your database when you did the upgrade. If you're restoring from a 1.7.8 backup I'd recommend you drop and recreate the database first with the 1.7.8 schema, otherwise when you run the 1.7.9 upgrade process the schema upgrade will hang.


The upgrade process was smooth and no issues while the new schemas were being imported. The error logs don't suggest the issue is with the new schemas anyway.

Rather than switch to postgresql, I would suggest you switch to mariadb which is a drop-in replacement for mysql. It is suppose to have better performance and all the major distributions are switching to it anyway... so you might as well give it a try since more than likely you'll be running it eventually anyway. I've posted instructions for Fedora at http://tso.bzb.us and there are plenty of howto's available for Ubuntu a Google search away. Try the mariadb migration first, and if that doesn't work, keep it with mariadb, drop the ttrss database, recreate from 1.7.8 schema, restore from 1.7.8 backup upgrade again to 1.7.9 - you should be able to do it all within 30 minutes or so....


The more I read about MariaDB, the more I'm liking it.

supersmurf
Bear Rating Trainee
Bear Rating Trainee
Posts: 3
Joined: 26 Mar 2013, 00:38

Re: MySQL issues: Lock wait timeout exceeded;

Postby supersmurf » 19 May 2013, 02:51

Your lack of ram is probably whats causing the load issues, my 151 feeds db is 366mb. Innodb loves ram and basically you dont have enough, read up on innodb_buffer_pool_size and try increasing it depending on how much ram you have free.

gbcox
Bear Rating Master
Bear Rating Master
Posts: 149
Joined: 25 Apr 2013, 04:52

Re: MySQL issues: Lock wait timeout exceeded;

Postby gbcox » 19 May 2013, 03:22

The more I read about MariaDB, the more I'm liking it.

Post if it helps your issue... would be interesting to know...

User avatar
fox
^ me reading your posts ^
Posts: 6318
Joined: 27 Aug 2005, 22:53
Location: Saint-Petersburg, Russia
Contact:

Re: MySQL issues: Lock wait timeout exceeded;

Postby fox » 19 May 2013, 09:56

>The more I read about MariaDB, the more I'm liking it.

Yes I'm sure the name change made mysql from a shitty toy into a proper database.

Edit: I never noticed. 512mb ram? Yeah, that's not a lot.

gbcox
Bear Rating Master
Bear Rating Master
Posts: 149
Joined: 25 Apr 2013, 04:52

Re: MySQL issues: Lock wait timeout exceeded;

Postby gbcox » 19 May 2013, 12:01

Yes I'm sure the name change made mysql from a shitty toy into a proper database.


ROFL... Well, it's not simply a name change - it's a fork. For those who care there is plenty of information via Google - and Wikipedia now runs on it.

cqrt
Bear Rating Disaster
Bear Rating Disaster
Posts: 70
Joined: 05 Apr 2013, 00:37

Re: MySQL issues: Lock wait timeout exceeded;

Postby cqrt » 19 May 2013, 16:41

supersmurf wrote:Your lack of ram is probably whats causing the load issues, my 151 feeds db is 366mb. Innodb loves ram and basically you dont have enough, read up on innodb_buffer_pool_size and try increasing it depending on how much ram you have free.


My memory allocation table graph showed no discernible differences over the last 24 hours with 200mb consistently free. But I do think you may have a point with the innodb buffer usage but I already have that set to the maximum allowed for my environment. Don't forget, these issues only surfaced after upgrade to 1.7.9 from 1.7.8.

Fox gets the lollipop here, PostgreSQL is the clear winner. MariaDB, while I'm sure has improvements over MySQL, still behaves like a bloated hog and while I'm sure I could configure and optimize the heck out it, I've only got so much time in my day. PostgreSQL performed out of the box.

Image

For those following along at home:

0900 - 1100 After importing OPML from production, running trunk installation on postgresql with heavy use every 10mins, nice results.
1100 - 1200 Curious about MariaDB, converted production install over from mysql, results speak for themselves ^^
1300 - 1400 Ignore the spikes, was migrating my production mysql data over to postgresql. 13,000+ unread articles, 48,000+ in entry table, Interesting process, will do a wiki if time permits.
1400 - 1530 Very heavy use of my production install now running postgresql, very pleasing results.
1730 - I turned on my update daemon on and left it alone.

I'm pretty pleased with the results. While I realize this is only processor load averages, it appears to be the best indicator of my bottlenecks. Thanks for all your suggestions and helpful advice.

johnnychicago
Bear Rating Trainee
Bear Rating Trainee
Posts: 36
Joined: 25 Jul 2011, 23:26

Re: MySQL issues: Lock wait timeout exceeded;

Postby johnnychicago » 19 May 2013, 20:40

cqrt wrote:1300 - 1400 Ignore the spikes, was migrating my production mysql data over to postgresql. 13,000+ unread articles, 48,000+ in entry table, Interesting process, will do a wiki if time permits.


That would be very nice :-)

User avatar
fox
^ me reading your posts ^
Posts: 6318
Joined: 27 Aug 2005, 22:53
Location: Saint-Petersburg, Russia
Contact:

Re: MySQL issues: Lock wait timeout exceeded;

Postby fox » 19 May 2013, 20:51

Who woulda think an actual database would overperform the glorified grep with SQL syntax.

gbcox
Bear Rating Master
Bear Rating Master
Posts: 149
Joined: 25 Apr 2013, 04:52

Re: MySQL issues: Lock wait timeout exceeded;

Postby gbcox » 20 May 2013, 03:52

Wow, that seems to be a fairly dramatic difference, alot more than I would have expected - which begs the question if postgresql is so much better why aren't people switching to it in droves? All the reviews I've seen say the mysql is suppose to be faster is quite a bit more popular. It doesn't appear to be that much harder to install and configure... I don't get it...


Return to “Support”

Who is online

Users browsing this forum: No registered users and 1 guest