Open adrienpoly opened 6 days ago
Topics#show pages are quite slow to render and in general from the load test we performed the /talks page was the slowest index page.
This PR tries to cache the talks cards
I have deployed for a short time this PR in prod an the results are not what I would have expected and they are hard to understand right now
This topics#show response time as we can see this PR makes the performance really worst
BUT when I look into the looks I don't see the same response time, response time are typically within the 50ms range for those pages.
I, [2024-09-25T23:30:45.693454 #83] INFO -- : [82779c63-c469-477c-af1b-56009323b77b] Completed 200 OK in 28ms (Views: 17.6ms | ActiveRecord: 1.7ms (10 queries, 3 cached) | GC: 0.0ms) I, [2024-09-25T23:30:46.121273 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Started GET "/topics/abstract-syntax-tree-ast" for 141.101.95.60 at 2024-09-25 23:30:46 +0000 I, [2024-09-25T23:30:46.122217 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Processing by TopicsController#show as HTML I, [2024-09-25T23:30:46.122276 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Parameters: {"slug"=>"abstract-syntax-tree-ast"} D, [2024-09-25T23:30:46.123628 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Session Load (0.1ms) SELECT "sessions".* FROM "sessions" WHERE "sessions"."id" = ? LIMIT ? [["id", 32], ["LIMIT", 1]] D, [2024-09-25T23:30:46.124946 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT ? [["id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.126304 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] WatchList Load (0.1ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.144579 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Talk Ids (0.3ms) SELECT "talks"."id" FROM "talks" INNER JOIN "watch_list_talks" ON "talks"."id" = "watch_list_talks"."talk_id" WHERE "watch_list_talks"."watch_list_id" = ? [["watch_list_id", 1]] D, [2024-09-25T23:30:46.145654 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Topic Load (0.1ms) SELECT "topics".* FROM "topics" WHERE "topics"."slug" = ? LIMIT ? [["slug", "abstract-syntax-tree-ast"], ["LIMIT", 1]] D, [2024-09-25T23:30:46.147332 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendering layout layouts/application.html.erb D, [2024-09-25T23:30:46.147405 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendering topics/show.html.erb within layouts/application D, [2024-09-25T23:30:46.149912 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] (0.8ms) SELECT COUNT(*) AS "size", MAX("talks"."updated_at") AS timestamp FROM "talks" INNER JOIN "talk_topics" ON "talks"."id" = "talk_topics"."talk_id" WHERE "talk_topics"."topic_id" = ? [["topic_id", 875]] D, [2024-09-25T23:30:46.158374 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] SolidCache::Entry Load (7.6ms) SELECT "solid_cache_entries"."key", "solid_cache_entries"."value" FROM "solid_cache_entries" WHERE "solid_cache_entries"."key_hash" IN (?) [[nil, 7500390716560074863]] I, [2024-09-25T23:30:46.159038 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered topics/show.html.erb within layouts/application (Duration: 11.6ms | GC: 0.0ms) D, [2024-09-25T23:30:46.162084 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_top_banner.html.erb (Duration: 0.4ms | GC: 0.0ms) D, [2024-09-25T23:30:46.162571 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.3ms | GC: 0.0ms) D, [2024-09-25T23:30:46.162827 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.163040 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.163249 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.163474 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.163693 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.164665 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] CACHE WatchList Load (0.0ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.165459 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] CACHE WatchList Load (0.0ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.168015 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_user_dropdown.html.erb (Duration: 1.9ms | GC: 0.0ms) D, [2024-09-25T23:30:46.169156 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] CACHE WatchList Load (0.0ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.169811 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] CACHE WatchList Load (0.0ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.171676 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_user_mobile_dropdown.html.erb (Duration: 3.4ms | GC: 0.0ms) D, [2024-09-25T23:30:46.171800 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_navbar.html.erb (Duration: 9.6ms | GC: 0.0ms) D, [2024-09-25T23:30:46.172000 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_flashes.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.173676 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_footer.html.erb (Duration: 1.5ms | GC: 0.0ms) I, [2024-09-25T23:30:46.174116 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered layout layouts/application.html.erb (Duration: 26.7ms | GC: 0.0ms) D, [2024-09-25T23:30:46.175166 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Ahoy::Visit Load (0.1ms) SELECT "ahoy_visits".* FROM "ahoy_visits" WHERE "ahoy_visits"."visit_token" = ? LIMIT ? [["visit_token", "[FILTERED]"], ["LIMIT", 1]] D, [2024-09-25T23:30:46.176138 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] TRANSACTION (0.1ms) begin transaction D, [2024-09-25T23:30:46.176476 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Ahoy::Event Create (0.4ms) INSERT INTO "ahoy_events" ("visit_id", "user_id", "name", "properties", "time") VALUES (?, ?, ?, ?, ?) RETURNING "id" [["visit_id", 93941], ["user_id", nil], ["name", "topics#show"], ["properties", "{\"controller\":\"topics\",\"action\":\"show\",\"slug\":\"abstract-syntax-tree-ast\"}"], ["time", "2024-09-25 23:30:46.174767"]] D, [2024-09-25T23:30:46.176769 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] TRANSACTION (0.1ms) commit transaction I, [2024-09-25T23:30:46.177018 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Completed 200 OK in 55ms (Views: 18.8ms | ActiveRecord: 11.5ms (13 queries, 4 cached) | GC: 0.0ms) I, [2024-09-25T23:30:46.179585 #87] INFO -- : [b75fccb5-80f2-4174-84a8-90d5fdf033ba] Started GET "/up" for 127.0.0.1 at 2024-09-25 23:30:46 +0000 I, [2024-09-25T23:30:46.180248 #87] INFO -- : [b75fccb5-80f2-4174-84a8-90d5fdf033ba] Processing by Rails::HealthController#show as */* I, [2024-09-25T23:30:46.180861 #87] INFO -- : [b75fccb5-80f2-4174-84a8-90d5fdf033ba] [ahoy] Visit excluded
oha -c 1 -z 10s -m GET https://rubyvideo.dev/topics/abstract-syntax-tree-ast
Summary: Success rate: 100.00% Total: 10.1279 secs Slowest: 2.3109 secs Fastest: 0.3328 secs Average: 1.4139 secs Requests/sec: 0.7899
running the same test on a branch without cache returns those numbers
oha -c 1 -z 10s -m GET https://rubyvideo.dev/topics/abstract-syntax-tree-ast Summary: Success rate: 100.00% Total: 10.0025 secs Slowest: 2.1678 secs Fastest: 0.3932 secs Average: 1.2713 secs Requests/sec: 0.6998
Not sure what is happening but it looks like the cache is making things worst. I checked iin teh logs we do see in prod and dev cache read and write. To investigate....
Topics#show pages are quite slow to render and in general from the load test we performed the /talks page was the slowest index page.
This PR tries to cache the talks cards
I have deployed for a short time this PR in prod an the results are not what I would have expected and they are hard to understand right now
Appsignal
This topics#show response time as we can see this PR makes the performance really worst
logs
BUT when I look into the looks I don't see the same response time, response time are typically within the 50ms range for those pages.
Details
I, [2024-09-25T23:30:45.693454 #83] INFO -- : [82779c63-c469-477c-af1b-56009323b77b] Completed 200 OK in 28ms (Views: 17.6ms | ActiveRecord: 1.7ms (10 queries, 3 cached) | GC: 0.0ms) I, [2024-09-25T23:30:46.121273 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Started GET "/topics/abstract-syntax-tree-ast" for 141.101.95.60 at 2024-09-25 23:30:46 +0000 I, [2024-09-25T23:30:46.122217 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Processing by TopicsController#show as HTML I, [2024-09-25T23:30:46.122276 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Parameters: {"slug"=>"abstract-syntax-tree-ast"} D, [2024-09-25T23:30:46.123628 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Session Load (0.1ms) SELECT "sessions".* FROM "sessions" WHERE "sessions"."id" = ? LIMIT ? [["id", 32], ["LIMIT", 1]] D, [2024-09-25T23:30:46.124946 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT ? [["id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.126304 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] WatchList Load (0.1ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.144579 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Talk Ids (0.3ms) SELECT "talks"."id" FROM "talks" INNER JOIN "watch_list_talks" ON "talks"."id" = "watch_list_talks"."talk_id" WHERE "watch_list_talks"."watch_list_id" = ? [["watch_list_id", 1]] D, [2024-09-25T23:30:46.145654 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Topic Load (0.1ms) SELECT "topics".* FROM "topics" WHERE "topics"."slug" = ? LIMIT ? [["slug", "abstract-syntax-tree-ast"], ["LIMIT", 1]] D, [2024-09-25T23:30:46.147332 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendering layout layouts/application.html.erb D, [2024-09-25T23:30:46.147405 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendering topics/show.html.erb within layouts/application D, [2024-09-25T23:30:46.149912 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] (0.8ms) SELECT COUNT(*) AS "size", MAX("talks"."updated_at") AS timestamp FROM "talks" INNER JOIN "talk_topics" ON "talks"."id" = "talk_topics"."talk_id" WHERE "talk_topics"."topic_id" = ? [["topic_id", 875]] D, [2024-09-25T23:30:46.158374 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] SolidCache::Entry Load (7.6ms) SELECT "solid_cache_entries"."key", "solid_cache_entries"."value" FROM "solid_cache_entries" WHERE "solid_cache_entries"."key_hash" IN (?) [[nil, 7500390716560074863]] I, [2024-09-25T23:30:46.159038 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered topics/show.html.erb within layouts/application (Duration: 11.6ms | GC: 0.0ms) D, [2024-09-25T23:30:46.162084 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_top_banner.html.erb (Duration: 0.4ms | GC: 0.0ms) D, [2024-09-25T23:30:46.162571 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.3ms | GC: 0.0ms) D, [2024-09-25T23:30:46.162827 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.163040 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.163249 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.163474 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.163693 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/navbar/_link.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.164665 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] CACHE WatchList Load (0.0ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.165459 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] CACHE WatchList Load (0.0ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.168015 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_user_dropdown.html.erb (Duration: 1.9ms | GC: 0.0ms) D, [2024-09-25T23:30:46.169156 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] CACHE WatchList Load (0.0ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.169811 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] CACHE WatchList Load (0.0ms) SELECT "watch_lists".* FROM "watch_lists" WHERE "watch_lists"."user_id" = ? ORDER BY "watch_lists"."id" ASC LIMIT ? [["user_id", 1], ["LIMIT", 1]] D, [2024-09-25T23:30:46.171676 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_user_mobile_dropdown.html.erb (Duration: 3.4ms | GC: 0.0ms) D, [2024-09-25T23:30:46.171800 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_navbar.html.erb (Duration: 9.6ms | GC: 0.0ms) D, [2024-09-25T23:30:46.172000 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_flashes.html.erb (Duration: 0.1ms | GC: 0.0ms) D, [2024-09-25T23:30:46.173676 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered shared/_footer.html.erb (Duration: 1.5ms | GC: 0.0ms) I, [2024-09-25T23:30:46.174116 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Rendered layout layouts/application.html.erb (Duration: 26.7ms | GC: 0.0ms) D, [2024-09-25T23:30:46.175166 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Ahoy::Visit Load (0.1ms) SELECT "ahoy_visits".* FROM "ahoy_visits" WHERE "ahoy_visits"."visit_token" = ? LIMIT ? [["visit_token", "[FILTERED]"], ["LIMIT", 1]] D, [2024-09-25T23:30:46.176138 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] TRANSACTION (0.1ms) begin transaction D, [2024-09-25T23:30:46.176476 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] Ahoy::Event Create (0.4ms) INSERT INTO "ahoy_events" ("visit_id", "user_id", "name", "properties", "time") VALUES (?, ?, ?, ?, ?) RETURNING "id" [["visit_id", 93941], ["user_id", nil], ["name", "topics#show"], ["properties", "{\"controller\":\"topics\",\"action\":\"show\",\"slug\":\"abstract-syntax-tree-ast\"}"], ["time", "2024-09-25 23:30:46.174767"]] D, [2024-09-25T23:30:46.176769 #83] DEBUG -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] [primary] TRANSACTION (0.1ms) commit transaction I, [2024-09-25T23:30:46.177018 #83] INFO -- : [71ce1913-ac0a-48b6-9346-91ec8dbb117a] Completed 200 OK in 55ms (Views: 18.8ms | ActiveRecord: 11.5ms (13 queries, 4 cached) | GC: 0.0ms) I, [2024-09-25T23:30:46.179585 #87] INFO -- : [b75fccb5-80f2-4174-84a8-90d5fdf033ba] Started GET "/up" for 127.0.0.1 at 2024-09-25 23:30:46 +0000 I, [2024-09-25T23:30:46.180248 #87] INFO -- : [b75fccb5-80f2-4174-84a8-90d5fdf033ba] Processing by Rails::HealthController#show as */* I, [2024-09-25T23:30:46.180861 #87] INFO -- : [b75fccb5-80f2-4174-84a8-90d5fdf033ba] [ahoy] Visit excluded
oha
Summary: Success rate: 100.00% Total: 10.1279 secs Slowest: 2.3109 secs Fastest: 0.3328 secs Average: 1.4139 secs Requests/sec: 0.7899
running the same test on a branch without cache returns those numbers
Conclusion
Not sure what is happening but it looks like the cache is making things worst. I checked iin teh logs we do see in prod and dev cache read and write. To investigate....