craftcms / cms

Build bespoke content experiences with Craft.
https://craftcms.com
Other
3.22k stars 627 forks source link

Can't login to the CMS anymore: Bugsnag error => Lock wait timeout exceeded; try restarting transaction UPDATE 'queue' #5098

Closed mdominguez closed 4 years ago

mdominguez commented 4 years ago

Description

Unable to get passed the admin login screen after logging in with the correct credentials. Error looks like it has something to do with the queue table.

Screenshot of the queue table: screenshot (is the amount of rows here normal?)

If you need our db, tell me where to send it :)

This is the exact error in Bugsnag:

Twig\Error\RuntimeError An exception has been thrown during the rendering of a template ("SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction
The SQL being executed was: UPDATE `queue` SET `dateReserved`=NULL, `timeUpdated`=NULL, `progress`=0, `progressLabel`=NULL WHERE `timeUpdated` < 1571058040 - `ttr`"). 
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/templates/_layouts/cp.html:50 Twig\Template::displayWithErrorHandling
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:380 Twig\Template::display
    /data/sites/web/ariadgroupcom/apps/production/shared/storage/runtime/compiled_templates/ed/edfec90cabb9edede3ade097921d641e5cd4f406cd00ed3b9fb05d781f12041b.php:48 __TwigTemplate_a17b6c84117af68f58e73049f388ce1f5dc0ca3454d6da3dd00f8d3abcc58735::doDisplay
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:407 Twig\Template::displayWithErrorHandling
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:380 Twig\Template::display
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:392 Twig\Template::render
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/TemplateWrapper.php:45 Twig\TemplateWrapper::render
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Environment.php:318 Twig\Environment::render
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/View.php:344 craft\web\View::renderTemplate
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/View.php:393 craft\web\View::renderPageTemplate
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Controller.php:243 craft\web\Controller::renderTemplate
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/controllers/DashboardController.php:136 craft\controllers\DashboardController::actionIndex
    [internal] call_user_func_array
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/InlineAction.php:57 yii\base\InlineAction::runWithParams
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/Controller.php:157 yii\base\Controller::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Controller.php:187 craft\web\Controller::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/Module.php:528 yii\base\Module::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Application.php:299 craft\web\Application::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/web/Application.php:103 yii\web\Application::handleRequest
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Application.php:284 craft\web\Application::handleRequest
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/Application.php:386 yii\base\Application::run
    /data/sites/web/ariadgroupcom/apps/production/releases/121/web/index.php:21 [main]

Caused by: yii\db\Exception SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction
The SQL being executed was: UPDATE `queue` SET `dateReserved`=NULL, `timeUpdated`=NULL, `progress`=0, `progressLabel`=NULL WHERE `timeUpdated` < 1571058040 - `ttr` 
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/db/Schema.php:664 yii\db\Schema::convertException
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/db/Command.php:1295 yii\db\Command::internalExecute
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/db/Command.php:1091 yii\db\Command::execute
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/queue/Queue.php:541 craft\queue\Queue::_moveExpired
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/queue/Queue.php:326 craft\queue\Queue::getJobInfo
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Extension/CoreExtension.php:1495 twig_get_attribute
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/helpers/Template.php:105 craft\helpers\Template::attribute
    /data/sites/web/ariadgroupcom/apps/production/shared/storage/runtime/compiled_templates/dc/dcc8b71cb4900af90f356251e56ddbad1a91b1cfa77db4f298c562deaa253e32.php:60 __TwigTemplate_2e31f7792279a3b72fe78439e546080897eff82e7fe019ef79ef69c45e2c81fe::doDisplay
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:407 Twig\Template::displayWithErrorHandling
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:380 Twig\Template::display
    /data/sites/web/ariadgroupcom/apps/production/shared/storage/runtime/compiled_templates/ed/edfec90cabb9edede3ade097921d641e5cd4f406cd00ed3b9fb05d781f12041b.php:48 __TwigTemplate_a17b6c84117af68f58e73049f388ce1f5dc0ca3454d6da3dd00f8d3abcc58735::doDisplay
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:407 Twig\Template::displayWithErrorHandling
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:380 Twig\Template::display
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:392 Twig\Template::render
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/TemplateWrapper.php:45 Twig\TemplateWrapper::render
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Environment.php:318 Twig\Environment::render
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/View.php:344 craft\web\View::renderTemplate
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/View.php:393 craft\web\View::renderPageTemplate
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Controller.php:243 craft\web\Controller::renderTemplate
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/controllers/DashboardController.php:136 craft\controllers\DashboardController::actionIndex
    [internal] call_user_func_array
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/InlineAction.php:57 yii\base\InlineAction::runWithParams
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/Controller.php:157 yii\base\Controller::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Controller.php:187 craft\web\Controller::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/Module.php:528 yii\base\Module::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Application.php:299 craft\web\Application::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/web/Application.php:103 yii\web\Application::handleRequest
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Application.php:284 craft\web\Application::handleRequest
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/Application.php:386 yii\base\Application::run
    /data/sites/web/ariadgroupcom/apps/production/releases/121/web/index.php:21 [main]

Caused by: PDOException SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction 
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/db/Command.php:1290 PDOStatement::execute
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/db/Command.php:1290 yii\db\Command::internalExecute
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/db/Command.php:1091 yii\db\Command::execute
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/queue/Queue.php:541 craft\queue\Queue::_moveExpired
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/queue/Queue.php:326 craft\queue\Queue::getJobInfo
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Extension/CoreExtension.php:1495 twig_get_attribute
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/helpers/Template.php:105 craft\helpers\Template::attribute
    /data/sites/web/ariadgroupcom/apps/production/shared/storage/runtime/compiled_templates/dc/dcc8b71cb4900af90f356251e56ddbad1a91b1cfa77db4f298c562deaa253e32.php:60 __TwigTemplate_2e31f7792279a3b72fe78439e546080897eff82e7fe019ef79ef69c45e2c81fe::doDisplay
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:407 Twig\Template::displayWithErrorHandling
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:380 Twig\Template::display
    /data/sites/web/ariadgroupcom/apps/production/shared/storage/runtime/compiled_templates/ed/edfec90cabb9edede3ade097921d641e5cd4f406cd00ed3b9fb05d781f12041b.php:48 __TwigTemplate_a17b6c84117af68f58e73049f388ce1f5dc0ca3454d6da3dd00f8d3abcc58735::doDisplay
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:407 Twig\Template::displayWithErrorHandling
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:380 Twig\Template::display
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Template.php:392 Twig\Template::render
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/TemplateWrapper.php:45 Twig\TemplateWrapper::render
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/twig/twig/src/Environment.php:318 Twig\Environment::render
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/View.php:344 craft\web\View::renderTemplate
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/View.php:393 craft\web\View::renderPageTemplate
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Controller.php:243 craft\web\Controller::renderTemplate
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/controllers/DashboardController.php:136 craft\controllers\DashboardController::actionIndex
    [internal] call_user_func_array
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/InlineAction.php:57 yii\base\InlineAction::runWithParams
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/Controller.php:157 yii\base\Controller::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Controller.php:187 craft\web\Controller::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/Module.php:528 yii\base\Module::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Application.php:299 craft\web\Application::runAction
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/web/Application.php:103 yii\web\Application::handleRequest
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/craftcms/cms/src/web/Application.php:284 craft\web\Application::handleRequest
    /data/sites/web/ariadgroupcom/apps/production/releases/121/vendor/yiisoft/yii2/base/Application.php:386 yii\base\Application::run
    /data/sites/web/ariadgroupcom/apps/production/releases/121/web/index.php:21 [main]

Additional info

punkch commented 4 years ago

I am experiencing similar issue from several days now, but I though it has something to do with my mysql setup.

I first noticed it with the craft_queue table, then I increased the innodb_lock_wait_timeout to 120 (default is 50). I've stopped seeing the issue with craft_queue, but it started with craft_elements and craft_structureelements. I have tried to repair table and indexes by executing i.e. ALTER TABLE craft_elements ENGINE=InnoDB with no joy. At the moment, I have the innodb_lock_wait_timeout set to 500 and haven't seen the error for about one hour.

Let me know if I can provide you with more information.

Stacktrace of the error:

2019-10-15 10:45:38 [-][68][-][error][yii\db\Exception] PDOException: SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction in /var/www/vendor/yiisoft/yii2/db/Command.php:1290
Stack trace:
#0 /var/www/vendor/yiisoft/yii2/db/Command.php(1290): PDOStatement->execute()
#1 /var/www/vendor/yiisoft/yii2/db/Command.php(1091): yii\db\Command->internalExecute('UPDATE `craft_e...')
#2 /var/www/vendor/yiisoft/yii2/db/ActiveRecord.php(332): yii\db\Command->execute()
#3 /var/www/vendor/yiisoft/yii2/db/BaseActiveRecord.php(810): yii\db\ActiveRecord::updateAll(Array, Array)
#4 /var/www/vendor/yiisoft/yii2/db/ActiveRecord.php(676): yii\db\BaseActiveRecord->updateInternal(NULL)
#5 /var/www/vendor/yiisoft/yii2/db/BaseActiveRecord.php(681): yii\db\ActiveRecord->update(false, NULL)
#6 /var/www/vendor/craftcms/cms/src/services/Elements.php(1912): yii\db\BaseActiveRecord->save(false)
#7 /var/www/vendor/craftcms/cms/src/services/Elements.php(488): craft\services\Elements->_saveElementInternal(Object(craft\elements\Entry), true, false)
#8 /var/www/vendor/craftcms/cms/src/controllers/EntryRevisionsController.php(224): craft\services\Elements->saveElement(Object(craft\elements\Entry))
#9 [internal function]: craft\controllers\EntryRevisionsController->actionSaveDraft()
#10 /var/www/vendor/yiisoft/yii2/base/InlineAction.php(57): call_user_func_array(Array, Array)
#11 /var/www/vendor/yiisoft/yii2/base/Controller.php(157): yii\base\InlineAction->runWithParams(Array)
#12 /var/www/vendor/craftcms/cms/src/web/Controller.php(187): yii\base\Controller->runAction('save-draft', Array)
#13 /var/www/vendor/yiisoft/yii2/base/Module.php(528): craft\web\Controller->runAction('save-draft', Array)
#14 /var/www/vendor/craftcms/cms/src/web/Application.php(299): yii\base\Module->runAction('entry-revisions...', Array)
#15 /var/www/vendor/craftcms/cms/src/web/Application.php(566): craft\web\Application->runAction('entry-revisions...', Array)
#16 /var/www/vendor/craftcms/cms/src/web/Application.php(278): craft\web\Application->_processActionRequest(Object(craft\web\Request))
#17 /var/www/vendor/yiisoft/yii2/base/Application.php(386): craft\web\Application->handleRequest(Object(craft\web\Request))
#18 /var/www/web/index.php(28): yii\base\Application->run()
#19 {main}

Next yii\db\Exception: SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction
The SQL being executed was: UPDATE `craft_elements` SET `draftId`=1761, `fieldLayoutId`=29, `enabled`=1, `archived`=0, `dateUpdated`='2019-10-15 08:43:37' WHERE `id`=38514 in /var/www/vendor/yiisoft/yii2/db/Schema.php:664
Stack trace:
#0 /var/www/vendor/yiisoft/yii2/db/Command.php(1295): yii\db\Schema->convertException(Object(PDOException), 'UPDATE `craft_e...')
#1 /var/www/vendor/yiisoft/yii2/db/Command.php(1091): yii\db\Command->internalExecute('UPDATE `craft_e...')
#2 /var/www/vendor/yiisoft/yii2/db/ActiveRecord.php(332): yii\db\Command->execute()
#3 /var/www/vendor/yiisoft/yii2/db/BaseActiveRecord.php(810): yii\db\ActiveRecord::updateAll(Array, Array)
#4 /var/www/vendor/yiisoft/yii2/db/ActiveRecord.php(676): yii\db\BaseActiveRecord->updateInternal(NULL)
#5 /var/www/vendor/yiisoft/yii2/db/BaseActiveRecord.php(681): yii\db\ActiveRecord->update(false, NULL)
#6 /var/www/vendor/craftcms/cms/src/services/Elements.php(1912): yii\db\BaseActiveRecord->save(false)
#7 /var/www/vendor/craftcms/cms/src/services/Elements.php(488): craft\services\Elements->_saveElementInternal(Object(craft\elements\Entry), true, false)
#8 /var/www/vendor/craftcms/cms/src/controllers/EntryRevisionsController.php(224): craft\services\Elements->saveElement(Object(craft\elements\Entry))
#9 [internal function]: craft\controllers\EntryRevisionsController->actionSaveDraft()
#10 /var/www/vendor/yiisoft/yii2/base/InlineAction.php(57): call_user_func_array(Array, Array)
#11 /var/www/vendor/yiisoft/yii2/base/Controller.php(157): yii\base\InlineAction->runWithParams(Array)
#12 /var/www/vendor/craftcms/cms/src/web/Controller.php(187): yii\base\Controller->runAction('save-draft', Array)
#13 /var/www/vendor/yiisoft/yii2/base/Module.php(528): craft\web\Controller->runAction('save-draft', Array)
#14 /var/www/vendor/craftcms/cms/src/web/Application.php(299): yii\base\Module->runAction('entry-revisions...', Array)
#15 /var/www/vendor/craftcms/cms/src/web/Application.php(566): craft\web\Application->runAction('entry-revisions...', Array)
#16 /var/www/vendor/craftcms/cms/src/web/Application.php(278): craft\web\Application->_processActionRequest(Object(craft\web\Request))
#17 /var/www/vendor/yiisoft/yii2/base/Application.php(386): craft\web\Application->handleRequest(Object(craft\web\Request))
#18 /var/www/web/index.php(28): yii\base\Application->run()
#19 {main}
Additional Information:
Array
(
    [0] => HY000
    [1] => 1205
    [2] => Lock wait timeout exceeded; try restarting transaction
)
"
Show matching entries
Hide matching entries
Add field to summary line

 timestamp: "2019-10-15T08:45:38.925367Z"  
}

