XF 1.4 Double Posts, MySQL Lock Timeout errors

Denny Crane

Member
I've been getting a lot of both on my site lately.

http://www.sportstwo.com.

What I think is going on is users are clicking on the submit post button two or more times because they're on mobile and there's a lot of lag.

I just read a thread where one guy submitted the same post 4 times in a row.

I'm seeing only a handful (like 12-15) per day of these MySQL Lock Timeout errors in the server log.

Any suggestions?
 
I already bumped the innodb_lock_timeout variable as suggested in an older thread I found on this site.

I think that's a mistake, but I'm hoping someone will set that straight. I've not ever seen a message board take 50 seconds (the lock timeout default) to render a page.
 
Server Error Log
Error Info
Zend_Db_Statement_Mysqli_Exception: Mysqli statement execute error : Lock wait timeout exceeded; try restarting transaction - library/Zend/Db/Statement/Mysqli.php:214
Generated By: BlayZa, 31 minutes ago
Stack Trace
#0 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/Zend/Db/Statement.php(297): Zend_Db_Statement_Mysqli->_execute(Array)
#1 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/Zend/Db/Adapter/Abstract.php(479): Zend_Db_Statement->execute(Array)
#2 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter/DiscussionMessage.php(928): Zend_Db_Adapter_Abstract->query('?????UPDATE xf_...', 20938)
#3 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter/DiscussionMessage/Post.php(200): XenForo_DataWriter_DiscussionMessage->_updateUserMessageCount(false)
#4 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter/DiscussionMessage.php(560): XenForo_DataWriter_DiscussionMessage_Post->_updateUserMessageCount()
#5 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter.php(1409): XenForo_DataWriter_DiscussionMessage->_postSave()
#6 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/ControllerPublic/Thread.php(555): XenForo_DataWriter->save()
#7 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/FrontController.php(347): XenForo_ControllerPublic_Thread->actionAddReply()
#8 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/FrontController.php(134): XenForo_FrontController->dispatch(Object(XenForo_RouteMatch))
#9 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/index.php(13): XenForo_FrontController->run()
#10 {main}
Request State
array(3) {
["url"] => string(90) "http://www.sportstwo.com/threads/official-around-the-nba-february-edition.279290/add-reply"
["_GET"] => array(0) {
}
["_POST"] => array(9) {
["message_html"] => string(92) "<p>so Claver is exploring options outside the NBA</p><p><br></p><p>anyone surprised?<br></p>"
["_xfRelativeResolver"] => string(88) "http://www.sportstwo.com/threads/official-around-the-nba-february-edition.279290/page-27"
["attachment_hash"] => string(32) "74909a4696e516604e5b189890d19aea"
["last_date"] => string(10) "1424653759"
["last_known_date"] => string(10) "1424653759"
["_xfToken"] => string(8) "********"
["_xfRequestUri"] => string(64) "/threads/official-around-the-nba-february-edition.279290/page-27"
["_xfNoRedirect"] => string(1) "1"
["_xfResponseType"] => string(4) "json"
}
}
 
And another:

