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.
set
calls it starts removing items. About the-I
, I'm on osx, installed it throughbrew
and to set any configuration I need to put it as an argument. Currently I'm not setting it so using the default value.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