Awaiting feedback [1.4] Server error every time I rebuild usergroup promotions

Stuart Wright

Stuart Wright

Well-known member
I have 3 usergroup promotions:
  1. From member 1 to member 2 requires membership of usergroup member 1, posted at least 1 message, registered for at least 1 day, has at least 3 positive ratings and has an avatar (this last one just added)
  2. From member 2 to member 3 requires membership of usergroup member 2 and 75 trophy points
  3. From Member 3 to Member 4 requires membership of usergroup member 3 and 150 trophy points
each one adds the secondary usergroup which contains expanded privileges.
When I rebuild User Group Promotions, I always get this error after a while:
Admin Control Panel - AVForums
Server Error
Mysqli statement execute error : Deadlock found when trying to get lock; try restarting transaction

  1. Zend_Db_Statement_Mysqli->_execute() in Zend/Db/Statement.php at line 297
  2. Zend_Db_Statement->execute() in Zend/Db/Adapter/Abstract.php at line 479
  3. Zend_Db_Adapter_Abstract->query() in XenDebug/Db/Mysqli.php at line 13
  4. XenDebug_Db_Mysqli->query() in XenForo/Model/Deferred.php at line 111
  5. XenForo_Model_Deferred->defer() in XenForo/Application.php at line 1447
  6. XenForo_Application::defer() in XenForo/Model/Deferred.php at line 300
  7. XenForo_Model_Deferred->runDeferred() in XenForo/Model/Deferred.php at line 390
  8. XenForo_Model_Deferred->_runInternal() in XenForo/Model/Deferred.php at line 335
  9. XenForo_Model_Deferred->run() in XenForo/ControllerAdmin/Tools.php at line 159
  10. XenForo_ControllerAdmin_Tools->actionRunDeferred() in XenForo/FrontController.php at line 347
  11. XenForo_FrontController->dispatch() in XenForo/FrontController.php at line 134
  12. XenForo_FrontController->run() in /home/sites/avforums/public_html/admin.php at line 13
Click to expand...
Hitting refresh seems to instantly complete the rebuild.
 
It instantly completes?

AFAIK the execution of the user group promotion rebuild places a deferred task in the deferred table (xf_deffered), as the page refreshes, all it's doing is reading the deferred table and putting some output on display. As deferred runs, the script would remove the item from xf_deferred, execute whatever chunk is set, insert a new entry into the deferred table and then when the page refereshes that deferred task is run. If it instantly 'completes', it probably didn't complete at all - it's just that no new deferred task was made as the process borked part-way through.

The error itself is a deadlock error, couldn't really say what's caused it with the in for provided. It could be a clash with another deferred task, such as the standard usergroup promotion cron job, or it could be a clash with a user record somewhere.
 
Probably a clash with a cron job, then, because it did complete when I ran it late last night, which would indicate that it's dependent on what else might be going on.
It goes through the whole user table, right? Except for banned users, probably. So it has a lot to do and plenty of time for a cron job to run simultaneously.
 
Please trigger this error and run this query and attach the output here or send it to me:

SHOW ENGINE INNODB STATUS;
 
There's a good explanation of how Galera works here: http://www.percona.com/blog/2012/08...-multi-node-writing-and-unexpected-deadlocks/

This seems very relevant here or with the other xf_deferred deadlocks. Those deadlocks are almost always MailQueue related, so it's very possible that this has failed because the transaction was a bit delayed, whereas standard InnoDB would have waited to get the lock (leading to no issue).
 
Mike said:
Please trigger this error and run this query and attach the output here or send it to me:

