Rendering very slow

[rkh]

I'm trying to figure out why some tables load very slowly, and based on the logs the time is spent rendering templates:

  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_sortable_component.html.erb (Duration: 0.3ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_table_header.html.erb (Duration: 83.0ms | GC: 3.1ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/base/index.html.erb within layouts/avo/application (Duration: 16470.5ms | GC: 756.2ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_javascript.html.erb (Duration: 0.1ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_branding.html.erb (Duration: 0.1ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_pre_head.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_head.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_logo.html.erb (Duration: 0.1ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_header.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_navbar.html.erb (Duration: 1.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_sidebar_extra.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_profile_menu_extra.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_sidebar_extra.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_profile_menu_extra.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_custom_tools_alert.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_footer.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_all_alerts.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_alerts.html.erb (Duration: 0.5ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_scripts.html.erb (Duration: 0.0ms | GC: 0.0ms)
  Rendered /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/avo/partials/_confirm_dialog.html.erb (Duration: 123.4ms | GC: 5.6ms)
  Rendered layout /Users/konstantin/.asdf/installs/ruby/3.4.2/lib/ruby/gems/3.4.0/gems/avo-3.18.1/app/views/layouts/avo/application.html.erb (Duration: 17968.8ms | GC: 817.0ms)
Completed 200 OK in 18234ms (Views: 17973.5ms | ActiveRecord: 19.1ms (2 queries, 0 cached) | GC: 828.6ms)

No N+1 query, at least not based on the logs. The query to load the data for the table takes 41.3ms (not ideal, but a whole different world from the 18 seconds spent rendering).

[rkh]

I know this is probably not a good issue, no way to reproduce, etc, so feel free to close this. I did want to share this information, though.

[Paul-Bob]

Hi @rkh

18 seconds in view rendering is wildly outside the norm. It's most likely something happening in your app. Maybe a custom field running heavy logic, or some synchronous code sneaking into the view layer.

It doesn’t look like an issue with Avo itself, but if you dig deeper and find something reproducible, definitely let us know!

[adrianthedev]

What I would do @rkh is to slowly comment out (or in) one field at a time and try to figure out which one made the page load slower and take it from there.

Also, try this to get more debugging information.

I definitely want to get to the bottom of this and see if there's anything we can do about it.

[rkh]

I'll look into this when I have some more time, especially given that this is likely something in our code (that we're not triggering elsewhere, as most of our Rails backend is serving JSON – response times on the same machine for our controllers are between 8ms and 200ms on the same machine, depending on the endpoint).

[rkh]

Found how this is tripping up in our code. Used rack-miniprofiler (with flamegraphs) btw, can recommend.

[courtsimas]

Same issue. Our avo admin views suddenly started taking anywhere from 10 seconds to several minutes once we bumped to 3.18.x. It's odd.

[adrianthedev]

Hey @rkh. So what was it? Did rack-miniprofiler slow down the app?

Hey @courtsimas. That's wild and definitely not what how it should be.
We don't have many views that take more than a few milliseconds to load. The biggest one is an index view that stretches over a few records and joins to pick up data and that takes a second (and it's the exception).

I definitely want to get to the bottom of this. My hunch is that there's an oportunity to optimize the query and not an Avo thing (but I'm not ruling it out).
Would you like to spend some time to debug it, or would you prefer to get on a call with us and try to do it together?

FYI: performance is very important to us and we take a lot of steps to get out of your way and not add performance bottlenecks on Avo's end.

[rkh]

Hey @rkh. So what was it?

There are a lot of I18n calls being triggered. We had a custom I18n fallback in place that didn't do any caching in development mode and ended up doing a lot of file system scans in unexpected places.

Did rack-miniprofiler slow down the app?

Yes. The slowdown in normal mode was negligible, but generating the flamegraphs on an already slow endpoint took quite a while. This only happens with a special query parameter or header, though.

[adrianthedev]

Got it! Thanks for letting us know.
It's one of those that doesn't stand out immediately.
Nice job tracking it down!