3

I'm debugging a php script which is saving data in memcache as a way to warmup an application.
This script only makes set calls to save data into memcache, and after a specific number of entries being set, the first items inserted start to disappear (behaviour reproducible).

I've been reading memcache documentation, and learnt about the eviction process so started to check logs and read the stats to see if that's the reason.

Stopping the php script just before inserting the item that starts erasing the first elements, I run stats slabs:

stats slabs
STAT 1:chunk_size 96
STAT 1:chunks_per_page 10922
STAT 1:total_pages 1
STAT 1:total_chunks 10922
STAT 1:used_chunks 1
STAT 1:free_chunks 10921
STAT 1:free_chunks_end 0
STAT 1:mem_requested 93
STAT 1:get_hits 0
STAT 1:cmd_set 1
STAT 1:delete_hits 0
STAT 1:incr_hits 0
STAT 1:decr_hits 0
STAT 1:cas_hits 0
STAT 1:cas_badval 0
STAT 1:touch_hits 0
STAT 3:chunk_size 152
STAT 3:chunks_per_page 6898
STAT 3:total_pages 4
STAT 3:total_chunks 27592
STAT 3:used_chunks 22787
STAT 3:free_chunks 4805
STAT 3:free_chunks_end 0
STAT 3:mem_requested 3232040
STAT 3:get_hits 0
STAT 3:cmd_set 22814
STAT 3:delete_hits 0
STAT 3:incr_hits 0
STAT 3:decr_hits 0
STAT 3:cas_hits 0
STAT 3:cas_badval 0
STAT 3:touch_hits 0
STAT 4:chunk_size 192
STAT 4:chunks_per_page 5461
STAT 4:total_pages 1
STAT 4:total_chunks 5461
STAT 4:used_chunks 1300
STAT 4:free_chunks 4161
STAT 4:free_chunks_end 0
STAT 4:mem_requested 202877
STAT 4:get_hits 0
STAT 4:cmd_set 1301
STAT 4:delete_hits 0
STAT 4:incr_hits 0
STAT 4:decr_hits 0
STAT 4:cas_hits 0
STAT 4:cas_badval 0
STAT 4:touch_hits 0
STAT active_slabs 3
STAT total_malloced 6291008

As you can see, all slabs still have free space left.

When letting the script insert the next item, memcache server logs this:

30: going from conn_closing to conn_closed
29: going from conn_read to conn_parse_cmd
<29 set [tc:e-401:id-2485:profile-5:property-11][1] 0 0 3
29: going from conn_parse_cmd to conn_nread
> NOT FOUND [tc:e-401:id-2485:profile-5:property-11][1]
>29 STORED

Calling again stats slabs I see that a new slab has been used:

stats slabs
STAT 1:chunk_size 96
STAT 1:chunks_per_page 10922
STAT 1:total_pages 1
STAT 1:total_chunks 10922
STAT 1:used_chunks 1
STAT 1:free_chunks 10921
STAT 1:free_chunks_end 0
STAT 1:mem_requested 93
STAT 1:get_hits 0
STAT 1:cmd_set 1
STAT 1:delete_hits 0
STAT 1:incr_hits 0
STAT 1:decr_hits 0
STAT 1:cas_hits 0
STAT 1:cas_badval 0
STAT 1:touch_hits 0
STAT 2:chunk_size 120
STAT 2:chunks_per_page 8738
STAT 2:total_pages 1
STAT 2:total_chunks 8738
STAT 2:used_chunks 1
STAT 2:free_chunks 8737
STAT 2:free_chunks_end 0
STAT 2:mem_requested 120
STAT 2:get_hits 0
STAT 2:cmd_set 1
STAT 2:delete_hits 0
STAT 2:incr_hits 0
STAT 2:decr_hits 0
STAT 2:cas_hits 0
STAT 2:cas_badval 0
STAT 2:touch_hits 0
STAT 3:chunk_size 152
STAT 3:chunks_per_page 6898
STAT 3:total_pages 4
STAT 3:total_chunks 27592
STAT 3:used_chunks 22790
STAT 3:free_chunks 4802
STAT 3:free_chunks_end 0
STAT 3:mem_requested 3232437
STAT 3:get_hits 0
STAT 3:cmd_set 22817
STAT 3:delete_hits 0
STAT 3:incr_hits 0
STAT 3:decr_hits 0
STAT 3:cas_hits 0
STAT 3:cas_badval 0
STAT 3:touch_hits 0
STAT 4:chunk_size 192
STAT 4:chunks_per_page 5461
STAT 4:total_pages 1
STAT 4:total_chunks 5461
STAT 4:used_chunks 1300
STAT 4:free_chunks 4161
STAT 4:free_chunks_end 0
STAT 4:mem_requested 202877
STAT 4:get_hits 0
STAT 4:cmd_set 1301
STAT 4:delete_hits 0
STAT 4:incr_hits 0
STAT 4:decr_hits 0
STAT 4:cas_hits 0
STAT 4:cas_badval 0
STAT 4:touch_hits 0
STAT active_slabs 4
STAT total_malloced 7339568
END

