search

ostark / craft-async-queue

Async Queue Handler for Craft 3 and 4
MIT License
93 stars 7 forks source link

DB error (max-user-connections) #55

Closed JeanLucEsser closed 2 years ago

JeanLucEsser commented 2 years ago

Hi there,

I'm typically using your plugin with ImageOptimize but I deactivated it so I can isolate the issue.

I have a fairly simple setup, using AWS S3 bucket with CloudFront for all my assets. Without your plugin, going to the CP and updating asset indexes works fine. With your plugin installed, doing the same takes way more time and generates errors both in console.log and queue.log: User 'xxx' has exceeded the 'max_user_connections' resource (current value: 10)'. This is on a staging environment on fortrabbit FWIW.

Concurrency is set to 1. Craft 4.0.3 / Plugin 3.0

ostark commented 2 years ago

@JeanLucEsser Can you reproduce the behavior when you set runQueueAutomatically => false in config/general and run the queue listener on the command line?

php craft queue/listen -v
JeanLucEsser commented 2 years ago

Yes.

I have something like 200 fairly large images locally (not using S3 here to minimize the number of plugins). I have ImageOptimize installed and configured for about 5 transforms per image.

Without Async queue

With Async queue / Concurrency set to 1

Should you need me to try something to help you reproduce, let me know.

ostark commented 2 years ago

More than 50 jobs are reserved at a time (!), failed jobs are many (max_user_connections in the DB if set, or literally bringing the server to its knees with memory errors).

Can you provide log lines (Craft debug logs) that contain the string "RateLimiter"?

JeanLucEsser commented 2 years ago

Where do you want me to look for this? I found a reference to RateLimiter in the runtime debug data in the form of a query:

