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.

Sign up for GitHub

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

Jump to bottom

Performance regression in 6.0 due to unnecessarily eager loading #2468

Closed
tvdeyen opened this issue May 10, 2023 · 2 comments
Closed

Performance regression in 6.0 due to unnecessarily eager loading #2468

tvdeyen opened this issue May 10, 2023 · 2 comments
Labels
confirmed

Comments

@tvdeyen
Copy link
Member

tvdeyen commented May 10, 2023 •
edited
Loading

We just upgraded to 6.0.12 from 4.0 and noticed a significant performance regression and it appears to be due to this change. We verified by temporarily rolling back to 6.0.5 and the previous response times returned.

After we upgraded, we immediately noticed a lot more time spent in pg/postgres and that transactions were taking 2.5x as long overall at p50 in Datadog. Most of the requests we observe are just a small Alchemy page that's used as a health check. Therefore, the partials for this page are typically cached.

It seems like even if we don't need to get any data, it's eagerly being loaded. There were originally some eager loading optimizations added in Alchemy 4.4 (#1674), but @tvdeyen mentioned there that eager loading was not added non-API HTML requests to avoid unnecessary work for cached pages.

It appears that the performance slowdown I observed is related to that consideration where we now perform extra queries even if they wouldn't have been needed. However, on a cold cache, it does seem to improve performance. Maybe even adding nested elements could further reduce queries, but that's a separate question.

Is it intended that we'll now have slower performance on cached page fragment hits? Is there any way to eager load, but only if the page isn't cached?

Originally posted by @wuservices in #2313 (comment)
@tvdeyen tvdeyen mentioned this issue May 10, 2023
Merged
2 tasks
@wuservices
Copy link
Contributor

I created a fresh app in https://github.com/wuservices/alchemy-debug-performance on 6.0.5, then added a 6.0.6 branch to compare performance. See README there for methodology.

This confirmed in isolation what we noticed in production. After upgrading to 6.0.6, the eager loading will still fetch data via SQL even if the fragment cache is warmed up.

In our production app, here's what upgrading to 6.0.12 looked like where you can see the latency is over 2x on average (most of these are cached), and the percentage of overall transaction time spent in the database increases. You can then see we dip back down at the end, which is where I reverted to 6.0.5 for testing.
image

Below are logs from the fresh test instance where I compare how many queries are executed with cold/empty vs warm caches on 6.0.5 vs 6.0.6.

6.0.5 empty cache (19 queries)

I, Started GET "/" for 127.0.0.1 at 2023-05-10 10:32:31 -0700
I, Processing by Alchemy::PagesController#index as */*
D,   Alchemy::Site Load (0.2ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" WHERE "alchemy_sites"."host" = ? LIMIT ?  [["host", "localhost"], ["LIMIT", 1]]
D,   Alchemy::Site Load (0.0ms)  SELECT "alchemy_sites".* FROM "alchemy_sites"
D,   Alchemy::Site Load (0.1ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" ORDER BY "alchemy_sites"."id" ASC LIMIT ?  [["LIMIT", 1]]
D,   Alchemy::Language Load (0.3ms)  SELECT "alchemy_languages".* FROM "alchemy_languages" WHERE "alchemy_languages"."site_id" = ? AND "alchemy_languages"."default" = ? LIMIT ?  [["site_id", 1], ["default", 1], ["LIMIT", 1]]
D,   Alchemy::Page Load (0.3ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   Alchemy::User Exists? (0.2ms)  SELECT 1 AS one FROM "alchemy_users" WHERE "alchemy_users"."alchemy_roles" LIKE '%admin%' LIMIT ?  [["LIMIT", 1]]
D,   Alchemy::PageVersion Load (0.2ms)  SELECT "alchemy_page_versions".* FROM "alchemy_page_versions" WHERE "alchemy_page_versions"."page_id" = ? AND "alchemy_page_versions"."public_on" IS NOT NULL ORDER BY "alchemy_page_versions"."public_on" DESC LIMIT ?  [["page_id", 1], ["LIMIT", 1]]
D,   Alchemy::Language Count (0.1ms)  SELECT COUNT(*) FROM "alchemy_languages" WHERE "alchemy_languages"."site_id" = ? AND "alchemy_languages"."public" = ?  [["site_id", 1], ["public", 1]]
D,   Alchemy::User Count (0.2ms)  SELECT COUNT(*) FROM "alchemy_users"
D,   Rendering layout layouts/application.html.erb
D,   Rendering alchemy_cms-6.0.5/app/views/alchemy/pages/show.html.erb within layouts/application
D,   Alchemy::Element Load (0.3ms)  SELECT "alchemy_elements".* FROM "alchemy_elements" WHERE "alchemy_elements"."page_version_id" = ? ORDER BY "alchemy_elements"."position" ASC  [["page_version_id", 2]]
D,   Alchemy::Content Load (0.4ms)  SELECT "alchemy_contents".* FROM "alchemy_contents" WHERE "alchemy_contents"."element_id" = ?  [["element_id", 2]]
D,   Alchemy::EssenceText Load (0.2ms)  SELECT "alchemy_essence_texts".* FROM "alchemy_essence_texts" WHERE "alchemy_essence_texts"."id" = ?  [["id", 2]]
D,   Alchemy::EssencePicture Load (0.3ms)  SELECT "alchemy_essence_pictures".* FROM "alchemy_essence_pictures" WHERE "alchemy_essence_pictures"."id" = ?  [["id", 2]]
D,   Alchemy::EssenceRichtext Load (0.3ms)  SELECT "alchemy_essence_richtexts".* FROM "alchemy_essence_richtexts" WHERE "alchemy_essence_richtexts"."id" = ?  [["id", 2]]
D,   Gutentag::Tagging Load (0.0ms)  SELECT "gutentag_taggings".* FROM "gutentag_taggings" WHERE "gutentag_taggings"."taggable_type" = ? AND "gutentag_taggings"."taggable_id" = ?  [["taggable_type", "Alchemy::Element"], ["taggable_id", 2]]
D,   Alchemy::Page Exists? (0.1ms)  SELECT 1 AS one FROM "alchemy_pages" INNER JOIN "alchemy_elements_alchemy_pages" ON "alchemy_pages"."id" = "alchemy_elements_alchemy_pages"."page_id" WHERE "alchemy_elements_alchemy_pages"."element_id" = ? AND "alchemy_pages"."id" = ? LIMIT ?  [["element_id", 2], ["id", 1], ["LIMIT", 1]]
D,   Alchemy::Ingredient Load (0.0ms)  SELECT "alchemy_ingredients".* FROM "alchemy_ingredients" WHERE "alchemy_ingredients"."element_id" = ?  [["element_id", 2]]
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/essences/_essence_text_view.html.erb (Duration: 0.4ms | Allocations: 211)
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/essences/_essence_picture_view.html.erb (Duration: 0.4ms | Allocations: 268)
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/essences/_essence_richtext_view.html.erb (Duration: 0.2ms | Allocations: 169)
D,   Rendered alchemy/elements/_article.html.erb (Duration: 8.9ms | Allocations: 5297) [cache miss]
D,   Rendered alchemy/page_layouts/_index.html.erb (Duration: 40.5ms | Allocations: 32876) [cache miss]
I,   Rendered alchemy_cms-6.0.5/app/views/alchemy/pages/show.html.erb within layouts/application (Duration: 67.6ms | Allocations: 95201)
D,   CACHE Alchemy::Page Load (0.0ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   CACHE Alchemy::Page Load (0.0ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/pages/_meta_data.html.erb (Duration: 1.2ms | Allocations: 1063)
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/_menubar.html.erb (Duration: 0.6ms | Allocations: 288)
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/_preview_mode_code.html.erb (Duration: 10.1ms | Allocations: 127)
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/_edit_mode.html.erb (Duration: 11.7ms | Allocations: 840)
I,   Rendered layout layouts/application.html.erb (Duration: 82.0ms | Allocations: 98075)
I, Completed 200 OK in 153ms (Views: 115.4ms | ActiveRecord: 8.5ms | Allocations: 139816)

6.0.5 warm cache (11 queries)

I, Started GET "/" for 127.0.0.1 at 2023-05-10 10:33:30 -0700
I, Processing by Alchemy::PagesController#index as */*
D,   Alchemy::Site Load (0.1ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" WHERE "alchemy_sites"."host" = ? LIMIT ?  [["host", "localhost"], ["LIMIT", 1]]
D,   Alchemy::Site Load (0.0ms)  SELECT "alchemy_sites".* FROM "alchemy_sites"
D,   Alchemy::Site Load (0.0ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" ORDER BY "alchemy_sites"."id" ASC LIMIT ?  [["LIMIT", 1]]
D,   Alchemy::Language Load (0.1ms)  SELECT "alchemy_languages".* FROM "alchemy_languages" WHERE "alchemy_languages"."site_id" = ? AND "alchemy_languages"."default" = ? LIMIT ?  [["site_id", 1], ["default", 1], ["LIMIT", 1]]
D,   Alchemy::Page Load (0.0ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   Alchemy::User Exists? (0.1ms)  SELECT 1 AS one FROM "alchemy_users" WHERE "alchemy_users"."alchemy_roles" LIKE '%admin%' LIMIT ?  [["LIMIT", 1]]
D,   Alchemy::PageVersion Load (0.1ms)  SELECT "alchemy_page_versions".* FROM "alchemy_page_versions" WHERE "alchemy_page_versions"."page_id" = ? AND "alchemy_page_versions"."public_on" IS NOT NULL ORDER BY "alchemy_page_versions"."public_on" DESC LIMIT ?  [["page_id", 1], ["LIMIT", 1]]
D,   Alchemy::Language Count (0.1ms)  SELECT COUNT(*) FROM "alchemy_languages" WHERE "alchemy_languages"."site_id" = ? AND "alchemy_languages"."public" = ?  [["site_id", 1], ["public", 1]]
D,   Alchemy::User Count (0.1ms)  SELECT COUNT(*) FROM "alchemy_users"
D,   Rendering layout layouts/application.html.erb
D,   Rendering alchemy_cms-6.0.5/app/views/alchemy/pages/show.html.erb within layouts/application
D,   Rendered alchemy/page_layouts/_index.html.erb (Duration: 0.7ms | Allocations: 120) [cache hit]
I,   Rendered alchemy_cms-6.0.5/app/views/alchemy/pages/show.html.erb within layouts/application (Duration: 0.9ms | Allocations: 183)
D,   CACHE Alchemy::Page Load (0.0ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   CACHE Alchemy::Page Load (0.0ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/pages/_meta_data.html.erb (Duration: 0.9ms | Allocations: 784)
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/_menubar.html.erb (Duration: 0.1ms | Allocations: 64)
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/_preview_mode_code.html.erb (Duration: 0.0ms | Allocations: 5)
D,   Rendered alchemy_cms-6.0.5/app/views/alchemy/_edit_mode.html.erb (Duration: 0.2ms | Allocations: 170)
I,   Rendered layout layouts/application.html.erb (Duration: 2.4ms | Allocations: 1495)
I, Completed 200 OK in 9ms (Views: 2.7ms | ActiveRecord: 0.6ms | Allocations: 5495)

6.0.6 empty cache (22 queries)

I, Started GET "/" for 127.0.0.1 at 2023-05-10 10:47:57 -0700
I, Processing by Alchemy::PagesController#index as */*
D,   Alchemy::Site Load (0.3ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" WHERE "alchemy_sites"."host" = ? LIMIT ?  [["host", "localhost"], ["LIMIT", 1]]
D,   Alchemy::Site Load (0.1ms)  SELECT "alchemy_sites".* FROM "alchemy_sites"
D,   Alchemy::Site Load (0.1ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" ORDER BY "alchemy_sites"."id" ASC LIMIT ?  [["LIMIT", 1]]
D,   Alchemy::Language Load (0.2ms)  SELECT "alchemy_languages".* FROM "alchemy_languages" WHERE "alchemy_languages"."site_id" = ? AND "alchemy_languages"."default" = ? LIMIT ?  [["site_id", 1], ["default", 1], ["LIMIT", 1]]
D,   Alchemy::Page Load (0.2ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE ("alchemy_pages"."layoutpage" = ? OR "alchemy_pages"."layoutpage" IS NULL) AND "alchemy_pages"."language_root" = ? AND "alchemy_pages"."language_id" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["layoutpage", 0], ["language_root", 1], ["language_id", 1], ["LIMIT", 1]]
D,   Gutentag::Tagging Load (0.2ms)  SELECT "gutentag_taggings".* FROM "gutentag_taggings" WHERE "gutentag_taggings"."taggable_type" = ? AND "gutentag_taggings"."taggable_id" = ?  [["taggable_type", "Alchemy::Page"], ["taggable_id", 1]]
D,   Alchemy::Language Load (0.0ms)  SELECT "alchemy_languages".* FROM "alchemy_languages" WHERE "alchemy_languages"."id" = ?  [["id", 1]]
D,   Alchemy::PageVersion Load (0.2ms)  SELECT "alchemy_page_versions".* FROM "alchemy_page_versions" WHERE "alchemy_page_versions"."public_on" IS NOT NULL AND "alchemy_page_versions"."page_id" = ? ORDER BY "alchemy_page_versions"."public_on" DESC  [["page_id", 1]]
D,   Alchemy::Site Load (0.0ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" WHERE "alchemy_sites"."id" = ?  [["id", 1]]
D,   Alchemy::Element Load (0.2ms)  SELECT "alchemy_elements".* FROM "alchemy_elements" WHERE "alchemy_elements"."page_version_id" = ? ORDER BY "alchemy_elements"."position" ASC  [["page_version_id", 2]]
D,   HABTM_TouchablePages Load (0.2ms)  SELECT "alchemy_elements_alchemy_pages".* FROM "alchemy_elements_alchemy_pages" WHERE "alchemy_elements_alchemy_pages"."element_id" = ?  [["element_id", 2]]
D,   Alchemy::Ingredient Load (0.2ms)  SELECT "alchemy_ingredients".* FROM "alchemy_ingredients" WHERE "alchemy_ingredients"."element_id" = ?  [["element_id", 2]]
D,   Alchemy::Content Load (0.2ms)  SELECT "alchemy_contents".* FROM "alchemy_contents" WHERE "alchemy_contents"."element_id" = ?  [["element_id", 2]]
D,   Alchemy::Page Load (0.1ms)  SELECT DISTINCT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."id" = ?  [["id", 1]]
D,   Alchemy::EssenceText Load (0.2ms)  SELECT "alchemy_essence_texts".* FROM "alchemy_essence_texts" WHERE "alchemy_essence_texts"."id" = ?  [["id", 2]]
D,   Alchemy::EssencePicture Load (0.2ms)  SELECT "alchemy_essence_pictures".* FROM "alchemy_essence_pictures" WHERE "alchemy_essence_pictures"."id" = ?  [["id", 2]]
D,   Alchemy::EssenceRichtext Load (0.0ms)  SELECT "alchemy_essence_richtexts".* FROM "alchemy_essence_richtexts" WHERE "alchemy_essence_richtexts"."id" = ?  [["id", 2]]
D,   Alchemy::User Exists? (0.2ms)  SELECT 1 AS one FROM "alchemy_users" WHERE "alchemy_users"."alchemy_roles" LIKE '%admin%' LIMIT ?  [["LIMIT", 1]]
D,   Alchemy::Language Count (0.1ms)  SELECT COUNT(*) FROM "alchemy_languages" WHERE "alchemy_languages"."site_id" = ? AND "alchemy_languages"."public" = ?  [["site_id", 1], ["public", 1]]
D,   Alchemy::User Count (0.0ms)  SELECT COUNT(*) FROM "alchemy_users"
D,   Rendering layout layouts/application.html.erb
D,   Rendering alchemy_cms-6.0.6/app/views/alchemy/pages/show.html.erb within layouts/application
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/essences/_essence_text_view.html.erb (Duration: 0.3ms | Allocations: 213)
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/essences/_essence_picture_view.html.erb (Duration: 0.3ms | Allocations: 272)
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/essences/_essence_richtext_view.html.erb (Duration: 0.2ms | Allocations: 169)
D,   Rendered alchemy/elements/_article.html.erb (Duration: 4.2ms | Allocations: 4241) [cache miss]
D,   Rendered alchemy/page_layouts/_index.html.erb (Duration: 25.1ms | Allocations: 7773) [cache miss]
I,   Rendered alchemy_cms-6.0.6/app/views/alchemy/pages/show.html.erb within layouts/application (Duration: 39.0ms | Allocations: 70094)
D,   Alchemy::Page Load (0.2ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   CACHE Alchemy::Page Load (0.0ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/pages/_meta_data.html.erb (Duration: 2.1ms | Allocations: 1596)
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/_menubar.html.erb (Duration: 0.6ms | Allocations: 288)
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/_preview_mode_code.html.erb (Duration: 0.3ms | Allocations: 127)
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/_edit_mode.html.erb (Duration: 2.1ms | Allocations: 840)
I,   Rendered layout layouts/application.html.erb (Duration: 51.4ms | Allocations: 73501)
I, Completed 200 OK in 124ms (Views: 63.0ms | ActiveRecord: 8.4ms | Allocations: 143044)

6.0.6 warm cache (22 queries)

I, Started GET "/" for 127.0.0.1 at 2023-05-10 10:48:44 -0700
I, Processing by Alchemy::PagesController#index as */*
D,   Alchemy::Site Load (0.1ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" WHERE "alchemy_sites"."host" = ? LIMIT ?  [["host", "localhost"], ["LIMIT", 1]]
D,   Alchemy::Site Load (0.0ms)  SELECT "alchemy_sites".* FROM "alchemy_sites"
D,   Alchemy::Site Load (0.0ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" ORDER BY "alchemy_sites"."id" ASC LIMIT ?  [["LIMIT", 1]]
D,   Alchemy::Language Load (0.0ms)  SELECT "alchemy_languages".* FROM "alchemy_languages" WHERE "alchemy_languages"."site_id" = ? AND "alchemy_languages"."default" = ? LIMIT ?  [["site_id", 1], ["default", 1], ["LIMIT", 1]]
D,   Alchemy::Page Load (0.0ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE ("alchemy_pages"."layoutpage" = ? OR "alchemy_pages"."layoutpage" IS NULL) AND "alchemy_pages"."language_root" = ? AND "alchemy_pages"."language_id" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["layoutpage", 0], ["language_root", 1], ["language_id", 1], ["LIMIT", 1]]
D,   Gutentag::Tagging Load (0.0ms)  SELECT "gutentag_taggings".* FROM "gutentag_taggings" WHERE "gutentag_taggings"."taggable_type" = ? AND "gutentag_taggings"."taggable_id" = ?  [["taggable_type", "Alchemy::Page"], ["taggable_id", 1]]
D,   Alchemy::Language Load (0.1ms)  SELECT "alchemy_languages".* FROM "alchemy_languages" WHERE "alchemy_languages"."id" = ?  [["id", 1]]
D,   Alchemy::PageVersion Load (0.0ms)  SELECT "alchemy_page_versions".* FROM "alchemy_page_versions" WHERE "alchemy_page_versions"."public_on" IS NOT NULL AND "alchemy_page_versions"."page_id" = ? ORDER BY "alchemy_page_versions"."public_on" DESC  [["page_id", 1]]
D,   Alchemy::Site Load (0.0ms)  SELECT "alchemy_sites".* FROM "alchemy_sites" WHERE "alchemy_sites"."id" = ?  [["id", 1]]
D,   Alchemy::Element Load (0.0ms)  SELECT "alchemy_elements".* FROM "alchemy_elements" WHERE "alchemy_elements"."page_version_id" = ? ORDER BY "alchemy_elements"."position" ASC  [["page_version_id", 2]]
D,   HABTM_TouchablePages Load (0.0ms)  SELECT "alchemy_elements_alchemy_pages".* FROM "alchemy_elements_alchemy_pages" WHERE "alchemy_elements_alchemy_pages"."element_id" = ?  [["element_id", 2]]
D,   Alchemy::Ingredient Load (0.0ms)  SELECT "alchemy_ingredients".* FROM "alchemy_ingredients" WHERE "alchemy_ingredients"."element_id" = ?  [["element_id", 2]]
D,   Alchemy::Content Load (0.0ms)  SELECT "alchemy_contents".* FROM "alchemy_contents" WHERE "alchemy_contents"."element_id" = ?  [["element_id", 2]]
D,   Alchemy::Page Load (0.0ms)  SELECT DISTINCT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."id" = ?  [["id", 1]]
D,   Alchemy::EssenceText Load (0.0ms)  SELECT "alchemy_essence_texts".* FROM "alchemy_essence_texts" WHERE "alchemy_essence_texts"."id" = ?  [["id", 2]]
D,   Alchemy::EssencePicture Load (0.0ms)  SELECT "alchemy_essence_pictures".* FROM "alchemy_essence_pictures" WHERE "alchemy_essence_pictures"."id" = ?  [["id", 2]]
D,   Alchemy::EssenceRichtext Load (0.0ms)  SELECT "alchemy_essence_richtexts".* FROM "alchemy_essence_richtexts" WHERE "alchemy_essence_richtexts"."id" = ?  [["id", 2]]
D,   Alchemy::User Exists? (0.1ms)  SELECT 1 AS one FROM "alchemy_users" WHERE "alchemy_users"."alchemy_roles" LIKE '%admin%' LIMIT ?  [["LIMIT", 1]]
D,   Alchemy::Language Count (0.1ms)  SELECT COUNT(*) FROM "alchemy_languages" WHERE "alchemy_languages"."site_id" = ? AND "alchemy_languages"."public" = ?  [["site_id", 1], ["public", 1]]
D,   Alchemy::User Count (0.0ms)  SELECT COUNT(*) FROM "alchemy_users"
D,   Rendering layout layouts/application.html.erb
D,   Rendering alchemy_cms-6.0.6/app/views/alchemy/pages/show.html.erb within layouts/application
D,   Rendered alchemy/page_layouts/_index.html.erb (Duration: 3.4ms | Allocations: 140) [cache hit]
I,   Rendered alchemy_cms-6.0.6/app/views/alchemy/pages/show.html.erb within layouts/application (Duration: 3.6ms | Allocations: 210)
D,   Alchemy::Page Load (0.1ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   CACHE Alchemy::Page Load (0.0ms)  SELECT "alchemy_pages".* FROM "alchemy_pages" WHERE "alchemy_pages"."language_id" = ? AND "alchemy_pages"."language_root" = ? ORDER BY "alchemy_pages"."id" ASC LIMIT ?  [["language_id", 1], ["language_root", 1], ["LIMIT", 1]]
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/pages/_meta_data.html.erb (Duration: 1.3ms | Allocations: 883)
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/_menubar.html.erb (Duration: 0.1ms | Allocations: 64)
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/_preview_mode_code.html.erb (Duration: 0.0ms | Allocations: 5)
D,   Rendered alchemy_cms-6.0.6/app/views/alchemy/_edit_mode.html.erb (Duration: 0.2ms | Allocations: 170)
I,   Rendered layout layouts/application.html.erb (Duration: 5.5ms | Allocations: 1622)
I, Completed 200 OK in 15ms (Views: 5.8ms | ActiveRecord: 0.8ms | Allocations: 10572)

The best solution would be if we didn't have to run the eager loading unnecessarily, but that I'm not sure if that's possible to know at the right time since the templates aren't hit yet, and they may or may not have fragment caching. I suspect this was the original concern in #1674.

As is, there's still a question of whether this is better than not eager loading at all. One might argue that ideally, the Alchemy origin server shouldn't be getting these kinds of cached requests anyways. However, if the app can still respond efficiently when caches are cleared, that will mitigate any slowdown when intermediate (e.g. CDN) caches are cleared.

@tvdeyen tvdeyen changed the title Potential performance regression in 6.0 due to unnecessarily eager loading Performance regression in 6.0 due to unnecessarily eager loading May 10, 2023
tvdeyen added a commit to tvdeyen/alchemy_cms that referenced this issue May 11, 2023
@tvdeyen
Revert "Preload related objects in Alchemy::PagesController"
008f6af 
Pages make use of fragment caching and we cannot know which element is cached.

Therefore we cannot know what to eager load.

Closes AlchemyCMS#2468

This reverts commit d556574.
@tvdeyen tvdeyen mentioned this issue May 11, 2023
Merged
2 tasks
tvdeyen added a commit to tvdeyen/alchemy_cms that referenced this issue May 11, 2023
@tvdeyen
Revert "Preload related objects in Alchemy::PagesController"
1a8edac 
Pages make use of fragment caching and we cannot know which element is cached.

Therefore we cannot know what to eager load.

Refs AlchemyCMS#2468

This reverts commit d556574.
tvdeyen added a commit to tvdeyen/alchemy_cms that referenced this issue May 11, 2023
@tvdeyen
Do not eager load elements in pages controller
f39ac51 
Pages make use of fragment caching and we cannot know which element is cached.

Therefore we cannot know what to eager load.

Closes AlchemyCMS#2468

This partially reverts commit 0aa84d0.
@tvdeyen tvdeyen mentioned this issue May 11, 2023
Merged
@tvdeyen
Copy link
Member Author

tvdeyen commented May 11, 2023

@wuservices thanks for the great write up and all this infos. This really helped to understand the issue. We agree that this is an regression that needs to be reverted. I created a PR that only reverts the change in question at #2474

Would you mind trying that one and verify it removes the performance regression? Thanks again for bringing this one up.

tvdeyen added a commit to tvdeyen/alchemy_cms that referenced this issue May 18, 2023
@tvdeyen
Do not eager load elements in pages controller
3462603 
Pages make use of fragment caching and we cannot know which element is cached.

Therefore we cannot know what to eager load.

Closes AlchemyCMS#2468

This partially reverts commit 0aa84d0.
@volta-net volta-net bot closed this as completed May 18, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
confirmed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@tvdeyen @wuservices