ostark/craft-async-queue

DB error (max-user-connections)

Closed this issue · 5 comments

JeanLucEsser commented

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

@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

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

  • Clearing all caches to start clean.
  • Going to CP > Utilities > Asset indexes > Update.
  • Indexing takes about 5 minutes, generating about 1000 jobs (transforms).
  • A single job is reserved at a time, no failed jobs.
  • Finishing all jobs takes about 15 minutes.
  • Whether runQueueAutomatically => true or running manually does not make a difference.

With Async queue / Concurrency set to 1

  • Clearing all caches to start clean.
  • Going to CP > Utilities > Asset indexes > Update.
  • Indexing takes hours, jobs are failing slowing down indexing.
  • 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).
  • Whether runQueueAutomatically => true or false does not make any difference.
  • Listening to the queue does not seem to show all errors as jobs continue to fail in parallel.

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

ostark commented

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

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

Related: #60