The first item (with key starting with "tc:e-501" is no longer present (checked using memdump --servers=localhost | grep tc:e-501, and calling a get from php to get the first key also gives me non-existing)

Calling stats items I see that the evictions counter is 0...

stats items
STAT items:1:number 1
STAT items:1:age 1391
STAT items:1:evicted 0
STAT items:1:evicted_nonzero 0
STAT items:1:evicted_time 0
STAT items:1:outofmemory 0
STAT items:1:tailrepairs 0
STAT items:1:reclaimed 0
STAT items:1:expired_unfetched 0
STAT items:1:evicted_unfetched 0
STAT items:1:crawler_reclaimed 0
STAT items:2:number 1
STAT items:2:age 982
STAT items:2:evicted 0
STAT items:2:evicted_nonzero 0
STAT items:2:evicted_time 0
STAT items:2:outofmemory 0
STAT items:2:tailrepairs 0
STAT items:2:reclaimed 0
STAT items:2:expired_unfetched 0
STAT items:2:evicted_unfetched 0
STAT items:2:crawler_reclaimed 0
STAT items:3:number 22790
STAT items:3:age 1391
STAT items:3:evicted 0
STAT items:3:evicted_nonzero 0
STAT items:3:evicted_time 0
STAT items:3:outofmemory 0
STAT items:3:tailrepairs 0
STAT items:3:reclaimed 0
STAT items:3:expired_unfetched 0
STAT items:3:evicted_unfetched 0
STAT items:3:crawler_reclaimed 0
STAT items:4:number 1300
STAT items:4:age 1381
STAT items:4:evicted 0
STAT items:4:evicted_nonzero 0
STAT items:4:evicted_time 0
STAT items:4:outofmemory 0
STAT items:4:tailrepairs 0
STAT items:4:reclaimed 0
STAT items:4:expired_unfetched 0
STAT items:4:evicted_unfetched 0
STAT items:4:crawler_reclaimed 0
END

Following calls to set from the script keep removing the first items inserted sequentially, so I discard a key collision.

What may be causing this behaviour? I'm currently completely clueless.

Edited: Using memcached 1.4.20 Edited: Using option -M does not seems to help, items still get removed and no set call return any false value.

6
  • 1
    Just a quick question, after how many sets does this behavior occur ? if so is the data size of the set in the limits ? can you check parameter -I (I in India) in /etc/memcached.conf or where your memcached config is. Oct 3, 2016 at 13:45
  • Currently, after 24115 set calls it starts removing items. About the -I, I'm on osx, installed it through brew and to set any configuration I need to put it as an argument. Currently I'm not setting it so using the default value. Oct 3, 2016 at 14:05
  • 1
    Can you start memcached using the following command and test it ? memcached -p 11211 -d -u root -I 8m -m 256 -vvv >> /var/log/memcached 2&1. This command starts memcached with max item size 8MB with 256MB memory. I may think the problem may be item size. Also check memcached log or remove it to see debug. Thanks Oct 4, 2016 at 6:14
  • Tried, and no changes :( Oct 4, 2016 at 7:53
  • Damn, i was hoping a change, as a last recommendation, would it be problematic if you use an older/newer version ? perhaps an internal bug ? Oct 4, 2016 at 8:11

0

You must log in to answer this question.

Browse other questions tagged .