Additional info

mdominguez commented 4 years ago

If this helps: our project where this occurs also contains heavy use of Neo 2.5.4 ...

punkch commented 4 years ago

I've managed to catch it while waiting for the lock. Basically, our users were rearranging the entries inside one of our structures. We have something like 25k rows in craft_structureelements and all the entries in our three structures have nested urls.

If of any help, below is a portion of show engine innodb status;

mysql tables in use 1, locked 1
LOCK WAIT 94 lock struct(s), heap size 24784, 753 row lock(s), undo log entries 5
MySQL thread id 420608, OS thread handle 139669489399552, query id 45555957 cloudsqlproxy~35.240.28.74 craftcms Searching rows for update
UPDATE `craft_structureelements` SET `lft`=`lft`+2, `dateUpdated`='2019-10-15 13:19:56' WHERE (`lft` >= 2608) AND (`root`=949)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 623 page no 324 n bits 1272 index craft_structureelements_lft_idx of table `craftcms`.`craft_structureelements` trx id 29508094 lock_mode X waiting
Record lock, heap no 773 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 00000d9e; asc     ;;
 1: len 4; hex 8001e3ca; asc     ;;

*** (2) TRANSACTION:
TRANSACTION 29508024, ACTIVE 3 sec fetching rows
mysql tables in use 1, locked 1
73 lock struct(s), heap size 8400, 319 row lock(s), undo log entries 294
MySQL thread id 420604, OS thread handle 139671263672064, query id 45555966 cloudsqlproxy~35.240.28.74 craftcms updating
DELETE FROM `craft_structureelements` WHERE ((`lft` >= 936) AND (`rgt` <= 937)) AND (`root`=32)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 623 page no 324 n bits 1272 index craft_structureelements_lft_idx of table `craftcms`.`craft_structureelements` trx id 29508024 lock_mode X locks rec but not gap
Record lock, heap no 773 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 00000d9e; asc     ;;
 1: len 4; hex 8001e3ca; asc     ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 623 page no 10 n bits 232 index PRIMARY of table `craftcms`.`craft_structureelements` trx id 29508024 lock_mode X locks rec but not gap waiting
