Struggling to process 100,000+ jobs #1091

rmontgomery429 · 2023-09-28T04:02:41Z

rmontgomery429
Sep 28, 2023

I've been struggling to get Good Job to play well with a large number of jobs and I feel like I haven't even really pushed it yet. I have only maybe 150,000 jobs in queue and they've kind of just been hanging there even when I scale the workers up from 1 to 10. No real change in throughput.

Here are some of the env vars I've set:

GOOD_JOB_MAX_THREADS=8
GOOD_JOB_QUEUES=+default,low
GOOD_JOB_QUEUE_SELECT_LIMIT=1000
DATABASE_POOL=8
RAILS_MAX_THREADS=8
WEB_CONCURENCY=8

I am on Heroku so there is a 30 second timeout limit for accessing the UI but ... why does it take so long? It should only take a second to read a few tables. There is plenty of bandwidth on the server to serve the request. With 64 web processes my main website is running fine and is usable and both are talking to the same database running on the same webserver.

I have maybe 150,000 job in the low queue and 32 GoodJob threads (8 MAX_THREADS * 4 workers processes) seems like it would be a lot more productive given that these jobs seem to be taking less than 50 ms to complete.

In an entire hour it was only able to process 791 jobs. 😳 (I made this graph with a direct query of the Good Jobs table directly given that I can't access the Web UI)

This is all I get when I try to go to the UI to investigate what's going on.

Is there another setting I'm missing? Is high volume jobs a problem for the way it handles locking?

Answered by bensheldon

Sep 28, 2023

Yep, that's a very good sign!

I have one more experiment for you to try. Could you try running GoodJob.perform_inline("+default,low")? That will dequeue in order by queue that you have configured and I have a hypothesis that using the + results in a not very performant query. I could be wrong though.

Regardless, I'd still recommend that you ran separate threadpools for your queues e.g. GOOD_JOB_QUEUES=default:2;low:2 (with the semicolon) because that will give you better quality of service.

View full answer

bensheldon · 2023-09-28T05:15:40Z

bensheldon
Sep 28, 2023
Maintainer

hmm, that seems unexpected to me.

Do you have Heroku+Rails console access (heroku console bin/rails c) ? If you do, you could try running GoodJob.perform_inline in the console, which will start dequeuing and executing jobs right there. That would give you a sense of the theoretical maximum throughput of a single thread.

If you're able to run that experiment, I think that would help diagnose whether the bottleneck is in dequeuing a job, or whether it's in the concurrency.

If the problem is in dequeuing the job, I'd expect you to see a very slow database query. Then that would mean taking a look at indexes and doublechecking the queue_select_limit or looking at your database itself and trying to figure out why that's slow. (The query does get slower with the number of jobs on the queue because it involves a materialized CTE, but I don't think your queue is problematically deep.)
If the problem is in concurrency, then that would mean that not all of your resources/threads are engaged, or there is some other bottleneck (e.g. your database connection pool isn't large enough, or there's a typo in one of the configuration settings, or something in that nature)

0 replies

rmontgomery429 · 2023-09-28T05:20:35Z

rmontgomery429
Sep 28, 2023
Author

Thank you so much for responding so quickly. 🙏 Yes I do have heroku rails console access. Running GoodJob.perform_inline seems to be running jobs pretty quickly.

Performed ActivityJob (Job ID: 9a700c49-118b-4645-9a6d-9610522e9978) from GoodJob(low) in 0.23ms
Executed GoodJob 9a700c49-118b-4645-9a6d-9610522e9978
Performing ActivityJob (Job ID: 7a27d3d5-defb-4545-ad71-82f170ffea9e) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: 7a27d3d5-defb-4545-ad71-82f170ffea9e) from GoodJob(low) in 0.3ms
Executed GoodJob 7a27d3d5-defb-4545-ad71-82f170ffea9e
Performing ActivityJob (Job ID: 6b863ae6-ee39-4275-a1ea-931a742c2c6d) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: 6b863ae6-ee39-4275-a1ea-931a742c2c6d) from GoodJob(low) in 0.27ms
Executed GoodJob 6b863ae6-ee39-4275-a1ea-931a742c2c6d
Performing ActivityJob (Job ID: 7224c764-35a6-47a8-a654-56d9f6a9199a) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: 7224c764-35a6-47a8-a654-56d9f6a9199a) from GoodJob(low) in 0.29ms
Executed GoodJob 7224c764-35a6-47a8-a654-56d9f6a9199a
Performing ActivityJob (Job ID: 80e2e576-5ec4-4f00-9c34-43cb5b4a8bf4) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: 80e2e576-5ec4-4f00-9c34-43cb5b4a8bf4) from GoodJob(low) in 0.22ms
Executed GoodJob 80e2e576-5ec4-4f00-9c34-43cb5b4a8bf4
Performing ActivityJob (Job ID: 0d43a718-379d-4449-81ae-72249cb37a6e) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: 0d43a718-379d-4449-81ae-72249cb37a6e) from GoodJob(low) in 0.27ms
Executed GoodJob 0d43a718-379d-4449-81ae-72249cb37a6e
Performing ActivityJob (Job ID: bca37960-3295-4569-b863-cda01f3b163f) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: bca37960-3295-4569-b863-cda01f3b163f) from GoodJob(low) in 0.23ms
Executed GoodJob bca37960-3295-4569-b863-cda01f3b163f
Performing ActivityJob (Job ID: f78a76ff-55f9-4b17-be3b-e69c0762e9e8) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: f78a76ff-55f9-4b17-be3b-e69c0762e9e8) from GoodJob(low) in 0.52ms
Executed GoodJob f78a76ff-55f9-4b17-be3b-e69c0762e9e8
Performing ActivityJob (Job ID: e2e742fd-091a-484c-9db2-5ddf9e6caaf3) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: e2e742fd-091a-484c-9db2-5ddf9e6caaf3) from GoodJob(low) in 5.12ms
Executed GoodJob e2e742fd-091a-484c-9db2-5ddf9e6caaf3
Performing ActivityJob (Job ID: bad69887-798c-4475-9a59-18694ac2ad49) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: bad69887-798c-4475-9a59-18694ac2ad49) from GoodJob(low) in 0.33ms
Executed GoodJob bad69887-798c-4475-9a59-18694ac2ad49
Performing ActivityJob (Job ID: a73cba63-c593-42bf-95a3-edfaa59cbe89) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: a73cba63-c593-42bf-95a3-edfaa59cbe89) from GoodJob(low) in 0.22ms
Executed GoodJob a73cba63-c593-42bf-95a3-edfaa59cbe89
Performing ActivityJob (Job ID: de1a2e98-8e9d-4207-8d6f-705e0a452f9a) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: de1a2e98-8e9d-4207-8d6f-705e0a452f9a) from GoodJob(low) in 0.27ms
Executed GoodJob de1a2e98-8e9d-4207-8d6f-705e0a452f9a
Performing ActivityJob (Job ID: 315bfb55-ec2e-4bfa-ac75-d7a495fecbbb) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: 315bfb55-ec2e-4bfa-ac75-d7a495fecbbb) from GoodJob(low) in 0.24ms
Executed GoodJob 315bfb55-ec2e-4bfa-ac75-d7a495fecbbb
Performing ActivityJob (Job ID: a69d47fc-4f32-43de-84b2-77b19ee85863) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: a69d47fc-4f32-43de-84b2-77b19ee85863) from GoodJob(low) in 0.26ms
Executed GoodJob a69d47fc-4f32-43de-84b2-77b19ee85863
Performing ActivityJob (Job ID: fc976678-08e0-4f19-914b-358c49c31581) from GoodJob(low) enqueued at 2023-09-27T16:52:06Z with arguments: ...
Performed ActivityJob (Job ID: fc976678-08e0-4f19-914b-358c49c31581) from GoodJob(low) in 0.25ms