SHOW ENGINE INNODB STATUS;
Click to expand...
I can't trigger it to order, but here is the latest example from just 7 minutes ago. (I don't have any particular reason to think this is related to user promotions. It's just they aren't working as expected):
Error Info
Zend_Db_Statement_Mysqli_Exception: Mysqli statement execute error : Deadlock found when trying to get lock; try restarting transaction - library/Zend/Db/Statement/Mysqli.php:214
Generated By: Unknown Account, 7 minutes ago
Stack Trace
#0 /home/sites/avforums/public_html/library/Zend/Db/Statement.php(297): Zend_Db_Statement_Mysqli->_execute(Array)
#1 /home/sites/avforums/public_html/library/Zend/Db/Adapter/Abstract.php(479): Zend_Db_Statement->execute(Array)
#2 /home/sites/avforums/public_html/library/XenDebug/Db/Mysqli.php(13): Zend_Db_Adapter_Abstract->query('DELETE FROM `xf...', Array)
#3 /home/sites/avforums/public_html/library/Zend/Db/Adapter/Abstract.php(661): XenDebug_Db_Mysqli->query('DELETE FROM `xf...')
#4 /home/sites/avforums/public_html/library/XenForo/Model/Deferred.php(168): Zend_Db_Adapter_Abstract->delete('xf_deferred', 'deferred_id = 2...')
#5 /home/sites/avforums/public_html/library/XenForo/Model/Deferred.php(232): XenForo_Model_Deferred->deleteDeferredById(2219988)
#6 /home/sites/avforums/public_html/library/XenForo/Model/Deferred.php(390): XenForo_Model_Deferred->runDeferred(Array, 7.9999980926514, '', false)
#7 /home/sites/avforums/public_html/library/XenForo/Model/Deferred.php(335): XenForo_Model_Deferred->_runInternal(Array, NULL, '', false)
#8 /home/sites/avforums/public_html/deferred.php(23): XenForo_Model_Deferred->run(false)
#9 {main}
Request State
array(3) {
["url"] => string(37) "https://www.avforums.com/deferred.php"
["_GET"] => array(0) {
}
["_POST"] => array(3) {
["_xfRequestUri"] => string(39) "/threads/tuning-samsung-hd2333.1269619/"
["_xfNoRedirect"] => string(1) "1"
["_xfResponseType"] => string(4) "json"
}
}
Click to expand...
 
Here is the INNODB status as requested
=====================================
141112 10:13:29 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 13 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2739737 1_second, 2739719 sleeps, 273929 10_second, 457 background, 456 flush
srv_master_thread log flush and writes: 2780499
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 8468109, signal count 102685304
Mutex spin waits 2791499327, rounds 2491101259, OS waits 2525938
RW-shared spins 22988675, rounds 131615410, OS waits 2734073
RW-excl spins 5353469, rounds 220914633, OS waits 2467597
Spin rounds per wait: 0.89 mutex, 5.73 RW-shared, 41.27 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
141112 10:02:18
*** (1) TRANSACTION:
TRANSACTION 1A3B53283, ACTIVE 3 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 2
MySQL thread id 88364939, OS thread handle 0x2b89453cd940, query id 3707956086 192.168.0.2 xfvbulletin update
INSERT INTO xf_deferred
(execute_class, execute_data, unique_key, manual_execute, trigger_date)
VALUES
('XenPushover_Deferred_Pushover', 'a:0:{}', 'XenPushoverQueue', '0', '1415786534')
ON DUPLICATE KEY UPDATE
execute_class = VALUES(execute_class),
execute_data = VALUES(execute_data),
manual_execute = VALUES(manual_execute),
trigger_date = VALUES(trigger_date)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 941 page no 3 n bits 88 index `PRIMARY` of table `xfavforums`.`xf_deferred` trx id 1A3B53283 lock_mode X locks rec but not gap waiting
Record lock, heap no 13 PHYSICAL RECORD: n_fields 8; compact format; info bits 32
0: len 4; hex 0021dfd4; asc ! ;;
1: len 6; hex 0001a3b53606; asc 6 ;;
2: len 7; hex 0d000056fd1123; asc V #;;
3: len 16; hex 58656e507573686f7665725175657565; asc XenPushoverQueue;;
4: len 29; hex 58656e507573686f7665725f44656665727265645f507573686f766572; asc XenPushover_Deferred_Pushover;;
5: len 6; hex 613a303a7b7d; asc a:0:{};;
6: len 1; hex 80; asc ;;
7: len 4; hex d4633024; asc c0$;;

