We upgraded to 2.13.3, but unfortunately we’re still experiencing this issue. It looks like it is related to the Oban.insert_all, because we’re only experiencing it with the jobs inserted like that. And maybe only when that queue is empty, because the jobs after that first insert_all runs with a concurrency of 1.
tompesman
0
sorentwo
Oban Core Team
If you can make a minimal reproduction of your setup that exhibits the problem then I’ll investigate and work on a fix.
1
tompesman
I’m trying to get a reproduction. The non default we have in our applications is that there are two databases and the prepare: :unnamed setting enabled in Ecto. At the moment I do not have a test case where I can reproduce it consistently, but I’ve seen the behaviour a few times.
0
tompesman
I think it is not related to the multiple database setup of Ecto. I just saw it again with only the prepare: :unnamed setting enabled and a single database.
521 completed ocr Demo.Job {"id": 1} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.907732 {9to5-MacBook-Pro} 3 {} {}
522 completed ocr Demo.Job {"id": 2} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.907957 {9to5-MacBook-Pro} 3 {} {}
523 completed ocr Demo.Job {"id": 3} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.909088 {9to5-MacBook-Pro} 3 {} {}
524 completed ocr Demo.Job {"id": 4} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.90967 {9to5-MacBook-Pro} 3 {} {}
525 completed ocr Demo.Job {"id": 5} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.910167 {9to5-MacBook-Pro} 3 {} {}
526 completed ocr Demo.Job {"id": 6} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.915585 {9to5-MacBook-Pro} 3 {} {}
527 completed ocr Demo.Job {"id": 7} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.915452 {9to5-MacBook-Pro} 3 {} {}
528 completed ocr Demo.Job {"id": 8} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.915305 {9to5-MacBook-Pro} 3 {} {}
529 completed ocr Demo.Job {"id": 9} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.915722 {9to5-MacBook-Pro} 3 {} {}
530 completed ocr Demo.Job {"id": 10} {} 1 1 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.88802 2022-09-14 11:26:10.89765 2022-09-14 11:26:11.915795 {9to5-MacBook-Pro} 3 {} {}
531 completed ocr Demo.Job {"id": 1} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.471022 {9to5-MacBook-Pro} 3 {} {}
532 completed ocr Demo.Job {"id": 2} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.470968 {9to5-MacBook-Pro} 3 {} {}
533 completed ocr Demo.Job {"id": 3} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.470802 {9to5-MacBook-Pro} 3 {} {}
534 completed ocr Demo.Job {"id": 4} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.472534 {9to5-MacBook-Pro} 3 {} {}
535 completed ocr Demo.Job {"id": 5} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.4725 {9to5-MacBook-Pro} 3 {} {}
536 completed ocr Demo.Job {"id": 6} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.472228 {9to5-MacBook-Pro} 3 {} {}
537 completed ocr Demo.Job {"id": 7} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.472295 {9to5-MacBook-Pro} 3 {} {}
538 completed ocr Demo.Job {"id": 8} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.472545 {9to5-MacBook-Pro} 3 {} {}
539 completed ocr Demo.Job {"id": 9} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.472601 {9to5-MacBook-Pro} 3 {} {}
540 completed ocr Demo.Job {"id": 10} {} 1 1 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.447177 2022-09-14 11:26:36.455261 2022-09-14 11:26:37.473616 {9to5-MacBook-Pro} 3 {} {}
0
sorentwo
Oban Core Team
It’s common to use prepare: :unnamed, I don’t believe that is an issue.
The output you’ve shared doesn’t include any headers, so I can’t tell which timestamp is which. Here is a short script I wrote to verify queues processes jobs sequentially:
Application.put_env(:oban, Oban.Test.Repo,
name: Oban.Test.Repo,
url: "postgres://localhost:5432/oban_test",
prepare: :unnamed
)
defmodule SomeWorker do
use Oban.Worker
@impl Worker
def perform(%{args: %{"id" => id}}) do
IO.puts "JOB #{id} started at #{System.system_time(:millisecond)}"
Process.sleep(100)
:ok
end
end
{:ok, _} = Oban.Test.Repo.start_link()
{:ok, _} = Oban.start_link(queues: [default: 1], repo: Oban.Test.Repo)
1..9
|> Enum.map(&SomeWorker.new(%{id: &1}))
|> Oban.insert_all()
That generates this output, showing that jobs are started sequentially:
JOB 1 started at 1663158893513
JOB 2 started at 1663158893630
JOB 3 started at 1663158893747
JOB 4 started at 1663158893861
JOB 5 started at 1663158893986
JOB 6 started at 1663158894108
JOB 7 started at 1663158894229
JOB 8 started at 1663158894344
JOB 9 started at 1663158894458
The oban_jobs table shows that the attempted_at and completed_at times are staggered as expected (note it is only showing the time and not the date):
id │ args │ state │ inserted_at │ attempted_at │ completed_at
═════╪════════════╪═══════════╪═════════════════╪═════════════════╪═════════════════
671 │ {"id": 1} │ completed │ 12:34:53.486301 │ 12:34:53.505758 │ 12:34:53.613663
672 │ {"id": 2} │ completed │ 12:34:53.486301 │ 12:34:53.623178 │ 12:34:53.730719
673 │ {"id": 3} │ completed │ 12:34:53.486301 │ 12:34:53.740571 │ 12:34:53.84865
674 │ {"id": 4} │ completed │ 12:34:53.486301 │ 12:34:53.857146 │ 12:34:53.961968
675 │ {"id": 5} │ completed │ 12:34:53.486301 │ 12:34:53.976616 │ 12:34:54.087918
676 │ {"id": 6} │ completed │ 12:34:53.486301 │ 12:34:54.102646 │ 12:34:54.20998
677 │ {"id": 7} │ completed │ 12:34:53.486301 │ 12:34:54.224589 │ 12:34:54.329783
678 │ {"id": 8} │ completed │ 12:34:53.486301 │ 12:34:54.339628 │ 12:34:54.445821
679 │ {"id": 9} │ completed │ 12:34:53.486301 │ 12:34:54.455605 │ 12:34:54.559764
0
tompesman
Getting the issue reproduced is hard, but I’m still trying to figure out in which direction the issue is. I’ve changed the insert_all to a Enum.each with an Oban.insert. The issue is still there. I’ve attached a screenshot of the database. The attempted_at timestamp is the same for the executing jobs.
To verify the config of the worker node I connected remotely to the node and ran: Oban.config()
%Oban.Config{
dispatch_cooldown: 5,
engine: Oban.Engines.Basic,
get_dynamic_repo: nil,
log: false,
name: Oban,
node: "node-name-here@10.0.4.30",
notifier: Oban.Notifiers.Postgres,
peer: Oban.Peers.Postgres,
plugins: [
{Oban.Plugins.Cron,
[
timezone: "Europe/Amsterdam",
crontab: [
...
]
]},
Oban.Plugins.Pruner,
Oban.Plugins.Stager
],
prefix: "public",
queues: [default: [limit: 2], images: [limit: 1], ocr: [limit: 1]],
repo: Project.Repo,
shutdown_grace_period: 15000,
testing: :disabled
}
When I look how the jobs are updated into an executing state: oban/lib/oban/engines/basic.ex at 44803121eb16be6a4dffb147aa257555c421050c · oban-bg/oban · GitHub
It looks like the demand is too high, but that can only happen if the limit is higher than 1 because map_size returns a non_neg_integer. Is it possible that I set the limit incorrectly?
Thanks!
0
sorentwo
Oban Core Team
Doubtful, the limit is validated before starting or updating the value on a running queue. Unless you’re using :sys.replace_state/2 to meddle with the queue’s producer, there’s no way to get an invalid limit. To verify the configuration, you can get the queue’s current state with Oban.check_queue/1.
Does it always run the same number of jobs simultaneously? From your screenshot, it looks like there are 24 with the same timestamp.
0
tompesman
I just caught it running multiple jobs on the ocr queue.
iex(node@10.0.3.26)2> Oban.check_queue(queue: :ocr)
%{
limit: 1,
name: Oban,
node: "node@10.0.3.26",
paused: false,
queue: "ocr",
refresh_interval: 30000,
running: [20660303, 20660276, 20660255, 20660257, 20660292, 20660280,
20660293],
started_at: ~U[2022-09-22 10:32:26.603968Z],
updated_at: ~U[2022-09-22 14:08:18.654687Z]
}
Right now I have 7 jobs with the same timestamp executing. But I do not see a pattern with the amount happening. It looks like if the queue is empty and new jobs are queued this happens. If new jobs are inserted after the queue is working on jobs the new jobs are executed one by one.
0
tompesman
Is there something else I can investigate? I have this situation multiple times per day on our production environment. So I can deploy some extra debug logs for example.
0
sorentwo
Oban Core Team
You could hook into the queue producer’s telemetry events and emit logs:
defmodule ProducerLogger do
require Logger
def handle(_event, _measure, %{queue: queue, dispatched_count: count}, _opts) do
Logger.debug("[ProducerLogger] queue #{queue} dispatched #{count} jobs")
end
end
:telemetry.attach("queue-logger", [:oban, :producer, :stop], &ProducerLogger.handle/4, [])
The count should always be 1 based on your config. If not, something is awry.
0