Server Error Log
Error Info
Zend_Db_Statement_Mysqli_Exception: Mysqli statement execute error : Lock wait timeout exceeded; try restarting transaction - library/Zend/Db/Statement/Mysqli.php:214
Generated By: Strenuus, Today at 4:39 PM
Stack Trace
#0 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/Zend/Db/Statement.php(297): Zend_Db_Statement_Mysqli->_execute(Array)
#1 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/Zend/Db/Adapter/Abstract.php(479): Zend_Db_Statement->execute(Array)
#2 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter/Alert.php(99): Zend_Db_Adapter_Abstract->query('????UPDATE xf_u...', 27997)
#3 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter.php(1409): XenForo_DataWriter_Alert->_postSave()
#4 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/Model/Alert.php(452): XenForo_DataWriter->save()
#5 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/Model/Alert.php(426): XenForo_Model_Alert->alertUser(27997, 27918, 'Strenuus', 'post', 3559884, 'insert', NULL)
#6 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/Model/ThreadWatch.php(279): XenForo_Model_Alert::alert(27997, 27918, 'Strenuus', 'post', 3559884, 'insert')
#7 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter/DiscussionMessage/Post.php(164): XenForo_Model_ThreadWatch->sendNotificationToWatchUsersOnReply(Array, NULL, Array)
#8 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/WidgetFramework/XenForo/DataWriter/DiscussionMessage/Post.php(7): XenForo_DataWriter_DiscussionMessage_Post->_postSaveAfterTransaction()
#9 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter.php(1423): WidgetFramework_XenForo_DataWriter_DiscussionMessage_Post->_postSaveAfterTransaction()
#10 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/ControllerPublic/Thread.php(555): XenForo_DataWriter->save()
#11 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/FrontController.php(347): XenForo_ControllerPublic_Thread->actionAddReply()
#12 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/FrontController.php(134): XenForo_FrontController->dispatch(Object(XenForo_RouteMatch))
#13 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/index.php(13): XenForo_FrontController->run()
#14 {main}
Request State
array(3) {
["url"] => string(117) "http://www.sportstwo.com/threads/ga...015-sunday-6-00-pm-pst-csnnw.280179/add-reply"
["_GET"] => array(0) {
}
["_POST"] => array(9) {
["message_html"] => string(99) "<p>This is cool</p><p><br></p><p>https://twitter.com/trailblazers/status/569654311535255552<br></p>"
["_xfRelativeResolver"] => string(108) "http://www.sportstwo.com/threads/ga...uary-22-2015-sunday-6-00-pm-pst-csnnw.280179/"
["attachment_hash"] => string(32) "f437c0494b4e7bb009f0718d2c5e3138"
["last_date"] => string(10) "1424649169"
["last_known_date"] => string(10) "1424649169"
["_xfToken"] => string(8) "********"
["_xfRequestUri"] => string(84) "/threads/game-55-grizzlies-blazers-february-22-2015-sunday-6-00-pm-pst-csnnw.280179/"
["_xfNoRedirect"] => string(1) "1"
["_xfResponseType"] => string(4) "json"
}
}
 
I think it is almost certainly coincidental with double posts.

The user clicks "submit" for his post and it does nothing while the lock timeout occurs. So he hits "submit" again.
 
This one's different:

Server Error Log
Error Info
Zend_Db_Statement_Mysqli_Exception: Mysqli statement execute error : Duplicate entry '28021-280179' for key 'PRIMARY' - library/Zend/Db/Statement/Mysqli.php:214
Generated By: honkicracker, 55 minutes ago
Stack Trace
#0 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/Zend/Db/Statement.php(297): Zend_Db_Statement_Mysqli->_execute(Array)
#1 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/Zend/Db/Adapter/Abstract.php(479): Zend_Db_Statement->execute(Array)
#2 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/Zend/Db/Adapter/Abstract.php(574): Zend_Db_Adapter_Abstract->query('INSERT INTO `xf...', Array)
#3 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter.php(1624): Zend_Db_Adapter_Abstract->insert('xf_thread_watch', Array)
#4 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter.php(1613): XenForo_DataWriter->_insert()
#5 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/DataWriter.php(1405): XenForo_DataWriter->_save()
#6 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/Model/ThreadWatch.php(506): XenForo_DataWriter->save()
#7 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/Model/ThreadWatch.php(549): XenForo_Model_ThreadWatch->setThreadWatchStateWithUserDefault(28021, 280179, 'watch_email')
#8 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/ControllerPublic/Thread.php(562): XenForo_Model_ThreadWatch->setVisitorThreadWatchStateFromInput(280179, Array)
#9 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/FrontController.php(347): XenForo_ControllerPublic_Thread->actionAddReply()
#10 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/library/XenForo/FrontController.php(134): XenForo_FrontController->dispatch(Object(XenForo_RouteMatch))
#11 /home/mschwartz/github/mschwartz/sportstwo-xenforo/htdocs/index.php(13): XenForo_FrontController->run()
#12 {main}
Request State
array(3) {
["url"] => string(117) "http://www.sportstwo.com/threads/ga...015-sunday-6-00-pm-pst-csnnw.280179/add-reply"
["_GET"] => array(0) {
}
["_POST"] => array(9) {
["message_html"] => string(258) "<p>hate to say it but... after dropping the Utah game... And the Thunder starting to play better... This Memphis game.. being at home is sort of a must win..... But without Aldridge I just don't see the Blazers having a chance...<br><br>I pray I'm wrong.</p>"
["_xfRelativeResolver"] => string(114) "http://www.sportstwo.com/threads/ga...2-2015-sunday-6-00-pm-pst-csnnw.280179/page-2"
["attachment_hash"] => string(32) "36f7497e81355035bf9bf0caf43f03cb"
["last_date"] => string(10) "1424655494"
["last_known_date"] => string(10) "1424655494"
["_xfToken"] => string(8) "********"
["_xfRequestUri"] => string(90) "/threads/game-55-grizzlies-blazers-february-22-2015-sunday-6-00-pm-pst-csnnw.280179/page-2"
["_xfNoRedirect"] => string(1) "1"
["_xfResponseType"] => string(4) "json"
}
}
 