*** (2) TRANSACTION:
TRANSACTION 1A3B53606, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
3 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 88365028, OS thread handle 0x2b8944bee940, query id 3707960349 192.168.0.2 xfvbulletin updating
DELETE FROM `xf_deferred` WHERE (deferred_id = 2219988)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 941 page no 3 n bits 88 index `PRIMARY` of table `xfavforums`.`xf_deferred` trx id 1A3B53606 lock_mode X locks rec but not gap
Record lock, heap no 13 PHYSICAL RECORD: n_fields 8; compact format; info bits 32
0: len 4; hex 0021dfd4; asc ! ;;
1: len 6; hex 0001a3b53606; asc 6 ;;
2: len 7; hex 0d000056fd1123; asc V #;;
3: len 16; hex 58656e507573686f7665725175657565; asc XenPushoverQueue;;
4: len 29; hex 58656e507573686f7665725f44656665727265645f507573686f766572; asc XenPushover_Deferred_Pushover;;
5: len 6; hex 613a303a7b7d; asc a:0:{};;
6: len 1; hex 80; asc ;;
7: len 4; hex d4633024; asc c0$;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 941 page no 4 n bits 168 index `unique_key` of table `xfavforums`.`xf_deferred` trx id 1A3B53606 lock_mode X locks rec but not gap waiting
Record lock, heap no 96 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 16; hex 58656e507573686f7665725175657565; asc XenPushoverQueue;;
1: len 4; hex 0021dfd4; asc ! ;;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 1A3B770CA
Purge done for trx's n:o < 1A3B76DD8 undo n:o < 0
History list length 717
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 88390552, OS thread handle 0x2b89475d3940, query id 3708951156 192.168.0.1 s8rc93d8238d2
SHOW ENGINE INNODB STATUS
---TRANSACTION 0, not started
MySQL thread id 88390551, OS thread handle 0x2b894c923940, query id 3708951158 192.168.0.1 xfvbulletin
---TRANSACTION 1A3B770C9, not started
MySQL thread id 88390550, OS thread handle 0x2b89472c7940, query id 3708951150 192.168.0.2 xfvbulletin
---TRANSACTION 1A3B770C8, not started
MySQL thread id 88390549, OS thread handle 0x2b8944cf2940, query id 3708951153 192.168.0.3 xfvbulletin
---TRANSACTION 1A3B770BD, not started
MySQL thread id 88390542, OS thread handle 0x2b89460c0940, query id 3708951143 192.168.0.1 xfvbulletin
---TRANSACTION 1A3B770BC, not started
MySQL thread id 88390541, OS thread handle 0x2b8947d71940, query id 3708951130 192.168.0.3 xfvbulletin
---TRANSACTION 1A3B770B4, not started
MySQL thread id 88390540, OS thread handle 0x2b89467dc940, query id 3708951105 192.168.0.3 xfvbulletin
---TRANSACTION 1A3B770C6, not started
MySQL thread id 88390532, OS thread handle 0x2b8945b6b940, query id 3708951126 192.168.0.1 xfvbulletin
--------
Click to expand...
 
