Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bug: Changing timezone to Asia/Krasnoyarsk causes page loads to be over 15 seconds #1588

Open
4ndv opened this issue Jan 3, 2025 · 8 comments
Labels
⚡ Performance Performance issues to address

Comments

@4ndv
Copy link

4ndv commented Jan 3, 2025

Describe the bug
When changing timezone to Asia/Krasnoyarsk (UTC+7), every single page load now takes up to 45 seconds, with most of the time is spent in views

With Etc/Utc timezone:

INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Started GET "/accounts/summary" for 10.100.11.252 at 2025-01-04 02:52:52 +0700
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Started GET "/accounts/summary" for 10.100.11.252 at 2025-01-04 02:52:52 +0700
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Started GET "/accounts/summary" for 10.100.11.252 at 2025-01-04 02:52:52 +0700
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Started GET "/accounts/summary" for 10.100.11.252 at 2025-01-04 02:52:52 +0700
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Processing by AccountsController#summary as HTML
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Processing by AccountsController#summary as HTML
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Processing by AccountsController#summary as HTML
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Processing by AccountsController#summary as HTML
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635]   Rendered layout layouts/with_sidebar.html.erb (Duration: 64.2ms | GC: 6.0ms)
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635]   Rendered layout layouts/with_sidebar.html.erb (Duration: 64.2ms | GC: 6.0ms)
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635]   Rendered layout layouts/with_sidebar.html.erb (Duration: 64.2ms | GC: 6.0ms)
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635]   Rendered layout layouts/with_sidebar.html.erb (Duration: 64.2ms | GC: 6.0ms)
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Completed 200 OK in 99ms (Views: 60.2ms | ActiveRecord: 13.0ms (258 queries, 135 cached) | GC: 8.2ms)
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Completed 200 OK in 99ms (Views: 60.2ms | ActiveRecord: 13.0ms (258 queries, 135 cached) | GC: 8.2ms)
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Completed 200 OK in 99ms (Views: 60.2ms | ActiveRecord: 13.0ms (258 queries, 135 cached) | GC: 8.2ms)
INFO -- : [802f9fcc-4153-4f44-bb2f-a43317808635] Completed 200 OK in 99ms (Views: 60.2ms | ActiveRecord: 13.0ms (258 queries, 135 cached) | GC: 8.2ms)

With Asia/Krasnoyarsk timezone:

INFO -- : [d089d80a-2b7b-41d0-a6a8-e5f4f7c2cb2c] Started GET "/transactions" for 10.100.11.252 at 2025-01-04 02:46:15 +0700
INFO -- : [d089d80a-2b7b-41d0-a6a8-e5f4f7c2cb2c] Processing by TransactionsController#index as HTML
INFO -- : [98ded54e-afda-46e9-be55-046a8925a3d6] Started GET "/transactions" for 10.100.11.252 at 2025-01-04 02:46:16 +0700
INFO -- : [98ded54e-afda-46e9-be55-046a8925a3d6] Processing by TransactionsController#index as HTML
INFO -- : [4798cb9d-7317-4e4f-a14b-ff4566c184ba]   Rendered layout layouts/with_sidebar.html.erb (Duration: 17836.4ms | GC: 19.1ms)
INFO -- : [4798cb9d-7317-4e4f-a14b-ff4566c184ba] Completed 200 OK in 17843ms (Views: 17806.2ms | ActiveRecord: 32.0ms (133 queries, 8 cached) | GC: 19.1ms)
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce] Started GET "/accounts/summary" for 10.100.11.252 at 2025-01-04 02:46:33 +0700
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce] Processing by AccountsController#summary as HTML
INFO -- : [d089d80a-2b7b-41d0-a6a8-e5f4f7c2cb2c]   Rendered layout layouts/with_sidebar.html.erb (Duration: 17931.0ms | GC: 34.6ms)
INFO -- : [d089d80a-2b7b-41d0-a6a8-e5f4f7c2cb2c] Completed 200 OK in 17942ms (Views: 17910.9ms | ActiveRecord: 24.3ms (261 queries, 100 cached) | GC: 35.1ms)
INFO -- : [98ded54e-afda-46e9-be55-046a8925a3d6]   Rendered layout layouts/with_sidebar.html.erb (Duration: 18838.2ms | GC: 36.5ms)
INFO -- : [98ded54e-afda-46e9-be55-046a8925a3d6] Completed 200 OK in 18869ms (Views: 18812.2ms | ActiveRecord: 37.7ms (261 queries, 100 cached) | GC: 36.5ms)
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce]   Rendered layout layouts/with_sidebar.html.erb (Duration: 32536.5ms | GC: 20.2ms)
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce]   Rendered layout layouts/with_sidebar.html.erb (Duration: 32536.5ms | GC: 20.2ms)
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce]   Rendered layout layouts/with_sidebar.html.erb (Duration: 32536.5ms | GC: 20.2ms)
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce] Completed 200 OK in 49497ms (Views: 32510.3ms | ActiveRecord: 54.3ms (274 queries, 82 cached) | GC: 45.5ms)
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce] Completed 200 OK in 49497ms (Views: 32510.3ms | ActiveRecord: 54.3ms (274 queries, 82 cached) | GC: 45.5ms)
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce] Completed 200 OK in 49497ms (Views: 32510.3ms | ActiveRecord: 54.3ms (274 queries, 82 cached) | GC: 45.5ms)
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce]   Rendered layout layouts/with_sidebar.html.erb (Duration: 32536.5ms | GC: 20.2ms)
INFO -- : [dd4ea97c-3fd1-45eb-aa31-2f06f1e194ce] Completed 200 OK in 49497ms (Views: 32510.3ms | ActiveRecord: 54.3ms (274 queries, 82 cached) | GC: 45.5ms)