Some more info.

The site is doing about 30 pages a minute while the errors are happening. Lots of race conditions as people are posting like crazy in one thread.

No, I can't drive them to different threads, they're discussing the NBA basketball game as it's being played.
 
What hosting package are you on and what are your server specs?
Tuning the server may help.

Threads aren't the best medium for real time discussion - have you considered a chat add-on of some sort?
 
The 2 lock wait issues are on the xf_user table. This almost looks like a general load issue as it's simply waiting for another transaction to free that row (or page actually); normally these transactions should be quick.

What does this query output?
Code:
SHOW ENGINE INNODB STATUS;
Have you gone through your InnoDB settings to ensure they're fully optimized for your usage? See: http://www.percona.com/blog/2013/09/20/innodb-performance-optimization-basics-updated/
 
====================================
2015-02-23 09:45:32 7f9c93594700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 15 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 3752728 srv_active, 0 srv_shutdown, 551763 srv_idle
srv_master_thread log flush and writes: 4303899
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4516342
OS WAIT ARRAY INFO: signal count 4677420
Mutex spin waits 5250178, rounds 88754970, OS waits 2880839
RW-shared spins 1702525, rounds 48518223, OS waits 1569819
RW-excl spins 117345, rounds 3240862, OS waits 51261
Spin rounds per wait: 16.91 mutex, 28.50 RW-shared, 27.62 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 40415194
Purge done for trx's n:o < 40415194 undo n:o < 0 state: running but idle
History list length 1883
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 16484479, OS thread handle 0x7f9c93594700, query id 342060715 localhost mschwartz init
SHOW ENGINE INNODB STATUS
---TRANSACTION 40415192, not started
MySQL thread id 16484562, OS thread handle 0x7f9c8a22f700, query id 342060718 www1.local 10.132.142.156 apache cleaning up
---TRANSACTION 40294476, not started
MySQL thread id 2, OS thread handle 0x7f9c938c3700, query id 341020989 Slave has read all relay log; waiting for the slave I/O thread to update it
--------
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
33742703 OS file reads, 34634129 OS file writes, 13387658 OS fsyncs
14.27 reads/s, 16384 avg bytes/read, 15.07 writes/s, 4.33 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 3077, seg size 3079, 1014753 merges
merged operations:
insert 1624831, delete mark 5849690, delete 3447754
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 276671, node heap has 568 buffer(s)
60.73 hash searches/s, 197.25 non-hash searches/s
---
LOG
---
Log sequence number 32854782961
Log flushed up to 32854782845
Pages flushed up to 32854735385
Last checkpoint at 32854673043
0 pending log writes, 0 pending chkp writes
11134187 log i/o's done, 3.73 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137363456; in additional pool allocated 0
Dictionary memory allocated 1349698
Buffer pool size 8191
Free buffers 1023
Database pages 6600
Old database pages 2416
Modified db pages 100
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 19844255, not young 557767527
1.80 youngs/s, 121.26 non-youngs/s
Pages read 33742219, created 422922, written 22892745
14.27 reads/s, 0.13 creates/s, 11.13 writes/s
Buffer pool hit rate 987 / 1000, young-making rate 1 / 1000 not 111 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6600, unzip_LRU len: 0
I/O sum[919]:cur[1], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Main thread process no. 30394, id 140310435165952, state: sleeping
Number of rows inserted 7001024, updated 7628939, deleted 2631031, read 48827526387
0.13 inserts/s, 3.00 updates/s, 0.07 deletes/s, 188.45 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
 
Using a chat program is not an option.

