Dalli/Memcached looks like caching but it's not caching in development environment

Question

• Rails 4.0.4
• Unicorn
• Dalli 2.7
• Memcached 1.4.17

development.rb is set up to use caching in dev env:

  config.cache_classes = true
  config.action_controller.perform_caching = true
  config.cache_store = :dalli_store

Weird thing is at the logs, see it:

18:57:15 web.1  |   Program Load (3.1ms)  SELECT "programs".* FROM "programs" WHERE "programs"."is_deleted" = 'f' AND (poster_file_name IS NOT NULL) AND ("programs"."poster_file_name" != 'yumurcatvkucuk.jpg') LIMIT 10
18:57:15 web.1  | Cache read: views/programs/21-20140408150833637850000/programs/807-20140408150843947601000/programs/925-20140408150845273240000/programs/872-20140418084359291046000/programs/132-20140408150835259856000/programs/136-20140408150835308846000/programs/140-20140408150835371772000/programs/1280-20140408150849908310000/programs/340-20140408150837584935000/programs/150-20140408150835553155000/adc205508053828cb96d93c37b9ad0f7
18:57:15 web.1  | Read fragment views/programs/21-20140408150833637850000/programs/807-20140408150843947601000/programs/925-20140408150845273240000/programs/872-20140418084359291046000/programs/132-20140408150835259856000/programs/136-20140408150835308846000/programs/140-20140408150835371772000/programs/1280-20140408150849908310000/programs/340-20140408150837584935000/programs/150-20140408150835553155000/adc205508053828cb96d93c37b9ad0f7 (0.6ms)
18:57:15 web.1  |   Rendered pages/index.html.erb within layouts/application (47.8ms)
18:57:15 web.1  |   Program Load (2.8ms)  SELECT "programs".* FROM "programs" WHERE "programs"."is_deleted" = 'f' AND "programs"."category_id" = 10 ORDER BY "programs"."order_no" ASC LIMIT 14
18:57:15 web.1  |   Category Load (2.4ms)  SELECT "categories".* FROM "categories" WHERE "categories"."id" IN (10)
18:57:15 web.1  | Cache read: views/programs/8-20140408150833498130000/programs/19-20140408150833622733000/programs/30-20140408150833742922000/programs/24-20140408150833663802000/programs/1021-20140408150846580202000/programs/872-20140418084359291046000/programs/1187-20140408150848167962000/programs/866-20140408150844626941000/programs/1280-20140408150849908310000/programs/881-20140408150844749467000/programs/1376-20140408150850766221000/programs/1379-20140408150850809312000/programs/1437-20140408150851047434000/programs/3-20140408150832973507000/6c2638ad89493f0c3e448b3d66c4a1de
18:57:15 web.1  | Read fragment views/programs/8-20140408150833498130000/programs/19-20140408150833622733000/programs/30-20140408150833742922000/programs/24-20140408150833663802000/programs/1021-20140408150846580202000/programs/872-20140418084359291046000/programs/1187-20140408150848167962000/programs/866-20140408150844626941000/programs/1280-20140408150849908310000/programs/881-20140408150844749467000/programs/1376-20140408150850766221000/programs/1379-20140408150850809312000/programs/1437-20140408150851047434000/programs/3-20140408150832973507000/6c2638ad89493f0c3e448b3d66c4a1de (0.7ms)
18:57:15 web.1  |   Episode Load (2.8ms)  SELECT "episodes".* FROM "episodes" WHERE "episodes"."is_deleted" = 'f' AND "episodes"."episode_type_id" = 2 ORDER BY "episodes"."id" DESC LIMIT 7
18:57:15 web.1  |   Program Load (2.6ms)  SELECT "programs".* FROM "programs" WHERE "programs"."is_deleted" = 'f' AND "programs"."id" IN (1340, 711, 5, 1380, 1344, 1311, 1210)
18:57:15 web.1  | Cache read: views/episodes/149768-20140419064643365309000/episodes/149752-20140419064643075387000/episodes/149748-20140419064642994891000/episodes/149740-20140419064642741006000/episodes/149738-20140419064642706457000/episodes/149736-20140419064642673073000/episodes/149726-20140419064642492558000/6c2638ad89493f0c3e448b3d66c4a1de
18:57:15 web.1  | Read fragment views/episodes/149768-20140419064643365309000/episodes/149752-20140419064643075387000/episodes/149748-20140419064642994891000/episodes/149740-20140419064642741006000/episodes/149738-20140419064642706457000/episodes/149736-20140419064642673073000/episodes/149726-20140419064642492558000/6c2638ad89493f0c3e448b3d66c4a1de (0.6ms)
18:57:15 web.1  |   Episode Load (3.5ms)  SELECT "episodes".* FROM "episodes" WHERE "episodes"."is_deleted" = 'f' AND "episodes"."episode_type_id" = 1 ORDER BY "episodes"."id" DESC LIMIT 12
18:57:15 web.1  |   Program Load (2.6ms)  SELECT "programs".* FROM "programs" WHERE "programs"."is_deleted" = 'f' AND "programs"."id" IN (1016, 341)
18:57:15 web.1  | Cache read: views/episodes/149773-20140419094829793071000/episodes/149772-20140419091743738305000/episodes/149771-20140419091322119681000/episodes/149770-20140419100721271419000/episodes/149761-20140419064643243075000/episodes/149760-20140419064643225958000/episodes/149759-20140419064643207847000/episodes/149758-20140419064643182828000/episodes/149757-20140419064643166963000/episodes/149756-20140419064643149717000/episodes/149755-20140419064643132085000/episodes/149754-20140419064643113035000/6c2638ad89493f0c3e448b3d66c4a1de
18:57:15 web.1  | Read fragment views/episodes/149773-20140419094829793071000/episodes/149772-20140419091743738305000/episodes/149771-20140419091322119681000/episodes/149770-20140419100721271419000/episodes/149761-20140419064643243075000/episodes/149760-20140419064643225958000/episodes/149759-20140419064643207847000/episodes/149758-20140419064643182828000/episodes/149757-20140419064643166963000/episodes/149756-20140419064643149717000/episodes/149755-20140419064643132085000/episodes/149754-20140419064643113035000/6c2638ad89493f0c3e448b3d66c4a1de (0.6ms)

It writes and reads cache fragments BUT it runs all SQL each time I refresh the page! The logs are always same after all of my refreshes. It was supposed to show only fragment readings after the first loading??

I tried reinstalling Dalli gem, upgraded memcached to latest version.

When I try caching and fetching data in console, it's successful. Caching also works in production.

I'm using mini_profiler to see SQL transactions in dev env and I see the same SQLs in mini_profiler popup too...

Do you have an idea? What's going on?

A part from my view file:

<% cache @latest_episodes do %>
<% @latest_episodes.each do |t| %>
<% cache(t) do %>
<%= render 'common/slider_item', episode: t, lazy_owl: true %>
<% end %>
<% end %>
<% end %>

Answer 1

I'm still not so clear about the issue but I've found the reason.

As I stated in my question, the code I used in my view was like this:

<% cache @latest_episodes do %>
<% @latest_episodes.each do |t| %>
<% cache(t) do %>
<%= render 'common/slider_item', episode: t, lazy_owl: true %>
<% end %>
<% end %>
<% end %>

When I changed the instance variables to regular string keys and removed cache(t) blocks, everything worked just fine.

I guess this issue occurred because Rails had to recreate the cache key on each request by processing the instance variables. But if it's the point, how come does Rails also have an auto-expiring mechanism? The statement I guess shows that it should always hit the database to create cache keys.

Any comment would be appreciated on this.