To Reproduce
Steps to reproduce the behavior:

Change timezone in Preferences to Asia/Krasnoyarsk,

Expected behavior
Page loads quickly :)

What version of Maybe are you using?
Self-hosted with Docker, latest tag, latest image

What operating system and browser are you using?
EndeavourOS, latest Firefox

Screenshots / Recordings
-

Additional context
Settings section is not affected, I don't have lots of transactions, around 100-ish, across ~15 accounts

@4ndv 4ndv added the 🐛 Bug Something isn't working label Jan 3, 2025
@4ndv
Copy link
Author

4ndv commented Jan 3, 2025

So I've added rack-mini-profiler to my instance and here's some results:

Screenshot from the profiler

image

There is a lot of calls to Synth API: Net::HTTP GET /rates/historical?date=2025-01-04&from=USD&to=RUB

More context:

  1. I have accounts in multiple currencies
  2. The date in request is 2025-01-04
  3. But, I guess, there is not 2025-01-04 everywhere in the world yet :)

The offending code is most likely in app/models/exchange_rate.rb#find_rates, where it thinks that 2025-01-04 is a missing date, but, I guess, Synth does not have data for 2025-01-04 yet, so it is called again and again from different places where exchange rate is needed.

When I call fetch_rate_from_provider manually, I receive nil:

ExchangeRate.send(:fetch_rate_from_provider, from: "USD", to: "RUB", date: "2025-01-04")

Also summaries show as 0 for accounts in another currencies until I change timezone and there is yet again 2025-01-03 for me.

Some ideas:

  1. Exchange rates fetching really should be done in background, because of stuff like this when it fails
  2. For timezones that are "in the future" against Synth, historical data should be used

@zachgoll
Copy link
Collaborator

zachgoll commented Jan 7, 2025

@4ndv thanks for the details here!

This "off by 1" lookup in Synth is definitely something we'll need to address.

That said, I'm not sure that it would be the root cause of the performance issue—all of these exchange rates are being synced in the background and should not affect HTTP requests.

Can we narrow this down to something within the request/response cycle by chance?

@zachgoll zachgoll added ⚡ Performance Performance issues to address and removed 🐛 Bug Something isn't working labels Jan 7, 2025
@4ndv
Copy link
Author

4ndv commented Jan 7, 2025

From a very brief look:

lib/money.rb in method exchange_to calls ExchangeRate#find_rate, which conditionally calls fetch_rate_from_provider if find_by returns nil. So every single call to exchange_to produces HTTP request if there is no data for the currency pair for that date.

There is fallback_rate in exchange_to, but it is applied after HTTP request already made

@4ndv
Copy link
Author

4ndv commented Jan 7, 2025

exchange_to is called from Account#series, which gets called at least several times from the views (chart, _accounts_list partial)

@zachgoll
Copy link
Collaborator

zachgoll commented Jan 7, 2025

May have a bit of overlap to #1530 here

Switching timezones shouldn't affect performance this much though. I agree that the currency conversion operations could be a source, but merely switching from one timezone to another shouldn't affect anything drastically.

@4ndv
Copy link
Author

4ndv commented Jan 7, 2025

Switching timezones causes date to be "in the future", so every single call to exchange_to causes HTTP request

@zachgoll
Copy link
Collaborator

zachgoll commented Jan 7, 2025

@4ndv ahhh, I see what you mean now! That makes sense to me.

@4ndv
Copy link
Author

4ndv commented Jan 7, 2025

For timezones that are "in the future" against Synth, historical data should be used

Also I think this is important separate issue, so users with "+N" timezones wouldn't see 0es as a sum for foreign currency accounts

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
⚡ Performance Performance issues to address
Projects
None yet
Development

No branches or pull requests

2 participants