Record lock, heap no 99 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
 0: len 4; hex 80000167; asc    g;;
 1: len 6; hex 000001c22ec8; asc     . ;;
 2: len 7; hex 3a0000043c1ab7; asc :   <  ;;
 3: len 4; hex 80000005; asc     ;;
 4: len 4; hex 80000127; asc    ';;
 5: len 4; hex 00000020; asc     ;;
 6: len 4; hex 00000bb6; asc     ;;
 7: len 4; hex 00000bb7; asc     ;;
 8: len 2; hex 0001; asc   ;;
 9: len 5; hex 99a39eda02; asc      ;;
 10: len 5; hex 99a45ed437; asc   ^ 7;;
 11: len 30; hex 36393534303239342d653833612d343532632d626137312d356339626637; asc 69540294-e83a-452c-ba71-5c9bf7; (total 36 bytes);
angrybrad commented 4 years ago

@punkch @mdominguez these are likely two separate issues.

@punkch if you've got 3 structures with a total of 25k rows and you make a change to the hierarchy (especially on a higher level), then that's an expensive operation. Craft will have to go through each descendant and update things like their nested URI format as well as their position in the structure. If you add multiple users doing those expensive operations at the same time, then I can see where MySQL would hit the default wait lock timeout.

@mdominguez For yours I'd start by seeing why there are 5,000 jobs in the queue. Are none of them processing?