Switching back to vBulletin is. We never ever had this kind of problem using vb4 or ipBoard prior.

The site setup is described here:
http://moduscreate.com/scaling-xenforo-on-digital-oceans-iaas/

I have monitored the vps systems under load and we're not even using 5% of any of the CPUs. All are 95%+ idle.

It's not for lack of computing power. It appears to be a race condition BUG in xenforo where two HTTP requests cause the PHP to issue.

I cannot imagine why the software would hold a lock on a row or rows in the users table for over a minute at a time if it is not a bug.
 
2015-02-23%20at%207.22%20AM.png


Those are my innodb settings in my.cnf.


db1:~$ free
total used free shared buffers cached
Mem: 8176824 1810012 6366812 340 16288 261464
-/+ buffers/cache: 1532260 6644564
Swap: 0 0
 
Note that XenForo does not use the same MySQL configuration as vBulletin. If you setup your MySQL server for MyISAM primarily, the server is likely setup totally the wrong way for XenForo.

This part is making me think that InnoDB hasn't been hugely configured:

Total memory allocated 137363456; in additional pool allocated 0
This would seem to imply the innodb_buffer_pool_size variable is something like 128M. It should ideally be set as large as possible. If you can fit your entire data set in it, all the better.

There are also things that can be done to speed up writes specifically (innodb_flush_log_at_trx_commit and innodb_flush_method) that, if not tuned, may cause significant overhead if you have a lot of writes happening.

XenForo certainly shouldn't be holding on to a transaction while posting for any significant amount of time. When you make a post, you're seeing the transaction in question and much more happen. All told, it should probably take no longer than a second for the entire request to run. Individual transactions within should be less than that. That's what made me suggest that there's some general load/resource contention issue within MySQL that's causing issues.

Note that a lock wait timeout isn't a race condition or a deadlock. It's just waiting for another transaction to release. The question is why that other transaction is taking so long. This is very often a load issue. It could potentially also happen if there are things being done in the transaction that are taking a long time. The only thing done within the post insert transaction that doesn't depend on MySQL would be Elasticsearch indexing (assuming you're using that). If there's some issue there that would take a huge amount of time, that could be related; ES is usually significantly faster at indexing than MySQL fulltext itself though.
 
I see you posted some InnoDB settings while I was posting. Can you confirm those are the variables in use? The total memory allocated doesn't seem to correspond to 6G (testing here, it does correspond to what we have in my.cnf, though slightly larger than what's set there).
 