...and the second bit because it's more than 10,000 characters...
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 (read thread)
I/O thread 7 state: waiting for completed aio requests (read thread)
I/O thread 8 state: waiting for completed aio requests (read thread)
I/O thread 9 state: waiting for completed aio requests (read thread)
I/O thread 10 state: waiting for completed aio requests (read thread)
I/O thread 11 state: waiting for completed aio requests (read thread)
I/O thread 12 state: waiting for completed aio requests (read thread)
I/O thread 13 state: waiting for completed aio requests (read thread)
I/O thread 14 state: waiting for completed aio requests (read thread)
I/O thread 15 state: waiting for completed aio requests (read thread)
I/O thread 16 state: waiting for completed aio requests (read thread)
I/O thread 17 state: waiting for completed aio requests (read thread)
I/O thread 18 state: waiting for completed aio requests (read thread)
I/O thread 19 state: waiting for completed aio requests (read thread)
I/O thread 20 state: waiting for completed aio requests (read thread)
I/O thread 21 state: waiting for completed aio requests (read thread)
I/O thread 22 state: waiting for completed aio requests (read thread)
I/O thread 23 state: waiting for completed aio requests (read thread)
I/O thread 24 state: waiting for completed aio requests (read thread)
I/O thread 25 state: waiting for completed aio requests (read thread)
I/O thread 26 state: waiting for completed aio requests (read thread)
I/O thread 27 state: waiting for completed aio requests (read thread)
I/O thread 28 state: waiting for completed aio requests (read thread)
I/O thread 29 state: waiting for completed aio requests (read thread)
I/O thread 30 state: waiting for completed aio requests (read thread)
I/O thread 31 state: waiting for completed aio requests (read thread)
I/O thread 32 state: waiting for completed aio requests (read thread)
I/O thread 33 state: waiting for completed aio requests (read thread)
I/O thread 34 state: waiting for completed aio requests (read thread)
I/O thread 35 state: waiting for completed aio requests (read thread)
I/O thread 36 state: waiting for completed aio requests (read thread)
I/O thread 37 state: waiting for completed aio requests (read thread)
I/O thread 38 state: waiting for completed aio requests (read thread)
I/O thread 39 state: waiting for completed aio requests (read thread)
I/O thread 40 state: waiting for completed aio requests (read thread)
I/O thread 41 state: waiting for completed aio requests (read thread)
I/O thread 42 state: waiting for completed aio requests (read thread)
I/O thread 43 state: waiting for completed aio requests (read thread)
I/O thread 44 state: waiting for completed aio requests (read thread)
I/O thread 45 state: waiting for completed aio requests (read thread)
I/O thread 46 state: waiting for completed aio requests (read thread)
I/O thread 47 state: waiting for completed aio requests (read thread)
I/O thread 48 state: waiting for completed aio requests (read thread)
I/O thread 49 state: waiting for completed aio requests (read thread)
I/O thread 50 state: waiting for completed aio requests (read thread)
I/O thread 51 state: waiting for completed aio requests (read thread)
I/O thread 52 state: waiting for completed aio requests (read thread)
I/O thread 53 state: waiting for completed aio requests (read thread)
I/O thread 54 state: waiting for completed aio requests (read thread)
I/O thread 55 state: waiting for completed aio requests (read thread)
I/O thread 56 state: waiting for completed aio requests (read thread)
I/O thread 57 state: waiting for completed aio requests (read thread)
I/O thread 58 state: waiting for completed aio requests (read thread)
I/O thread 59 state: waiting for completed aio requests (read thread)
I/O thread 60 state: waiting for completed aio requests (read thread)
I/O thread 61 state: waiting for completed aio requests (read thread)
I/O thread 62 state: waiting for completed aio requests (read thread)
I/O thread 63 state: waiting for completed aio requests (read thread)
I/O thread 64 state: waiting for completed aio requests (read thread)
I/O thread 65 state: waiting for completed aio requests (read thread)
I/O thread 66 state: waiting for completed aio requests (write thread)
I/O thread 67 state: waiting for completed aio requests (write thread)
I/O thread 68 state: waiting for completed aio requests (write thread)
I/O thread 69 state: waiting for completed aio requests (write thread)
I/O thread 70 state: waiting for completed aio requests (write thread)
I/O thread 71 state: waiting for completed aio requests (write thread)
I/O thread 72 state: waiting for completed aio requests (write thread)
I/O thread 73 state: waiting for completed aio requests (write thread)
I/O thread 74 state: waiting for completed aio requests (write thread)
I/O thread 75 state: waiting for completed aio requests (write thread)
I/O thread 76 state: waiting for completed aio requests (write thread)
I/O thread 77 state: waiting for completed aio requests (write thread)
I/O thread 78 state: waiting for completed aio requests (write thread)
I/O thread 79 state: waiting for completed aio requests (write thread)
I/O thread 80 state: waiting for completed aio requests (write thread)
I/O thread 81 state: waiting for completed aio requests (write thread)
I/O thread 82 state: waiting for completed aio requests (write thread)
I/O thread 83 state: waiting for completed aio requests (write thread)
I/O thread 84 state: waiting for completed aio requests (write thread)
I/O thread 85 state: waiting for completed aio requests (write thread)
I/O thread 86 state: waiting for completed aio requests (write thread)
I/O thread 87 state: waiting for completed aio requests (write thread)
I/O thread 88 state: waiting for completed aio requests (write thread)
I/O thread 89 state: waiting for completed aio requests (write thread)
I/O thread 90 state: waiting for completed aio requests (write thread)
I/O thread 91 state: waiting for completed aio requests (write thread)
I/O thread 92 state: waiting for completed aio requests (write thread)
I/O thread 93 state: waiting for completed aio requests (write thread)
I/O thread 94 state: waiting for completed aio requests (write thread)
I/O thread 95 state: waiting for completed aio requests (write thread)
I/O thread 96 state: waiting for completed aio requests (write thread)
I/O thread 97 state: waiting for completed aio requests (write thread)
I/O thread 98 state: waiting for completed aio requests (write thread)
I/O thread 99 state: waiting for completed aio requests (write thread)
I/O thread 100 state: waiting for completed aio requests (write thread)
I/O thread 101 state: waiting for completed aio requests (write thread)
I/O thread 102 state: waiting for completed aio requests (write thread)
I/O thread 103 state: waiting for completed aio requests (write thread)
I/O thread 104 state: waiting for completed aio requests (write thread)
I/O thread 105 state: waiting for completed aio requests (write thread)
I/O thread 106 state: waiting for completed aio requests (write thread)
I/O thread 107 state: waiting for completed aio requests (write thread)
I/O thread 108 state: waiting for completed aio requests (write thread)
I/O thread 109 state: waiting for completed aio requests (write thread)
I/O thread 110 state: waiting for completed aio requests (write thread)
I/O thread 111 state: waiting for completed aio requests (write thread)
I/O thread 112 state: waiting for completed aio requests (write thread)
I/O thread 113 state: waiting for completed aio requests (write thread)
I/O thread 114 state: waiting for completed aio requests (write thread)
I/O thread 115 state: waiting for completed aio requests (write thread)
I/O thread 116 state: waiting for completed aio requests (write thread)
I/O thread 117 state: waiting for completed aio requests (write thread)
I/O thread 118 state: waiting for completed aio requests (write thread)
I/O thread 119 state: waiting for completed aio requests (write thread)
I/O thread 120 state: waiting for completed aio requests (write thread)
I/O thread 121 state: waiting for completed aio requests (write thread)
I/O thread 122 state: waiting for completed aio requests (write thread)
I/O thread 123 state: waiting for completed aio requests (write thread)
I/O thread 124 state: waiting for completed aio requests (write thread)
I/O thread 125 state: waiting for completed aio requests (write thread)
I/O thread 126 state: waiting for completed aio requests (write thread)
I/O thread 127 state: waiting for completed aio requests (write thread)
I/O thread 128 state: waiting for completed aio requests (write thread)
I/O thread 129 state: waiting for completed aio requests (write thread)
Click to expand...
 