mdominguez commented 4 years ago

@angrybrad Well if I check now, the queue table is empty, so they indeed get processed. We also have a synchronisation running with Bullhorn recruiting software, which retrieves job listings created in Bullhorn and adds/updates them as entries in Craft every hour. Maybe this could have something to do with the fact the queue gets so full every now and then? If that's not the case, how could I determine if processing works like intended?

punkch commented 4 years ago

@angrybrad Thank you for the quick reply. Just to clarify, the number of entries in each structure is around 150 (so 450 in total). The count in craft_structureelements is 25k. For now I'll just limit the number of revisions and have structure reorganizations happen only during maintenance windows and see how it goes. If you want me to open a new issue, or provide more information let me know.

angrybrad commented 4 years ago

@mdominguez

Maybe this could have something to do with the fact the queue gets so full every now and then?

Entirely likely. Maybe look into staggering or batching the entry creation to give your servers enough time to process the results.

@punkch Sounds good.

These deadlock types of issues are difficult to debug because they often depend on server load, server hardware, traffic, plugins, etc.

Going to go ahead and close, but feel free to comment again if anything new comes up.

punkch commented 4 years ago

Hi @angrybrad,

I could reproduce the issue @mdominguez described. Basically, on multiple occasions my users have complained that nobody can login in the admin panel while at the same time the "frontend" was running just fine.

