`Oban.Met.Recorder` excessive message queue length

[up2jj]

Environment

Elixir 1.16.2
OTP 26.2.5
Oban 2.17.6
Oban Pro 1.3.5
Oban Web 2.10.2
Oban Met 0.1.5

Recently, we have successfully migrated our app from Elixir 1.14 to 1.16. After the migration, the Oban.Met process started to receive large volumes of messages which results directly in an OOM kill and the inability to use the Oban Web dashboard.

We did not make any code or configuration changes that could affect this. System load is at a similar level to before the migration.

[sorentwo]

@up2jj That's unpleasant. This is the first I've heard of an excessive message queue for the recorder process.

Was this a one off experience, or is the message queue remaining high after a reboot? A few other questions to get a better idea of your setup:

1. How many nodes?
2. How many queues?
3. How many workers?
4. How many jobs per hour (roughly)?

[sorentwo]

Somebody else reported this on Slack. sThe relevant change in both cases is upgrading to OTP 26.2.5, and in both situations the current function was :ets.select/1.

In reviewing the OTP 26.2.5 release notes, I noticed this change:

  OTP-19070    Application(s): erts
               Related Id(s): GH-8385

               ETS functions did not properly handle keys containing
               maps, sometimes matching too many or too few objects.

That traces back to this issue from @tsloughter, and this patch by @jhogberg.

A simple benchmark that loosely recreates how oban_met is using :ets.select highlights an extreme performance regression for select, and oddly enough a massive boost for lookup. Details are in this gist, but here's the relevant part:

Name                     ips        average  deviation         median         99th %
lookup                1.62 M      616.07 ns  ±1798.74%         584 ns         791 ns
select_reverse        1.21 M      823.61 ns  ±1503.76%         667 ns         958 ns
select             0.00100 M   995660.57 ns     ±2.84%      982750 ns  1058731.74 ns

Comparison:
lookup                1.62 M
select_reverse        1.21 M - 1.34x slower +207.54 ns
select             0.00100 M - 1616.16x slower +995044.50 ns

Removing the map portion of the key alleviates the performance issue entirely (and it's much faster for the other operations):

Name                     ips        average  deviation         median         99th %
lookup                3.61 M      276.76 ns  ±9550.30%         250 ns         333 ns
select_reverse        2.21 M      452.09 ns  ±2259.09%         458 ns         583 ns
select                2.20 M      454.81 ns  ±2213.31%         458 ns         583 ns

Comparison:
lookup                3.61 M
select_reverse        2.21 M - 1.63x slower +175.33 ns
select                2.20 M - 1.64x slower +178.05 ns

We'll look at revising the table structure to avoid using a map as an immediate fix for this, but this is bound to impact other applications and I'll report this upstream to the OTP team.

[up2jj]

Hi @sorentwo Thank you for your quick and detailed response. Ultimately we have decided to downgrade the OTP to the previous version, however we will keep an eye out for any immediate updates to Oban itself tackling this issue.

[sorentwo]

This is fixed in the soon-to-be-released oban_met v0.1.6

[up2jj]

@sorentwo FYI, we updated oban_met to v0.1.6 on prod and it seems that problem is solved on OTP 26.2.5 🙌🏻