...and the third bit...
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 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
4521728 OS file reads, 645701392 OS file writes, 269098771 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 221.75 writes/s, 119.84 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5, seg size 7, 150617 merges
merged operations:
insert 123791, delete mark 791612, delete 11479
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 95624047, node heap has 162042 buffer(s)
40792.79 hash searches/s, 28644.10 non-hash searches/s
---
LOG
---
Log sequence number 5139046681032
Log flushed up to 5139046681032
Last checkpoint at 5139046322677
0 pending log writes, 0 pending chkp writes
257613645 log i/o's done, 116.61 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 49450844160; in additional pool allocated 0
Dictionary memory allocated 2472522
Buffer pool size 2949120
Free buffers 3
Database pages 2787075
Old database pages 1028802
Modified db pages 464
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 6449437, not young 0
1.69 youngs/s, 0.00 non-youngs/s
Pages read 4521573, created 1577618, written 381719280
0.00 reads/s, 0.00 creates/s, 103.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: 2787075, unzip_LRU len: 0
I/O sum[8504]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 29160, id 47867228113216, state: sleeping
Number of rows inserted 40953209, updated 239652068, deleted 11845645, read 231688306777
3.23 inserts/s, 56.00 updates/s, 0.23 deletes/s, 40702.95 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
Click to expand...
 
I'm not positive it's directly related. It'd just be creating more contention. The Galera/cluster comment may be the most relevant though (as it's creating deadlocks that don't actually exist and unfortunately are basically unavoidable in a system like the deferred jobs).
 

Similar threads

Mouth
Not a bug Rebuild User Caches - Mysqli statement execute error - Incorrect integer value
Replies
7
Views
1K
Mouth
Mouth
johndaroza
  • Question Question
i use Xenforo Enhanced Search have a error when i Rebuild Search Index
Replies
2
Views
2K
johndaroza
johndaroza
Mouth
Not a bug Server error from Usergroup Promotions
Replies
8
Views
1K
borbole
B
Back
Top Bottom