In MySQL's show processlist; , I've noticed several queries like the mentioned UPDATE `craft_queue` SET `dateReserved`=NULL, `timeUpdated`=NULL, `progress`=0, `progressLabel`=NULL WHERE `timeUpdated` < 1571320464 - `ttr` having status "Searching for rows to update". On these occasions, the craft_queue table had between 6 and 50 rows.

I've tried adding an index on timeUpdate and ttr, so to improve this query's lock wait times but this didn't help at all. Then, I've commented out this line and it seems to help. What do you think?

brandonkelly commented 4 years ago

@punkch Can you try changing your craftcms/cms requirement in composer.json to:

"require": {
  "craftcms/cms": "dev-develop#a294c07b6ed848bc37a1ba1ca63f883f06199fcf as 3.3.11",
  "...": "..."
}

And then run composer update and see if that helps?

punkch commented 4 years ago

Hi @brandonkelly

I've tried this, but then started getting errors when doing project-config/sync So, I'll just wait for when this gets officially released and revert with the outcome.

error: Calling unknown method: craft\services\Gql::invalidateResultCaches()
2019-10-21 13:47:33 [-][-][-][error][yii\base\UnknownMethodException] yii\base\UnknownMethodException: Calling unknown method: craft\services\Gql::invalidateResultCaches() in /var/www/vendor/yiisoft/yii2/base/Component.php:300
Stack trace:
#0 [internal function]: yii\base\Component->__call('invalidateResul...', Array)
#1 /var/www/vendor/yiisoft/yii2/base/Component.php(627): call_user_func(Array, Object(yii\base\Event))
#2 /var/www/vendor/craftcms/cms/src/services/ProjectConfig.php(983): yii\base\Component->trigger('afterApplyChang...')
#3 /var/www/vendor/craftcms/cms/src/services/ProjectConfig.php(436): craft\services\ProjectConfig->_applyChanges(Array)
#4 /var/www/vendor/craftcms/cms/src/console/controllers/ProjectConfigController.php(87): craft\services\ProjectConfig->applyYamlChanges()
#5 [internal function]: craft\console\controllers\ProjectConfigController->actionSync()
#6 /var/www/vendor/yiisoft/yii2/base/InlineAction.php(57): call_user_func_array(Array, Array)
#7 /var/www/vendor/yiisoft/yii2/base/Controller.php(157): yii\base\InlineAction->runWithParams(Array)
#8 /var/www/vendor/yiisoft/yii2/console/Controller.php(148): yii\base\Controller->runAction('sync', Array)
#9 /var/www/vendor/craftcms/cms/src/console/Controller.php(199): yii\console\Controller->runAction('sync', Array)
#10 /var/www/vendor/yiisoft/yii2/base/Module.php(528): craft\console\Controller->runAction('sync', Array)
#11 /var/www/vendor/yiisoft/yii2/console/Application.php(180): yii\base\Module->runAction('project-config/...', Array)
#12 /var/www/vendor/craftcms/cms/src/console/Application.php(93): yii\console\Application->runAction('project-config/...', Array)
#13 /var/www/vendor/yiisoft/yii2/console/Application.php(147): craft\console\Application->runAction('project-config/...', Array)
#14 /var/www/vendor/yiisoft/yii2/base/Application.php(386): yii\console\Application->handleRequest(Object(craft\console\Request))
#15 /var/www/craft(24): yii\base\Application->run()
#16 {main}
brandonkelly commented 4 years ago