1 reply

bensheldon Sep 28, 2023
Maintainer

That's a good sign! Much easier to fix concurrency issues than if it's slow dequeuing.

Just to doublecheck, could you also try enabling Active Record query logging in the console too:

ActiveRecord::Base.logger = Logger.new(STDOUT)
ActiveRecord::Base.logger.level = Logger::DEBUG

That should show how many ms each query takes. Just to be sure.

rmontgomery429 · 2023-09-28T05:30:40Z

rmontgomery429
Sep 28, 2023
Author

These are being processes so quickly that it's noticeable when I spin up a worker (I had it at zero) to just one server, the console slowed way down, the worker wasn't doing much either so I spun it down and then the console sped up again. 🤔

0 replies

rmontgomery429 · 2023-09-28T05:37:28Z

rmontgomery429
Sep 28, 2023
Author

Just a few minutes and I've already processed over 13,000 jobs from the console. The previous hour it had only processed 1,914. Here is how the process is defined in my Procfile:

worker: DATABASE_POOL=$GOOD_JOB_MAX_THREADS bundle exec good_job start

And database.yml...

default: &default
  adapter: postgresql
  encoding: utf8
  pool: <%= ENV["DATABASE_POOL"] { 5 } %>
  url: <%= ENV["DATABASE_URL"] %>