=====================================
2015-02-23 10:26:32 7fbd0fd32700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 13 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 285 srv_active, 0 srv_shutdown, 32 srv_idle
srv_master_thread log flush and writes: 317
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 642
OS WAIT ARRAY INFO: signal count 650
Mutex spin waits 496, rounds 12180, OS waits 397
RW-shared spins 245, rounds 7270, OS waits 239
RW-excl spins 2, rounds 307, OS waits 4
Spin rounds per wait: 24.56 mutex, 29.67 RW-shared, 153.50 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 40441013
Purge done for trx's n:o < 40441007 undo n:o < 0 state: running but idle
History list length 1454
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 1305, OS thread handle 0x7fbd0fd32700, query id 27074 localhost mschwartz init
SHOW ENGINE INNODB STATUS
---TRANSACTION 40437755, not started
MySQL thread id 1, OS thread handle 0x7fbd0fdb6700, query id 262 Slave has read all relay log; waiting for the slave I/O thread to update it
--------
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
8475 OS file reads, 3816 OS file writes, 1162 OS fsyncs
6.92 reads/s, 16384 avg bytes/read, 3.77 writes/s, 0.46 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 3077, seg size 3079, 105 merges
merged operations:
insert 394, delete mark 80, delete 34
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 12749447, node heap has 573 buffer(s)
244.67 hash searches/s, 154.45 non-hash searches/s
---
LOG
---
Log sequence number 32863462053
Log flushed up to 32863462053
Pages flushed up to 32863354953
Last checkpoint at 32863354953
0 pending log writes, 0 pending chkp writes
886 log i/o's done, 3.77 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 6593445888; in additional pool allocated 0
Dictionary memory allocated 1349698
Buffer pool size 393200
Free buffers 384263
Database pages 8364
Old database pages 1664
Modified db pages 317
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 8334, created 30, written 2591
6.92 reads/s, 0.08 creates/s, 0.00 writes/s
Buffer pool hit rate 995 / 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: 8364, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size 24575
Free buffers 24037
Database pages 502
Old database pages 0
Modified db pages 51
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 502, created 0, written 443
0.85 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 996 / 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: 502, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size 24575
Free buffers 24058
Database pages 481
Old database pages 0
Modified db pages 10
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 481, created 0, written 46
0.31 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 971 / 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: 481, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size 24575
Free buffers 24072
Database pages 467
Old database pages 0
Modified db pages 12
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 467, created 0, written 50
1.15 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 971 / 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: 467, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size 24575
Free buffers 23980
Database pages 559
Old database pages 226
Modified db pages 29
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 559, created 0, written 341
0.54 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 995 / 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: 559, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size 24575
Free buffers 23841
Database pages 698
Old database pages 277
Modified db pages 52
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 698, created 0, written 470
0.15 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 999 / 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: 698, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size 24575
Free buffers 23982
Database pages 557
Old database pages 225
Modified db pages 23
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 548, created 9, written 199
0.77 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 962 / 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: 557, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size 24575
Free buffers 23982
Database pages 557
Old database pages 225
Modified db pages 10
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 552, created 5, written 95
0.69 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 973 / 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: 557, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size 24575
Free buffers 24002
Database pages 537
Old database pages 218
Modified db pages 14
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 537, created 0, written 122
0.38 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 970 / 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: 537, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 8
Buffer pool size 24575
Free buffers 23854
Database pages 685
Old database pages 272
Modified db pages 25
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 671, created 14, written 183
0.38 reads/s, 0.08 creates/s, 0.00 writes/s
Buffer pool hit rate 997 / 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: 685, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 9
Buffer pool size 24575
Free buffers 24107
Database pages 432
Old database pages 0
Modified db pages 20
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 432, created 0, written 215
0.23 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 994 / 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: 432, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 10
Buffer pool size 24575
Free buffers 24076
Database pages 463
Old database pages 0
Modified db pages 6
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 463, created 0, written 36
0.31 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 999 / 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: 463, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 11
Buffer pool size 24575
Free buffers 24035
Database pages 504
Old database pages 0
Modified db pages 7
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 504, created 0, written 20
0.23 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 997 / 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: 504, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 12
Buffer pool size 24575
Free buffers 23994
Database pages 545
Old database pages 221
Modified db pages 25
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 543, created 2, written 143
0.54 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 996 / 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: 545, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 13
Buffer pool size 24575
Free buffers 24097
Database pages 443
Old database pages 0
Modified db pages 13
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 443, created 0, written 119
0.00 reads/s, 0.00 creates/s, 0.00 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: 443, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 14
Buffer pool size 24575
Free buffers 24068
Database pages 472
Old database pages 0
Modified db pages 12
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 472, created 0, written 63
0.23 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 995 / 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: 472, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 15
Buffer pool size 24575
Free buffers 24078
Database pages 462
Old database pages 0
Modified db pages 8
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 462, created 0, written 46
0.15 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 997 / 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: 462, 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
0 read views open inside InnoDB
Main thread process no. 1254, id 140450042210048, state: sleeping
Number of rows inserted 199, updated 743, deleted 16, read 3662284
1.23 inserts/s, 1.92 updates/s, 0.00 deletes/s, 486.65 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
 
I made adjustments according to the persona document you linked.

The section of my.cnf I posted are the new values.

If you think I have set anything wrong, please let me know.

In the mean time, I can monitor the site for any continued issues.
 
Please let me know how that goes. If you see the site slow down/give lock timeout errors, run a few more InnoDB status checks -- we'd be looking for the open transactions at the time to hopefully see if anything can be gleaned from that.

Are you running Elasticsearch? If so, please have a look to make sure that's running well and that it has memory allocated to handle its indexes. (If you're running MySQL full text search, that could potentially be a bottleneck I suppose; it may be slow to update the index with 3.5 million posts. That's also a MyISAM table so some memory would still need to be allocated to MyISAM and its key cache to handle that table.)

I assume you are pulling sessions for Memcached as well (cache has to be enabled in config.php and you have to explicitly opt in to using it for sessions). That will remove a read and a write to the DB server on each page.
 
Top Bottom