INSERT INTO `queue` (`channel`, `job`, `description`, `timePushed`, `ttr`, `delay`, `priority`) VALUES ('queue', 'O:52:\"nystudio107\\imageoptimize\\jobs\\ResaveOptimizedImages\":6:{s:11:\"description\";s:24:\"Optimizing image id 1115\";s:30:\"\0craft\\queue\\BaseJob\0_progress\";i:0;s:35:\"\0craft\\queue\\BaseJob\0_progressLabel\";N;s:8:\"criteria\";a:2:{s:2:\"id\";i:1115;s:6:\"status\";N;}s:7:\"fieldId\";N;s:5:\"force\";b:0;}', 'Optimizing image id 1115', 1654335506, 300, 0, 1024)";i:1;i:8;i:2;s:23:"yii\db\Command::execute";i:3;d:1654335506.465429;i:4;a:0:{}i:5;i:35691576;}i:141;a:6:{i:0;s:55:"RateLimiter (0 of 1, context: Optimizing image id 1115)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335506.500746;i:4;a:0:{}i:5;i:35701896;}i:142;a:6:{i:0;s:58:"New PushEvent for Optimizing image id 1115 job - (handled)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.068521;i:4;a:0:{}i:5;i:36018416;}i:143;a:6:{i:0;s:55:"Started resaveAsset queue job id: 7844 Element id: 1115";i:1;i:8;i:2;s:63:"nystudio107\imageoptimize\services\OptimizedImages::resaveAsset";i:3;d:1654335507.068785;i:4;a:0:{}i:5;i:36013064;}i:144;a:6:{i:0;s:498:"SQL query:
INSERT INTO `queue` (`channel`, `job`, `description`, `timePushed`, `ttr`, `delay`, `priority`) VALUES ('queue', 'O:52:\"nystudio107\\imageoptimize\\jobs\\ResaveOptimizedImages\":6:{s:11:\"description\";s:24:\"Optimizing image id 1115\";s:30:\"\0craft\\queue\\BaseJob\0_progress\";i:0;s:35:\"\0craft\\queue\\BaseJob\0_progressLabel\";N;s:8:\"criteria\";a:2:{s:2:\"id\";i:1115;s:6:\"status\";N;}s:7:\"fieldId\";N;s:5:\"force\";b:0;}', 'Optimizing image id 1115', 1654335507, 300, 0, 1024)";i:1;i:8;i:2;s:23:"yii\db\Command::execute";i:3;d:1654335507.071801;i:4;a:0:{}i:5;i:36024664;}i:147;a:6:{i:0;s:55:"RateLimiter (1 of 1, context: Optimizing image id 1115)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.095618;i:4;a:0:{}i:5;i:36023088;}i:148;a:6:{i:0;s:58:"New PushEvent for Optimizing image id 1115 job - (skipped)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.095636;i:4;a:0:{}i:5;i:36023720;}i:149;a:6:{i:0;s:55:"Started resaveAsset queue job id: 7845 Element id: 1115";i:1;i:8;i:2;s:63:"nystudio107\imageoptimize\services\OptimizedImages::resaveAsset";i:3;d:1654335507.095651;i:4;a:0:{}i:5;i:36018368;}i:150;a:6:{i:0;s:498:"SQL query:
INSERT INTO `queue` (`channel`, `job`, `description`, `timePushed`, `ttr`, `delay`, `priority`) VALUES ('queue', 'O:52:\"nystudio107\\imageoptimize\\jobs\\ResaveOptimizedImages\":6:{s:11:\"description\";s:24:\"Optimizing image id 1115\";s:30:\"\0craft\\queue\\BaseJob\0_progress\";i:0;s:35:\"\0craft\\queue\\BaseJob\0_progressLabel\";N;s:8:\"criteria\";a:2:{s:2:\"id\";i:1115;s:6:\"status\";N;}s:7:\"fieldId\";N;s:5:\"force\";b:0;}', 'Optimizing image id 1115', 1654335507, 300, 0, 1024)";i:1;i:8;i:2;s:23:"yii\db\Command::execute";i:3;d:1654335507.095855;i:4;a:0:{}i:5;i:36029968;}i:153;a:6:{i:0;s:55:"RateLimiter (1 of 1, context: Optimizing image id 1115)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.096203;i:4;a:0:{}i:5;i:36028392;}i:154;a:6:{i:0;s:58:"New PushEvent for Optimizing image id 1115 job - (skipped)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.096206;i:4;a:0:{}i:5;i:36029024;}i:155;a:6:{i:0;s:55:"Started resaveAsset queue job id: 7846 Element id: 1115";i:1;i:8;i:2;s:63:"nystudio107\imageoptimize\services\OptimizedImages::resaveAsset";i:3;d:1654335507.09621;i:4;a:0:{}i:5;i:36023672;}i:156;a:6:{i:0;s:498:"SQL query:
INSERT INTO `queue` (`channel`, `job`, `description`, `timePushed`, `ttr`, `delay`, `priority`) VALUES ('queue', 'O:52:\"nystudio107\\imageoptimize\\jobs\\ResaveOptimizedImages\":6:{s:11:\"description\";s:24:\"Optimizing image id 1115\";s:30:\"\0craft\\queue\\BaseJob\0_progress\";i:0;s:35:\"\0craft\\queue\\BaseJob\0_progressLabel\";N;s:8:\"criteria\";a:2:{s:2:\"id\";i:1115;s:6:\"status\";N;}s:7:\"fieldId\";N;s:5:\"force\";b:0;}', 'Optimizing image id 1115', 1654335507, 300, 0, 1024)";i:1;i:8;i:2;s:23:"yii\db\Command::execute";i:3;d:1654335507.096325;i:4;a:0:{}i:5;i:36035272;}i:159;a:6:{i:0;s:55:"RateLimiter (1 of 1, context: Optimizing image id 1115)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.096554;i:4;a:0:{}i:5;i:36033696;}i:160;a:6:{i:0;s:58:"New PushEvent for Optimizing image id 1115 job - (skipped)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.096557;i:4;a:0:{}i:5;i:36034328;}i:161;a:6:{i:0;s:55:"Started resaveAsset queue job id: 7847 Element id: 1115";i:1;i:8;i:2;s:63:"nystudio107\imageoptimize\services\OptimizedImages::resaveAsset";i:3;d:1654335507.096562;i:4;a:0:{}i:5;i:36028976;}i:162;a:6:{i:0;s:498:"SQL query:
INSERT INTO `queue` (`channel`, `job`, `description`, `timePushed`, `ttr`, `delay`, `priority`) VALUES ('queue', 'O:52:\"nystudio107\\imageoptimize\\jobs\\ResaveOptimizedImages\":6:{s:11:\"description\";s:24:\"Optimizing image id 1115\";s:30:\"\0craft\\queue\\BaseJob\0_progress\";i:0;s:35:\"\0craft\\queue\\BaseJob\0_progressLabel\";N;s:8:\"criteria\";a:2:{s:2:\"id\";i:1115;s:6:\"status\";N;}s:7:\"fieldId\";N;s:5:\"force\";b:0;}', 'Optimizing image id 1115', 1654335507, 300, 0, 1024)";i:1;i:8;i:2;s:23:"yii\db\Command::execute";i:3;d:1654335507.096659;i:4;a:0:{}i:5;i:36040576;}i:165;a:6:{i:0;s:55:"RateLimiter (1 of 1, context: Optimizing image id 1115)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.096829;i:4;a:0:{}i:5;i:36039000;}i:166;a:6:{i:0;s:58:"New PushEvent for Optimizing image id 1115 job - (skipped)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.096832;i:4;a:0:{}i:5;i:36039632;}i:167;a:6:{i:0;s:55:"Started resaveAsset queue job id: 7848 Element id: 1115";i:1;i:8;i:2;s:63:"nystudio107\imageoptimize\services\OptimizedImages::resaveAsset";i:3;d:1654335507.096837;i:4;a:0:{}i:5;i:36034280;}i:168;a:6:{i:0;s:498:"SQL query:
INSERT INTO `queue` (`channel`, `job`, `description`, `timePushed`, `ttr`, `delay`, `priority`) VALUES ('queue', 'O:52:\"nystudio107\\imageoptimize\\jobs\\ResaveOptimizedImages\":6:{s:11:\"description\";s:24:\"Optimizing image id 1115\";s:30:\"\0craft\\queue\\BaseJob\0_progress\";i:0;s:35:\"\0craft\\queue\\BaseJob\0_progressLabel\";N;s:8:\"criteria\";a:2:{s:2:\"id\";i:1115;s:6:\"status\";N;}s:7:\"fieldId\";N;s:5:\"force\";b:0;}', 'Optimizing image id 1115', 1654335507, 300, 0, 1024)";i:1;i:8;i:2;s:23:"yii\db\Command::execute";i:3;d:1654335507.096948;i:4;a:0:{}i:5;i:36045880;}i:171;a:6:{i:0;s:55:"RateLimiter (1 of 1, context: Optimizing image id 1115)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.097099;i:4;a:0:{}i:5;i:36044304;}i:172;a:6:{i:0;s:58:"New PushEvent for Optimizing image id 1115 job - (skipped)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.097102;i:4;a:0:{}i:5;i:36044936;}i:173;a:6:{i:0;s:55:"Started resaveAsset queue job id: 7849 Element id: 1115";i:1;i:8;i:2;s:63:"nystudio107\imageoptimize\services\OptimizedImages::resaveAsset";i:3;d:1654335507.097106;i:4;a:0:{}i:5;i:36039584;}i:174;a:6:{i:0;s:18:"Commit transaction";i:1;i:8;i:2;s:26:"yii\db\Transaction::commit";i:3;d:1654335507.099428;i:4;a:0:{}i:5;i:36041184;}i:175;a:6:{i:0;s:496:"SQL query:
INSERT INTO `queue` (`channel`, `job`, `description`, `timePushed`, `ttr`, `delay`, `priority`) VALUES ('queue', 'O:34:\"craft\\queue\\jobs\\UpdateSearchIndex\":7:{s:11:\"description\";N;s:30:\"\0craft\\queue\\BaseJob\0_progress\";i:0;s:35:\"\0craft\\queue\\BaseJob\0_progressLabel\";N;s:11:\"elementType\";s:20:\"craft\\elements\\Asset\";s:9:\"elementId\";i:1115;s:6:\"siteId\";i:1;s:12:\"fieldHandles\";a:0:{}}', 't9n:[\"app\",\"Updating search indexes\"]', 1654335507, 300, 0, 2048)";i:1;i:8;i:2;s:23:"yii\db\Command::execute";i:3;d:1654335507.54182;i:4;a:0:{}i:5;i:36075296;}i:178;a:6:{i:0;s:68:"RateLimiter (1 of 1, context: t9n:["app","Updating search indexes"])";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.567209;i:4;a:0:{}i:5;i:36073784;}i:179;a:6:{i:0;s:71:"New PushEvent for t9n:["app","Updating search indexes"] job - (skipped)";i:1;i:8;i:2;s:11:"async-queue";i:3;d:1654335507.567267;i:4;a:0:{}i:5;i:36074416;}i:180;a:6:{i:0;s:34:"Elements::EVENT_AFTER_SAVE_ELEMENT";i:1;i:8;i:2;s:30:"nystudio107\seomatic\{closure}";i:3;d:1654335507.568222;i:4;a:0:{}i:5;i:36070752;}i:181;a:6:{i:0;s:136:"SQL query:

Not sure that's what you are looking for.

ostark commented 2 years ago

Related: https://github.com/ostark/craft-async-queue/issues/60