production:
  <<: *default
  url: <%= ENV["DATABASE_URL"] %>

development:
  <<: *default
  url: <%= ENV["DATABASE_URL"] %>

test:
  <<: *default
  url: <%= ENV["DATABASE_URL"] %>

1 reply

bensheldon Sep 28, 2023
Maintainer

I'm glad that we're achieving job throughput! Now to figure out the other problems.

You'll need your database connection pool to be at minimum 2 + GOOD_JOB_MAX_THREADS to account for the LISTEN thread and another utility thread. I'd recommend setting it to be 2 * GOOD_JOB_MAX_THREADS just because there's no reason to run lean on database connections (especially if you're using load_async or doing any other multithreaded behavior in your app).

rmontgomery429 · 2023-09-28T05:40:37Z

rmontgomery429
Sep 28, 2023
Author

GoodJob::Lockable Unlock Session (0.7ms)  SELECT pg_advisory_unlock_all()::text AS unlocked
GoodJob::Execution Load (1.5ms)  SELECT "good_jobs".* FROM "good_jobs" WHERE "good_jobs"."id" IN (WITH "rows" AS MATERIALIZED ( SELECT "good_jobs"."id", "good_jobs"."active_job_id" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= '2023-09-28 05:37:44.770108' OR "good_jobs"."scheduled_at" IS NULL) ORDER BY priority DESC NULLS LAST, "good_jobs"."created_at" ASC LIMIT 1000 ) SELECT "rows"."id" FROM "rows" WHERE pg_try_advisory_lock(('x' || substr(md5('good_jobs' || '-' || "rows"."active_job_id"::text), 1, 16))::bit(64)::bigint) LIMIT $1) ORDER BY priority DESC NULLS LAST, "good_jobs"."created_at" ASC  [["LIMIT", 1]]
GoodJob::Execution Exists? (1.7ms)  SELECT 1 AS one FROM "good_jobs" LEFT JOIN pg_locks ON pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "good_jobs"."finished_at" IS NULL AND ("pg_locks"."pid" = pg_backend_pid()) AND "good_jobs"."id" = $1 LIMIT $2  [["id", "d521c5f5-cda7-4f8a-83f8-0da53e2a95e5"], ["LIMIT", 1]]
TRANSACTION (0.6ms)  BEGIN
GoodJob::DiscreteExecution Create (0.9ms)  INSERT INTO "good_job_executions" ("created_at", "updated_at", "active_job_id", "job_class", "queue_name", "serialized_params", "scheduled_at", "finished_at", "error", "error_event") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10) RETURNING "id"  [["created_at", "2023-09-28 05:37:44.775042"], ["updated_at", "2023-09-28 05:37:44.775763"], ["active_job_id", "d521c5f5-cda7-4f8a-83f8-0da53e2a95e5"], ["job_class", "ActivityJob"], ["queue_name", "low"], ["serialized_params", "{\"job_id\":\"d521c5f5-cda7-4f8a-83f8-0da53e2a95e5\",\"locale\":\"en\",\"priority\":null,\"timezone\":\"UTC\",\"arguments\":[\"jtbd\",{\"author\":{\"_aj_globalid\":\"gid://app/model/233224408\"},\"_aj_ruby2_keywords\":[\"author\"]}],\"job_class\":\"ActivityJob\",\"executions\":0,\"queue_name\":\"low\",\"enqueued_at\":\"2023-09-27T16:54:38Z\",\"provider_job_id\":null,\"exception_executions\":{}}"], ["scheduled_at", "2023-09-27 16:54:38.735977"], ["finished_at", nil], ["error", nil], ["error_event", nil]]
GoodJob::Execution Update (0.9ms)  UPDATE "good_jobs" SET "performed_at" = $1, "updated_at" = $2, "executions_count" = $3 WHERE "good_jobs"."id" = $4  [["performed_at", "2023-09-28 05:37:44.775042"], ["updated_at", "2023-09-28 05:37:44.778265"], ["executions_count", 1], ["id", "d521c5f5-cda7-4f8a-83f8-0da53e2a95e5"]]
TRANSACTION (1.4ms)  COMMIT
model Load (1.3ms)  SELECT "models".* FROM "models" WHERE "models"."id" = $1 LIMIT $2  [["id", 233224408], ["LIMIT", 1]]
I, [2023-09-28T05:37:44.784327 #2]  INFO -- : Performing ActivityJob (Job ID: d521c5f5-cda7-4f8a-83f8-0da53e2a95e5) from GoodJob(low) enqueued at 2023-09-27T16:54:38Z with arguments: "jtbd", {:author=>#<GlobalID:0x00007f4caee34a20 @uri=#<URI::GID gid://app/model/233224408>>}
Model Count (0.8ms)  SELECT COUNT(*) FROM "completed_flashcard_sets" WHERE "completed_flashcard_sets"."deleted_at" IS NULL AND "completed_flashcard_sets"."model_id" = $1  [["model_id", 233224408]]
I, [2023-09-28T05:37:44.786768 #2]  INFO -- : Performed ActivityJob (Job ID: d521c5f5-cda7-4f8a-83f8-0da53e2a95e5) from GoodJob(low) in 4.97ms
Executed GoodJob d521c5f5-cda7-4f8a-83f8-0da53e2a95e5
TRANSACTION (0.6ms)  BEGIN
GoodJob::DiscreteExecution Update (0.9ms)  UPDATE "good_job_executions" SET "updated_at" = $1, "finished_at" = $2 WHERE "good_job_executions"."id" = $3  [["updated_at", "2023-09-28 05:37:44.787816"], ["finished_at", "2023-09-28 05:37:44.787037"], ["id", "8308623c-eb62-4877-8885-9278b6c15fe8"]]
GoodJob::Execution Update (0.8ms)  UPDATE "good_jobs" SET "finished_at" = $1, "updated_at" = $2 WHERE "good_jobs"."id" = $3  [["finished_at", "2023-09-28 05:37:44.787037"], ["updated_at", "2023-09-28 05:37:44.790121"], ["id", "d521c5f5-cda7-4f8a-83f8-0da53e2a95e5"]]
TRANSACTION (1.4ms)  COMMIT
GoodJob::Lockable Unlock Session (0.7ms)  SELECT pg_advisory_unlock_all()::text AS unlocked
GoodJob::Execution Load (1.9ms)  SELECT "good_jobs".* FROM "good_jobs" WHERE "good_jobs"."id" IN (WITH "rows" AS MATERIALIZED ( SELECT "good_jobs"."id", "good_jobs"."active_job_id" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= '2023-09-28 05:37:44.794610' OR "good_jobs"."scheduled_at" IS NULL) ORDER BY priority DESC NULLS LAST, "good_jobs"."created_at" ASC LIMIT 1000 ) SELECT "rows"."id" FROM "rows" WHERE pg_try_advisory_lock(('x' || substr(md5('good_jobs' || '-' || "rows"."active_job_id"::text), 1, 16))::bit(64)::bigint) LIMIT $1) ORDER BY priority DESC NULLS LAST, "good_jobs"."created_at" ASC  [["LIMIT", 1]]
GoodJob::Execution Exists? (1.7ms)  SELECT 1 AS one FROM "good_jobs" LEFT JOIN pg_locks ON pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "good_jobs"."finished_at" IS NULL AND ("pg_locks"."pid" = pg_backend_pid()) AND "good_jobs"."id" = $1 LIMIT $2  [["id", "281c8378-4c90-4814-a9a5-0dca6143195a"], ["LIMIT", 1]]
TRANSACTION (0.6ms)  BEGIN
GoodJob::DiscreteExecution Create (0.9ms)  INSERT INTO "good_job_executions" ("created_at", "updated_at", "active_job_id", "job_class", "queue_name", "serialized_params", "scheduled_at", "finished_at", "error", "error_event") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10) RETURNING "id"  [["created_at", "2023-09-28 05:37:44.799996"], ["updated_at", "2023-09-28 05:37:44.800767"], ["active_job_id", "281c8378-4c90-4814-a9a5-0dca6143195a"], ["job_class", "ActivityJob"], ["queue_name", "low"], ["serialized_params", "{\"job_id\":\"281c8378-4c90-4814-a9a5-0dca6143195a\",\"locale\":\"en\",\"priority\":null,\"timezone\":\"UTC\",\"arguments\":[\"jtbd\",{\"author\":{\"_aj_globalid\":\"gid://app/model/233557893\"},\"_aj_ruby2_keywords\":[\"author\"]}],\"job_class\":\"ActivityJob\",\"executions\":0,\"queue_name\":\"low\",\"enqueued_at\":\"2023-09-27T16:54:38Z\",\"provider_job_id\":null,\"exception_executions\":{}}"], ["scheduled_at", "2023-09-27 16:54:38.742745"], ["finished_at", nil], ["error", nil], ["error_event", nil]]
GoodJob::Execution Update (1.0ms)  UPDATE "good_jobs" SET "performed_at" = $1, "updated_at" = $2, "executions_count" = $3 WHERE "good_jobs"."id" = $4  [["performed_at", "2023-09-28 05:37:44.799996"], ["updated_at", "2023-09-28 05:37:44.803409"], ["executions_count", 1], ["id", "281c8378-4c90-4814-a9a5-0dca6143195a"]]
TRANSACTION (1.6ms)  COMMIT
model Load (1.5ms)  SELECT "models".* FROM "models" WHERE "models"."id" = $1 LIMIT $2  [["id", 233557893], ["LIMIT", 1]]
I, [2023-09-28T05:37:44.809846 #2]  INFO -- : Performing ActivityJob (Job ID: 281c8378-4c90-4814-a9a5-0dca6143195a) from GoodJob(low) enqueued at 2023-09-27T16:54:38Z with arguments: "jtbd", {:author=>#<GlobalID:0x00007f4caed617d8 @uri=#<URI::GID gid://app/model/233557893>>}
Model Count (1.2ms)  SELECT COUNT(*) FROM "completed_flashcard_sets" WHERE "completed_flashcard_sets"."deleted_at" IS NULL AND "completed_flashcard_sets"."model_id" = $1  [["model_id", 233557893]]
I, [2023-09-28T05:37:44.812488 #2]  INFO -- : Performed ActivityJob (Job ID: 281c8378-4c90-4814-a9a5-0dca6143195a) from GoodJob(low) in 5.47ms
Executed GoodJob 281c8378-4c90-4814-a9a5-0dca6143195a
TRANSACTION (0.6ms)  BEGIN
GoodJob::DiscreteExecution Update (0.8ms)  UPDATE "good_job_executions" SET "updated_at" = $1, "finished_at" = $2 WHERE "good_job_executions"."id" = $3  [["updated_at", "2023-09-28 05:37:44.813478"], ["finished_at", "2023-09-28 05:37:44.812700"], ["id", "ffd47f66-571a-4e8f-b2b6-95d796da69f8"]]
GoodJob::Execution Update (1.3ms)  UPDATE "good_jobs" SET "finished_at" = $1, "updated_at" = $2 WHERE "good_jobs"."id" = $3  [["finished_at", "2023-09-28 05:37:44.812700"], ["updated_at", "2023-09-28 05:37:44.815793"], ["id", "281c8378-4c90-4814-a9a5-0dca6143195a"]]
TRANSACTION (1.5ms)  COMMIT

They all seem to be pretty quick.

7 replies

bensheldon Sep 28, 2023
Maintainer

Yep, that's a very good sign!

I have one more experiment for you to try. Could you try running GoodJob.perform_inline("+default,low")? That will dequeue in order by queue that you have configured and I have a hypothesis that using the + results in a not very performant query. I could be wrong though.

Regardless, I'd still recommend that you ran separate threadpools for your queues e.g. GOOD_JOB_QUEUES=default:2;low:2 (with the semicolon) because that will give you better quality of service.

Answer selected by rmontgomery429

rmontgomery429 Sep 28, 2023
Author

😵‍💫 As soon as I did that it slowed wayyyyy down. Like stopped processing, slow. And then a 5-10 seconds pause and then another job processed. Hrmmm.

rmontgomery429 Sep 28, 2023
Author

Sorry, to be clear doing GoodJob.perform_inline("+default,low") slowed way down. The fix, I think, is exactly what you suggested: GOOD_JOB_QUEUES=default:6;low:2. That seems to be working much better now.

rmontgomery429 Sep 28, 2023
Author

@bensheldon What would happen if I set GOOD_JOB_QUEUES="default;low" without any specific thread count? Does it use the GOOD_JOB_MAX_THREADS for each thread pool? Does it work like that? Also, is a low priority queue the way to go or should I just set priority on the job itself? What are the implications of either approach?

bensheldon Sep 28, 2023
Maintainer

What would happen if I set GOOD_JOB_QUEUES="default;low" without any specific thread count? Does it use the GOOD_JOB_MAX_THREADS for each thread pool? Does it work like that?

Yep, that's exactly how it works 👍🏻 GOOD_JOB_MAX_THREADS defines the default pool size in that situation.

Also, is a low priority queue the way to go or should I just set priority on the job itself? What are the implications of either approach?

Writing this out makes me think I need to put this in the documentation. A lot of this is informed by Nate Berkopec's "Complete Guide to Rails Performance", which is largely about Sidekiq but covers a lot of the same territory:

Use queues to separate your jobs by their SLO expectation for total latency (queue latency + runtime latency). My recommendation is even to go so far as to name your queues slo_5s or slo_1m or slo_24h for ultimate clarity and observability
Run your fastest SLO queues in their own isolated threadpools, and combine queues as they become slower e.g. slo_5s;slo_1m,slo5s;slo_24h,* for example.
Largely ignore setting priority as it only comes into play when you don't have enough capacity to meet your SLOs; it's good in the sense of "reduce impact during an incident" but during normal operation, you should always have enough capacity to meet your SLOs and therefore dequeue order/priority shouldn't matter (that's also how I feel about the queue-ordered-+ feature too, performance problems we uncovered notwithstanding)
Don't have too many threads in the same process. 10 is probably max, though folks say more like 5, but it really depends on workload and you can be very precise in calculating it if you want: https://www.speedshop.co/2020/05/11/the-ruby-gvl-and-scaling.html

bensheldon · 2023-09-28T05:53:10Z

bensheldon
Sep 28, 2023
Maintainer

fyi, I have to go to bed for the night 🛌🏻 I'll pick this up tomorrow and we'll get to the bottom of it 🙇🏻

2 replies

mildavw Sep 28, 2023
Sponsor

I hate to interrupt this convo, but I'm compelled to remind the readers of this issue that this kind of super high quality support from Ben (to good questions and debugging from Ryan) benefits us all greatly and if you can afford it, it would be super cool to visit https://github.com/sponsors/bensheldon and contribute. (disclosure: I don't know Ben at all, or his financial sitch, but I've been using good_job in prod for a while and really want it to continue!)

rmontgomery429 Sep 28, 2023
Author

I couldn't agree more. Thank you for the reminder @mildavw and thank you @bensheldon for all your help.

1campbellj · 2024-10-01T22:21:59Z

1campbellj
Oct 1, 2024

I recently ran into a similar issue, although I don't believe it's the exact same root cause.

We (somewhat mistakenly) enqueued ~500k jobs, and some time after that saw job execution slow down, and surprisingly eventually it started to take our application down.

We resolved the issue by deleting the offending jobs from the queue and then refactoring the job to be more batch-aware and require fewer jobs to do the work. I believe this should have been done beforehand so we could have avoided bloating our queue unnecessarily, but it's curious to me that it ended up taking the app down. I think my expectation would be that you could enqueue some arbitrarily large number of jobs, and it would just take a very long time to complete them, but that issue would be isolated from your web environment.

Our setup differs somewhat from the original issue here:

Instead of having multiple queues, we enqueue everything into the default queue
Every job has a priority
Helpers are used to call queue_with_priority and pass in 10/50/100 as our high/medium/low with low being the default

Similar to the original issue here we have experienced very poor UI performance in the past, with heroku sometimes killing the request if there are a lot of jobs in the tables, even if they're old successfully completed jobs.

I'm curious if there's something about our setup that may be causing the DB to work very hard. To me that seems to be the likely mechanism that would cause our app to come down as queue size increases. Something like it becomes so expensive to dequeue a job that the DB because resource constrained and cannot serve the web side any longer. I don't believe it would be the case that we used all the connections, because we don't have enough workers to do that.

Unfortunately I don't have any logs from the actual incident, but I did pull this from HoneyComb that shows some insight into the performance just normally without a 500k jobs in the queue:

It stood out to me that the similar query in log posted above was taking less than 2ms, but in our case under ideal conditions it taking 8ms and occasionally 200ms.

In an attempt to reproduce the issue we simulated the conditions in a development environment, and once the queue size reached 250k+ we saw some significant slowdown with this query. We could make the issue even worse by lowering the RAM available to the DB. If we introduced a GOOD_JOB_QUEUE_SELECT_LIMIT=1000 env, it seemed to resolve the issue in this environment.

Could you provide any guidance around where you think the issue could be?

Could it be something in our config causing queries to be very expensive with large queue sizes?
Could our database just be under provisioned? (Currently on heroku Standard-0 tier (4 GB ram, 64 GB storage)
It seems like the performance degradation is also a function of the preserve_job_records config, and the related cleanup config

Thoughts about GOOD_JOB_QUEUE_SELECT_LIMIT:

Would a default here have prevented this issue? Maybe a reasonable default could be 1,000 or 10,000?
Would you say this is the root cause of the issue, or possibly a combination of this and an under-provisioned database?

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Struggling to process 100,000+ jobs #1091

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 7 comments 11 replies

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Struggling to process 100,000+ jobs #1091

rmontgomery429 Sep 28, 2023

Replies: 7 comments · 11 replies

bensheldon Sep 28, 2023 Maintainer

rmontgomery429 Sep 28, 2023 Author

bensheldon Sep 28, 2023 Maintainer

rmontgomery429 Sep 28, 2023 Author

rmontgomery429 Sep 28, 2023 Author

bensheldon Sep 28, 2023 Maintainer

rmontgomery429 Sep 28, 2023 Author

bensheldon Sep 28, 2023 Maintainer

rmontgomery429 Sep 28, 2023 Author

rmontgomery429 Sep 28, 2023 Author

rmontgomery429 Sep 28, 2023 Author

bensheldon Sep 28, 2023 Maintainer

bensheldon Sep 28, 2023 Maintainer

mildavw Sep 28, 2023 Sponsor

rmontgomery429 Sep 28, 2023 Author

1campbellj Oct 1, 2024

rmontgomery429
Sep 28, 2023

Replies: 7 comments 11 replies

bensheldon
Sep 28, 2023
Maintainer

rmontgomery429
Sep 28, 2023
Author

bensheldon Sep 28, 2023
Maintainer

rmontgomery429
Sep 28, 2023
Author

rmontgomery429
Sep 28, 2023
Author

bensheldon Sep 28, 2023
Maintainer

rmontgomery429
Sep 28, 2023
Author

bensheldon Sep 28, 2023
Maintainer

rmontgomery429 Sep 28, 2023
Author

rmontgomery429 Sep 28, 2023
Author

rmontgomery429 Sep 28, 2023
Author

bensheldon Sep 28, 2023
Maintainer

bensheldon
Sep 28, 2023
Maintainer

mildavw Sep 28, 2023
Sponsor

rmontgomery429 Sep 28, 2023
Author

1campbellj
Oct 1, 2024