@punkch Sorry, that was fixed in d703b4c0898ac96f923bf35a4eea630b5b761fb5. If you do want to try again, go with this instead:

"require": {
  "craftcms/cms": "dev-develop#b8b1ac5541a062b423cdb97207817ed23092c92e as 3.3.11",
  "...": "..."
}
mtwalsh commented 4 years ago

We're also seeing instances of a very similar error (the site also uses Neo):

An exception has been thrown during the rendering of a template ("SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction The SQL being executed was: UPDATE queue SET dateReserved=NULL, timeUpdated=NULL, progress=0, progressLabel=NULL WHERE (fail=FALSE) AND (timeUpdated < 1581671136 - ttr)").

We have a client's admin panel down at the moment, while the front-end of the site is still working. It seems to be pushing our Amazon RDS instances to way above average selects per second.

Additional info

Craft version: 3.3.20.1 PHP version: 7.3.14 Database driver & version: MySQL 5.6.10 (AWS Aurora with read/write splitting) Neo: 2.5.10

Sample of queries we are seeing

SELECT id, structureId, ownerId, ownerSiteId, fieldId FROM neoblockstructures WHERE (fieldId=220) AND (ownerId=28645) AND (ownerSiteId=1) LIMIT 1

DELETE FROM neoblockstructures WHERE (id='8925') AND (ownerId='28645') AND (ownerSiteId='1') AND (fieldId='220')

UPDATE queue SET dateReserved=NULL, timeUpdated=NULL, progress=0, progressLabel=NULL WHERE (fail=0) AND (timeUpdated < 1581669320 - ttr)

brandonkelly commented 4 years ago

@mtwalsh please write into support@craftcms.com about that.

aaronbushnell commented 4 years ago

Hey @mtwalsh and @brandonkelly i was curious what you found to be the issue. I’ve seen similar MySQL lock timeout errors and was wondering what helped you out here.

brandonkelly commented 4 years ago

@aaronbushnell Good starting point is to swap your searchindex table to the InnoDB engine.

mtwalsh commented 4 years ago

@aaronbushnell Within an hour the problem had cleared for us. We've since moved queues to Redis and haven't had any repeat occurrences although can't be sure if that has resolved the issue.

aaronbushnell commented 4 years ago

Hey @mtwalsh! Did moving the queues to Redis fix this problem for ya? Curious if it's still an issue on your side.

Also, @brandonkelly, what's the best/safest way to swap the table engine? Should I write up a migration for it?

brandonkelly commented 4 years ago

@aaronbushnell Run this SQL query:

ALTER TABLE searchindex ENGINE = InnoDB;
aaronbushnell commented 4 years ago

@brandonkelly Looks like our craft_searchindex is housing 500K rows of data. Is it okay to TRUNCATE the table and then change the engine after? Or should I avoid that?

brandonkelly commented 4 years ago

Sure you can truncate and then run ./craft resave/entries --update-search-index, etc. after changing the engine, to rebuild the search indexes.

mtwalsh commented 4 years ago

@aaronbushnell Yes, since switching queues to Redis we haven't had any further issues but as in my previous comment I can't be sure if that is what resolved the issue as there were some Craft CMS updates in the mix also.

Also, running resave/entries is trivial on small sites but when we have run it on a large site with ~50k entries you are looking at quite a long running process e.g. several hours. It will get there but make sure you have sufficient headroom in your hosting setup to cope.