Set operations failing on Memcached 1.4.15
367 views
Skip to first unread message
Nikhil Garg
Mar 27, 2013, 5:45:03 PM3/27/13
to memc...@googlegroups.com
We run 1.4.2 on our cluster though it goes OOM every few days and hence are trying to migrate to a newer build. Release notes of 1.4.15 specifically say that it fixes some OOM cases, so we tried 1.4.15. We noted that around every 40-60 mins, sets would fail in burst. On further digging we found that each such burst corresponds to a spike in user cpu time and a spike in open connections. We found that even if a box isn't serving any production traffic, user cpu still spikes at roughly same frequency (though spikes are much shorter). During one of the spikes, top showed that it was infact memcached process which was hogging cpu. This behavior wasn't observed on previous binary. Some differences between old binary and new binary:
* old binary used libevent 1.4.2 whereas new one uses libevent 2.0.16
* old binary was running on Ubuntu 10.04 whereas new one is running on 12.04
Some more details about new binary:
stats
STAT pid 2727
STAT uptime 74268
STAT time 1364419469
STAT version 1.4.15
STAT libevent 2.0.16-stable
STAT pointer_size 64
STAT rusage_user 16275.537157
STAT rusage_system 20872.252434
STAT curr_connections 33
STAT total_connections 270918
STAT connection_structures 3712
STAT reserved_fds 20
STAT cmd_get 2216135698
STAT cmd_set 161257323
STAT cmd_flush 0
STAT cmd_touch 0
STAT get_hits 1970822534
STAT get_misses 245313164
STAT delete_misses 2615317
STAT delete_hits 4184410
STAT incr_misses 366964
STAT incr_hits 3804454
STAT decr_misses 0
STAT decr_hits 0
STAT cas_misses 21315
STAT cas_hits 81561392
STAT cas_badval 1845457
STAT touch_hits 0
STAT touch_misses 0
STAT auth_cmds 0
STAT auth_errors 0
STAT bytes_read 114764483242
STAT bytes_written 396446726727
STAT limit_maxbytes 29360128000
STAT accepting_conns 1
STAT listen_disabled_num 0
STAT threads 4
STAT conn_yields 0
STAT hash_power_level 26
STAT hash_bytes 536870912
STAT hash_is_expanding 0
STAT bytes 10653107460
STAT curr_items 61033194
STAT total_items 163080654
STAT expired_unfetched 57
STAT evicted_unfetched 0
STAT evictions 0
STAT reclaimed 72
END
stats settings
STAT maxbytes 3590324224
STAT maxconns 100000
STAT tcpport 11211
STAT udpport 11211
STAT inter 0.0.0.0
STAT verbosity 0
STAT oldest 0
STAT evictions on
STAT domain_socket NULL
STAT umask 700
STAT growth_factor 1.25
STAT chunk_size 48
STAT num_threads 4
STAT num_threads_per_udp 4
STAT stat_key_prefix :
STAT detail_enabled no
STAT reqs_per_event 20
STAT cas_enabled yes
STAT tcp_backlog 1024
STAT binding_protocol auto-negotiate
STAT auth_enabled_sasl no
STAT item_size_max 1048576
STAT maxconns_fast no
STAT hashpower_init 0
STAT slab_reassign no
STAT slab_automove 0
END
We get around 10K operations per second (get + multi get + set) per server.
root@mc20:~# ps aux | grep mem | grep -v grep
nobody 2727 49.4 38.5 13935812 13508096 ? Ssl 00:46 619:36 /usr/bin/memcached -m 28000 -p 11211 -u nobody -l 0.0.0.0 -d -c 100000
User cpu spikes every 40-60 minutes:
Open connections seem to spike at same time:
User cpu graph for a non-production server at similar frequency but much shorter spikes:
I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
Is there some background thread which does some heavy duty work every some minutes?
dormando
Mar 27, 2013, 7:11:24 PM3/27/13
to memc...@googlegroups.com
There could be a brief spike when the hash_power_level is being increased
(it shuffles everything into a new hash table). That should stop after it
reaches a steady state.
Can you confirm a few things:
- What exactly are you seeing when a "set fails" ? is it timing out, are
you getting some specific error back?
- stats items / stats slabs are also helpful to know.
- Does hash_power_level increase after every spike? Does the spikes stop
after a wile?
- You can start an instance with -o hashpower=26 or something similar. If
you start an instance that way does it not spike?
Otherwise: no there're no background threads that do anything like that.
slab automove is a background thread but you don't have it enabled and its
CPU usage is minimal.
> [user_cpu.gif]
> �
> ---
> You received this message because you are subscribed to the Google Groups "memcached" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to memcached+...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
> �
> �
>
>
(it shuffles everything into a new hash table). That should stop after it
reaches a steady state.
Can you confirm a few things:
- What exactly are you seeing when a "set fails" ? is it timing out, are
you getting some specific error back?
- stats items / stats slabs are also helpful to know.
- Does hash_power_level increase after every spike? Does the spikes stop
after a wile?
- You can start an instance with -o hashpower=26 or something similar. If
you start an instance that way does it not spike?
Otherwise: no there're no background threads that do anything like that.
slab automove is a background thread but you don't have it enabled and its
CPU usage is minimal.
>
>
> Open connections seem to spike at same time:
>
> [open_connections.gif]
>
> Open connections seem to spike at same time:
>
>
>
> User cpu graph for a non-production server at similar frequency but much shorter spikes:
>
> [non_prod_user_cpu.gif]
>
> User cpu graph for a non-production server at similar frequency but much shorter spikes:
>
>
>
> I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
>
> Is there some background thread which does some heavy duty work every some minutes?
>
> --
>
> I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
>
> Is there some background thread which does some heavy duty work every some minutes?
>
> �
> ---
> You received this message because you are subscribed to the Google Groups "memcached" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to memcached+...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
> �
> �
>
>
Nikhil Garg
Mar 27, 2013, 8:01:39 PM3/27/13
to memc...@googlegroups.com
Thanks for a prompt response. My replies are inline:
There could be a brief spike when the hash_power_level is being increased
(it shuffles everything into a new hash table). That should stop after it
reaches a steady state.
Did we not have this in older binaries? (in particular we never observed it in 1.4.2). Also these spikes lasted for a few minutes. Is that possible?
- What exactly are you seeing when a "set fails" ? is it timing out, are
you getting some specific error back?
I'm using libmemcached as my client and it din't throw back an error, just returned false so I'm assuming that it was timing out. Is there a better way of observing errors?
- stats items / stats slabs are also helpful to know.
stats slabs
STAT 1:chunk_size 96
STAT 1:chunks_per_page 10922
STAT 1:total_pages 100
STAT 1:total_chunks 1092200
STAT 1:used_chunks 1086855
STAT 1:free_chunks 5345
STAT 1:free_chunks_end 0
STAT 1:mem_requested 95489164
STAT 1:get_hits 70066393
STAT 1:cmd_set 10885892
STAT 1:delete_hits 474
STAT 1:incr_hits 0
STAT 1:decr_hits 0
STAT 1:cas_hits 9368849
STAT 1:cas_badval 51059
STAT 1:touch_hits 0
STAT 2:chunk_size 120
STAT 2:chunks_per_page 8738
STAT 2:total_pages 1943
STAT 2:total_chunks 16977934
STAT 2:used_chunks 16956442
STAT 2:free_chunks 21492
STAT 2:free_chunks_end 0
STAT 2:mem_requested 1924547384
STAT 2:get_hits 571120045
STAT 2:cmd_set 54181852
STAT 2:delete_hits 114588
STAT 2:incr_hits 2697219
STAT 2:decr_hits 0
STAT 2:cas_hits 34170584
STAT 2:cas_badval 432534
STAT 2:touch_hits 0
STAT 3:chunk_size 152
STAT 3:chunks_per_page 6898
STAT 3:total_pages 3957
STAT 3:total_chunks 27295386
STAT 3:used_chunks 27292791
STAT 3:free_chunks 2595
STAT 3:free_chunks_end 0
STAT 3:mem_requested 3648301347
STAT 3:get_hits 549399821
STAT 3:cmd_set 67477695
STAT 3:delete_hits 1406880
STAT 3:incr_hits 1092162
STAT 3:decr_hits 0
STAT 3:cas_hits 33066285
STAT 3:cas_badval 847765
STAT 3:touch_hits 0
STAT 4:chunk_size 192
STAT 4:chunks_per_page 5461
STAT 4:total_pages 1339
STAT 4:total_chunks 7312279
STAT 4:used_chunks 7310621
STAT 4:free_chunks 1658
STAT 4:free_chunks_end 0
STAT 4:mem_requested 1220748987
STAT 4:get_hits 160481460
STAT 4:cmd_set 12249019
STAT 4:delete_hits 313636
STAT 4:incr_hits 15073
STAT 4:decr_hits 0
STAT 4:cas_hits 3776268
STAT 4:cas_badval 166761
STAT 4:touch_hits 0
STAT 5:chunk_size 240
STAT 5:chunks_per_page 4369
STAT 5:total_pages 447
STAT 5:total_chunks 1952943
STAT 5:used_chunks 1950091
STAT 5:free_chunks 2852
STAT 5:free_chunks_end 0
STAT 5:mem_requested 407609749
STAT 5:get_hits 98694189
STAT 5:cmd_set 3368595
STAT 5:delete_hits 404875
STAT 5:incr_hits 0
STAT 5:decr_hits 0
STAT 5:cas_hits 716127
STAT 5:cas_badval 82520
STAT 5:touch_hits 0
STAT 6:chunk_size 304
STAT 6:chunks_per_page 3449
STAT 6:total_pages 758
STAT 6:total_chunks 2614342
STAT 6:used_chunks 2611267
STAT 6:free_chunks 3075
STAT 6:free_chunks_end 0
STAT 6:mem_requested 684175813
STAT 6:get_hits 157817213
STAT 6:cmd_set 6277412
STAT 6:delete_hits 82723
STAT 6:incr_hits 0
STAT 6:decr_hits 0
STAT 6:cas_hits 300004
STAT 6:cas_badval 72973
STAT 6:touch_hits 0
STAT 7:chunk_size 384
STAT 7:chunks_per_page 2730
STAT 7:total_pages 707
STAT 7:total_chunks 1930110
STAT 7:used_chunks 1928612
STAT 7:free_chunks 1498
STAT 7:free_chunks_end 0
STAT 7:mem_requested 654651921
STAT 7:get_hits 182132593
STAT 7:cmd_set 2669451
STAT 7:delete_hits 254818
STAT 7:incr_hits 0
STAT 7:decr_hits 0
STAT 7:cas_hits 167632
STAT 7:cas_badval 49783
STAT 7:touch_hits 0
STAT 8:chunk_size 480
STAT 8:chunks_per_page 2184
STAT 8:total_pages 384
STAT 8:total_chunks 838656
STAT 8:used_chunks 837055
STAT 8:free_chunks 1601
STAT 8:free_chunks_end 0
STAT 8:mem_requested 353122096
STAT 8:get_hits 76904433
STAT 8:cmd_set 1520475
STAT 8:delete_hits 311542
STAT 8:incr_hits 0
STAT 8:decr_hits 0
STAT 8:cas_hits 215922
STAT 8:cas_badval 40975
STAT 8:touch_hits 0
STAT 9:chunk_size 600
STAT 9:chunks_per_page 1747
STAT 9:total_pages 200
STAT 9:total_chunks 349400
STAT 9:used_chunks 348242
STAT 9:free_chunks 1158
STAT 9:free_chunks_end 0
STAT 9:mem_requested 184945925
STAT 9:get_hits 40848868
STAT 9:cmd_set 612512
STAT 9:delete_hits 70471
STAT 9:incr_hits 0
STAT 9:decr_hits 0
STAT 9:cas_hits 72547
STAT 9:cas_badval 23751
STAT 9:touch_hits 0
STAT 10:chunk_size 752
STAT 10:chunks_per_page 1394
STAT 10:total_pages 182
STAT 10:total_chunks 253708
STAT 10:used_chunks 253310
STAT 10:free_chunks 398
STAT 10:free_chunks_end 0
STAT 10:mem_requested 170137135
STAT 10:get_hits 21423357
STAT 10:cmd_set 1067920
STAT 10:delete_hits 658545
STAT 10:incr_hits 0
STAT 10:decr_hits 0
STAT 10:cas_hits 55584
STAT 10:cas_badval 12776
STAT 10:touch_hits 0
STAT 11:chunk_size 944
STAT 11:chunks_per_page 1110
STAT 11:total_pages 123
STAT 11:total_chunks 136530
STAT 11:used_chunks 135969
STAT 11:free_chunks 561
STAT 11:free_chunks_end 0
STAT 11:mem_requested 113363762
STAT 11:get_hits 14265390
STAT 11:cmd_set 434224
STAT 11:delete_hits 215206
STAT 11:incr_hits 0
STAT 11:decr_hits 0
STAT 11:cas_hits 23539
STAT 11:cas_badval 8932
STAT 11:touch_hits 0
STAT 12:chunk_size 1184
STAT 12:chunks_per_page 885
STAT 12:total_pages 90
STAT 12:total_chunks 79650
STAT 12:used_chunks 79025
STAT 12:free_chunks 625
STAT 12:free_chunks_end 0
STAT 12:mem_requested 83166218
STAT 12:get_hits 8217152
STAT 12:cmd_set 235993
STAT 12:delete_hits 107058
STAT 12:incr_hits 0
STAT 12:decr_hits 0
STAT 12:cas_hits 13284
STAT 12:cas_badval 5073
STAT 12:touch_hits 0
STAT 13:chunk_size 1480
STAT 13:chunks_per_page 708
STAT 13:total_pages 110
STAT 13:total_chunks 77880
STAT 13:used_chunks 77259
STAT 13:free_chunks 621
STAT 13:free_chunks_end 0
STAT 13:mem_requested 103497237
STAT 13:get_hits 5462053
STAT 13:cmd_set 199975
STAT 13:delete_hits 89700
STAT 13:incr_hits 0
STAT 13:decr_hits 0
STAT 13:cas_hits 10065
STAT 13:cas_badval 5107
STAT 13:touch_hits 0
STAT 14:chunk_size 1856
STAT 14:chunks_per_page 564
STAT 14:total_pages 135
STAT 14:total_chunks 76140
STAT 14:used_chunks 75802
STAT 14:free_chunks 338
STAT 14:free_chunks_end 0
STAT 14:mem_requested 122552360
STAT 14:get_hits 3908927
STAT 14:cmd_set 149739
STAT 14:delete_hits 48735
STAT 14:incr_hits 0
STAT 14:decr_hits 0
STAT 14:cas_hits 7160
STAT 14:cas_badval 3189
STAT 14:touch_hits 0
STAT 15:chunk_size 2320
STAT 15:chunks_per_page 451
STAT 15:total_pages 58
STAT 15:total_chunks 26158
STAT 15:used_chunks 25925
STAT 15:free_chunks 233
STAT 15:free_chunks_end 0
STAT 15:mem_requested 53596256
STAT 15:get_hits 3297935
STAT 15:cmd_set 71708
STAT 15:delete_hits 28956
STAT 15:incr_hits 0
STAT 15:decr_hits 0
STAT 15:cas_hits 4555
STAT 15:cas_badval 3137
STAT 15:touch_hits 0
STAT 16:chunk_size 2904
STAT 16:chunks_per_page 361
STAT 16:total_pages 51
STAT 16:total_chunks 18411
STAT 16:used_chunks 18198
STAT 16:free_chunks 213
STAT 16:free_chunks_end 0
STAT 16:mem_requested 46976028
STAT 16:get_hits 2440957
STAT 16:cmd_set 57222
STAT 16:delete_hits 23059
STAT 16:incr_hits 0
STAT 16:decr_hits 0
STAT 16:cas_hits 3814
STAT 16:cas_badval 3249
STAT 16:touch_hits 0
STAT 17:chunk_size 3632
STAT 17:chunks_per_page 288
STAT 17:total_pages 44
STAT 17:total_chunks 12672
STAT 17:used_chunks 12508
STAT 17:free_chunks 164
STAT 17:free_chunks_end 0
STAT 17:mem_requested 40529987
STAT 17:get_hits 1292165
STAT 17:cmd_set 44610
STAT 17:delete_hits 14903
STAT 17:incr_hits 0
STAT 17:decr_hits 0
STAT 17:cas_hits 2921
STAT 17:cas_badval 3357
STAT 17:touch_hits 0
STAT 18:chunk_size 4544
STAT 18:chunks_per_page 230
STAT 18:total_pages 43
STAT 18:total_chunks 9890
STAT 18:used_chunks 9772
STAT 18:free_chunks 118
STAT 18:free_chunks_end 0
STAT 18:mem_requested 39394238
STAT 18:get_hits 1127464
STAT 18:cmd_set 32458
STAT 18:delete_hits 11187
STAT 18:incr_hits 0
STAT 18:decr_hits 0
STAT 18:cas_hits 2397
STAT 18:cas_badval 2871
STAT 18:touch_hits 0
STAT 19:chunk_size 5680
STAT 19:chunks_per_page 184
STAT 19:total_pages 35
STAT 19:total_chunks 6440
STAT 19:used_chunks 6284
STAT 19:free_chunks 156
STAT 19:free_chunks_end 0
STAT 19:mem_requested 31882788
STAT 19:get_hits 567234
STAT 19:cmd_set 24146
STAT 19:delete_hits 9717
STAT 19:incr_hits 0
STAT 19:decr_hits 0
STAT 19:cas_hits 1835
STAT 19:cas_badval 2172
STAT 19:touch_hits 0
STAT 20:chunk_size 7104
STAT 20:chunks_per_page 147
STAT 20:total_pages 38
STAT 20:total_chunks 5586
STAT 20:used_chunks 5513
STAT 20:free_chunks 73
STAT 20:free_chunks_end 0
STAT 20:mem_requested 35129062
STAT 20:get_hits 406460
STAT 20:cmd_set 18654
STAT 20:delete_hits 4957
STAT 20:incr_hits 0
STAT 20:decr_hits 0
STAT 20:cas_hits 1831
STAT 20:cas_badval 2177
STAT 20:touch_hits 0
STAT 21:chunk_size 8880
STAT 21:chunks_per_page 118
STAT 21:total_pages 47
STAT 21:total_chunks 5546
STAT 21:used_chunks 5457
STAT 21:free_chunks 89
STAT 21:free_chunks_end 0
STAT 21:mem_requested 43583181
STAT 21:get_hits 338174
STAT 21:cmd_set 17572
STAT 21:delete_hits 3798
STAT 21:incr_hits 0
STAT 21:decr_hits 0
STAT 21:cas_hits 1412
STAT 21:cas_badval 2081
STAT 21:touch_hits 0
STAT 22:chunk_size 11104
STAT 22:chunks_per_page 94
STAT 22:total_pages 61
STAT 22:total_chunks 5734
STAT 22:used_chunks 5701
STAT 22:free_chunks 33
STAT 22:free_chunks_end 0
STAT 22:mem_requested 56773938
STAT 22:get_hits 412445
STAT 22:cmd_set 15844
STAT 22:delete_hits 2434
STAT 22:incr_hits 0
STAT 22:decr_hits 0
STAT 22:cas_hits 1266
STAT 22:cas_badval 2172
STAT 22:touch_hits 0
STAT 23:chunk_size 13880
STAT 23:chunks_per_page 75
STAT 23:total_pages 120
STAT 23:total_chunks 9000
STAT 23:used_chunks 8972
STAT 23:free_chunks 28
STAT 23:free_chunks_end 0
STAT 23:mem_requested 113328033
STAT 23:get_hits 566151
STAT 23:cmd_set 23823
STAT 23:delete_hits 1342
STAT 23:incr_hits 0
STAT 23:decr_hits 0
STAT 23:cas_hits 1266
STAT 23:cas_badval 2085
STAT 23:touch_hits 0
STAT 24:chunk_size 17352
STAT 24:chunks_per_page 60
STAT 24:total_pages 124
STAT 24:total_chunks 7440
STAT 24:used_chunks 7389
STAT 24:free_chunks 51
STAT 24:free_chunks_end 0
STAT 24:mem_requested 112152649
STAT 24:get_hits 430006
STAT 24:cmd_set 19257
STAT 24:delete_hits 1641
STAT 24:incr_hits 0
STAT 24:decr_hits 0
STAT 24:cas_hits 874
STAT 24:cas_badval 1657
STAT 24:touch_hits 0
STAT 25:chunk_size 21696
STAT 25:chunks_per_page 48
STAT 25:total_pages 50
STAT 25:total_chunks 2400
STAT 25:used_chunks 2390
STAT 25:free_chunks 10
STAT 25:free_chunks_end 0
STAT 25:mem_requested 46065028
STAT 25:get_hits 167954
STAT 25:cmd_set 11829
STAT 25:delete_hits 1161
STAT 25:incr_hits 0
STAT 25:decr_hits 0
STAT 25:cas_hits 1071
STAT 25:cas_badval 2148
STAT 25:touch_hits 0
STAT 26:chunk_size 27120
STAT 26:chunks_per_page 38
STAT 26:total_pages 55
STAT 26:total_chunks 2090
STAT 26:used_chunks 2055
STAT 26:free_chunks 35
STAT 26:free_chunks_end 0
STAT 26:mem_requested 49471026
STAT 26:get_hits 128251
STAT 26:cmd_set 14025
STAT 26:delete_hits 793
STAT 26:incr_hits 0
STAT 26:decr_hits 0
STAT 26:cas_hits 1242
STAT 26:cas_badval 3929
STAT 26:touch_hits 0
STAT 27:chunk_size 33904
STAT 27:chunks_per_page 30
STAT 27:total_pages 64
STAT 27:total_chunks 1920
STAT 27:used_chunks 1900
STAT 27:free_chunks 20
STAT 27:free_chunks_end 0
STAT 27:mem_requested 58369912
STAT 27:get_hits 80492
STAT 27:cmd_set 17418
STAT 27:delete_hits 415
STAT 27:incr_hits 0
STAT 27:decr_hits 0
STAT 27:cas_hits 1279
STAT 27:cas_badval 8381
STAT 27:touch_hits 0
STAT 28:chunk_size 42384
STAT 28:chunks_per_page 24
STAT 28:total_pages 84
STAT 28:total_chunks 2016
STAT 28:used_chunks 2008
STAT 28:free_chunks 8
STAT 28:free_chunks_end 0
STAT 28:mem_requested 76131385
STAT 28:get_hits 60133
STAT 28:cmd_set 5365
STAT 28:delete_hits 266
STAT 28:incr_hits 0
STAT 28:decr_hits 0
STAT 28:cas_hits 380
STAT 28:cas_badval 1399
STAT 28:touch_hits 0
STAT 29:chunk_size 52984
STAT 29:chunks_per_page 19
STAT 29:total_pages 42
STAT 29:total_chunks 798
STAT 29:used_chunks 790
STAT 29:free_chunks 8
STAT 29:free_chunks_end 0
STAT 29:mem_requested 36500991
STAT 29:get_hits 33450
STAT 29:cmd_set 1915
STAT 29:delete_hits 301
STAT 29:incr_hits 0
STAT 29:decr_hits 0
STAT 29:cas_hits 179
STAT 29:cas_badval 72
STAT 29:touch_hits 0
STAT 30:chunk_size 66232
STAT 30:chunks_per_page 15
STAT 30:total_pages 13
STAT 30:total_chunks 195
STAT 30:used_chunks 185
STAT 30:free_chunks 10
STAT 30:free_chunks_end 0
STAT 30:mem_requested 10922133
STAT 30:get_hits 23401
STAT 30:cmd_set 1106
STAT 30:delete_hits 25
STAT 30:incr_hits 0
STAT 30:decr_hits 0
STAT 30:cas_hits 202
STAT 30:cas_badval 117
STAT 30:touch_hits 0
STAT 31:chunk_size 82792
STAT 31:chunks_per_page 12
STAT 31:total_pages 11
STAT 31:total_chunks 132
STAT 31:used_chunks 123
STAT 31:free_chunks 9
STAT 31:free_chunks_end 0
STAT 31:mem_requested 9067874
STAT 31:get_hits 32612
STAT 31:cmd_set 1011
STAT 31:delete_hits 17
STAT 31:incr_hits 0
STAT 31:decr_hits 0
STAT 31:cas_hits 126
STAT 31:cas_badval 280
STAT 31:touch_hits 0
STAT 32:chunk_size 103496
STAT 32:chunks_per_page 10
STAT 32:total_pages 8
STAT 32:total_chunks 80
STAT 32:used_chunks 80
STAT 32:free_chunks 0
STAT 32:free_chunks_end 0
STAT 32:mem_requested 7372469
STAT 32:get_hits 9291
STAT 32:cmd_set 394
STAT 32:delete_hits 47
STAT 32:incr_hits 0
STAT 32:decr_hits 0
STAT 32:cas_hits 81
STAT 32:cas_badval 47
STAT 32:touch_hits 0
STAT 33:chunk_size 129376
STAT 33:chunks_per_page 8
STAT 33:total_pages 7
STAT 33:total_chunks 56
STAT 33:used_chunks 44
STAT 33:free_chunks 12
STAT 33:free_chunks_end 0
STAT 33:mem_requested 5060683
STAT 33:get_hits 32517
STAT 33:cmd_set 887
STAT 33:delete_hits 140
STAT 33:incr_hits 0
STAT 33:decr_hits 0
STAT 33:cas_hits 125
STAT 33:cas_badval 300
STAT 33:touch_hits 0
STAT 34:chunk_size 161720
STAT 34:chunks_per_page 6
STAT 34:total_pages 8
STAT 34:total_chunks 48
STAT 34:used_chunks 44
STAT 34:free_chunks 4
STAT 34:free_chunks_end 0
STAT 34:mem_requested 6363909
STAT 34:get_hits 9409
STAT 34:cmd_set 521
STAT 34:delete_hits 0
STAT 34:incr_hits 0
STAT 34:decr_hits 0
STAT 34:cas_hits 78
STAT 34:cas_badval 100
STAT 34:touch_hits 0
STAT 35:chunk_size 202152
STAT 35:chunks_per_page 5
STAT 35:total_pages 5
STAT 35:total_chunks 25
STAT 35:used_chunks 22
STAT 35:free_chunks 3
STAT 35:free_chunks_end 0
STAT 35:mem_requested 3979019
STAT 35:get_hits 5360
STAT 35:cmd_set 499
STAT 35:delete_hits 0
STAT 35:incr_hits 0
STAT 35:decr_hits 0
STAT 35:cas_hits 65
STAT 35:cas_badval 113
STAT 35:touch_hits 0
STAT 36:chunk_size 252696
STAT 36:chunks_per_page 4
STAT 36:total_pages 4
STAT 36:total_chunks 16
STAT 36:used_chunks 15
STAT 36:free_chunks 1
STAT 36:free_chunks_end 0
STAT 36:mem_requested 3384744
STAT 36:get_hits 8815
STAT 36:cmd_set 610
STAT 36:delete_hits 0
STAT 36:incr_hits 0
STAT 36:decr_hits 0
STAT 36:cas_hits 77
STAT 36:cas_badval 144
STAT 36:touch_hits 0
STAT 37:chunk_size 315872
STAT 37:chunks_per_page 3
STAT 37:total_pages 1
STAT 37:total_chunks 3
STAT 37:used_chunks 2
STAT 37:free_chunks 1
STAT 37:free_chunks_end 0
STAT 37:mem_requested 566607
STAT 37:get_hits 2925
STAT 37:cmd_set 126
STAT 37:delete_hits 0
STAT 37:incr_hits 0
STAT 37:decr_hits 0
STAT 37:cas_hits 10
STAT 37:cas_badval 43
STAT 37:touch_hits 0
STAT 38:chunk_size 394840
STAT 38:chunks_per_page 2
STAT 38:total_pages 2
STAT 38:total_chunks 4
STAT 38:used_chunks 3
STAT 38:free_chunks 1
STAT 38:free_chunks_end 0
STAT 38:mem_requested 1049482
STAT 38:get_hits 7097
STAT 38:cmd_set 81
STAT 38:delete_hits 0
STAT 38:incr_hits 0
STAT 38:decr_hits 0
STAT 38:cas_hits 8
STAT 38:cas_badval 18
STAT 38:touch_hits 0
STAT 39:chunk_size 493552
STAT 39:chunks_per_page 2
STAT 39:total_pages 1
STAT 39:total_chunks 2
STAT 39:used_chunks 2
STAT 39:free_chunks 0
STAT 39:free_chunks_end 0
STAT 39:mem_requested 845545
STAT 39:get_hits 62
STAT 39:cmd_set 2
STAT 39:delete_hits 0
STAT 39:incr_hits 0
STAT 39:decr_hits 0
STAT 39:cas_hits 0
STAT 39:cas_badval 0
STAT 39:touch_hits 0
STAT 40:chunk_size 616944
STAT 40:chunks_per_page 1
STAT 40:total_pages 2
STAT 40:total_chunks 2
STAT 40:used_chunks 2
STAT 40:free_chunks 0
STAT 40:free_chunks_end 0
STAT 40:mem_requested 1075459
STAT 40:get_hits 6
STAT 40:cmd_set 4
STAT 40:delete_hits 0
STAT 40:incr_hits 0
STAT 40:decr_hits 0
STAT 40:cas_hits 0
STAT 40:cas_badval 0
STAT 40:touch_hits 0
STAT 41:chunk_size 771184
STAT 41:chunks_per_page 1
STAT 41:total_pages 2
STAT 41:total_chunks 2
STAT 41:used_chunks 1
STAT 41:free_chunks 1
STAT 41:free_chunks_end 0
STAT 41:mem_requested 689666
STAT 41:get_hits 270
STAT 41:cmd_set 729
STAT 41:delete_hits 0
STAT 41:incr_hits 0
STAT 41:decr_hits 0
STAT 41:cas_hits 50
STAT 41:cas_badval 210
STAT 41:touch_hits 0
STAT active_slabs 41
STAT total_malloced 11994848920
stats items
STAT items:1:number 1086855
STAT items:1:age 78210
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 1
STAT items:1:expired_unfetched 1
STAT items:1:evicted_unfetched 0
STAT items:2:number 16956442
STAT items:2:age 78211
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 1
STAT items:2:expired_unfetched 0
STAT items:2:evicted_unfetched 0
STAT items:3:number 27292791
STAT items:3:age 78211
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:4:number 7310621
STAT items:4:age 78210
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:5:number 1950091
STAT items:5:age 78210
STAT items:5:evicted 0
STAT items:5:evicted_nonzero 0
STAT items:5:evicted_time 0
STAT items:5:outofmemory 0
STAT items:5:tailrepairs 0
STAT items:5:reclaimed 0
STAT items:5:expired_unfetched 0
STAT items:5:evicted_unfetched 0
STAT items:6:number 2611267
STAT items:6:age 78209
STAT items:6:evicted 0
STAT items:6:evicted_nonzero 0
STAT items:6:evicted_time 0
STAT items:6:outofmemory 0
STAT items:6:tailrepairs 0
STAT items:6:reclaimed 6
STAT items:6:expired_unfetched 6
STAT items:6:evicted_unfetched 0
STAT items:7:number 1928612
STAT items:7:age 78208
STAT items:7:evicted 0
STAT items:7:evicted_nonzero 0
STAT items:7:evicted_time 0
STAT items:7:outofmemory 0
STAT items:7:tailrepairs 0
STAT items:7:reclaimed 0
STAT items:7:expired_unfetched 0
STAT items:7:evicted_unfetched 0
STAT items:8:number 837055
STAT items:8:age 78210
STAT items:8:evicted 0
STAT items:8:evicted_nonzero 0
STAT items:8:evicted_time 0
STAT items:8:outofmemory 0
STAT items:8:tailrepairs 0
STAT items:8:reclaimed 0
STAT items:8:expired_unfetched 0
STAT items:8:evicted_unfetched 0
STAT items:9:number 348242
STAT items:9:age 78207
STAT items:9:evicted 0
STAT items:9:evicted_nonzero 0
STAT items:9:evicted_time 0
STAT items:9:outofmemory 0
STAT items:9:tailrepairs 0
STAT items:9:reclaimed 0
STAT items:9:expired_unfetched 0
STAT items:9:evicted_unfetched 0
STAT items:10:number 253310
STAT items:10:age 78208
STAT items:10:evicted 0
STAT items:10:evicted_nonzero 0
STAT items:10:evicted_time 0
STAT items:10:outofmemory 0
STAT items:10:tailrepairs 0
STAT items:10:reclaimed 0
STAT items:10:expired_unfetched 0
STAT items:10:evicted_unfetched 0
STAT items:11:number 135969
STAT items:11:age 78193
STAT items:11:evicted 0
STAT items:11:evicted_nonzero 0
STAT items:11:evicted_time 0
STAT items:11:outofmemory 0
STAT items:11:tailrepairs 0
STAT items:11:reclaimed 0
STAT items:11:expired_unfetched 0
STAT items:11:evicted_unfetched 0
STAT items:12:number 79025
STAT items:12:age 78209
STAT items:12:evicted 0
STAT items:12:evicted_nonzero 0
STAT items:12:evicted_time 0
STAT items:12:outofmemory 0
STAT items:12:tailrepairs 0
STAT items:12:reclaimed 0
STAT items:12:expired_unfetched 0
STAT items:12:evicted_unfetched 0
STAT items:13:number 77259
STAT items:13:age 78184
STAT items:13:evicted 0
STAT items:13:evicted_nonzero 0
STAT items:13:evicted_time 0
STAT items:13:outofmemory 0
STAT items:13:tailrepairs 0
STAT items:13:reclaimed 0
STAT items:13:expired_unfetched 0
STAT items:13:evicted_unfetched 0
STAT items:14:number 75802
STAT items:14:age 78197
STAT items:14:evicted 0
STAT items:14:evicted_nonzero 0
STAT items:14:evicted_time 0
STAT items:14:outofmemory 0
STAT items:14:tailrepairs 0
STAT items:14:reclaimed 0
STAT items:14:expired_unfetched 0
STAT items:14:evicted_unfetched 0
STAT items:15:number 25925
STAT items:15:age 78173
STAT items:15:evicted 0
STAT items:15:evicted_nonzero 0
STAT items:15:evicted_time 0
STAT items:15:outofmemory 0
STAT items:15:tailrepairs 0
STAT items:15:reclaimed 0
STAT items:15:expired_unfetched 0
STAT items:15:evicted_unfetched 0
STAT items:16:number 18198
STAT items:16:age 78158
STAT items:16:evicted 0
STAT items:16:evicted_nonzero 0
STAT items:16:evicted_time 0
STAT items:16:outofmemory 0
STAT items:16:tailrepairs 0
STAT items:16:reclaimed 1
STAT items:16:expired_unfetched 1
STAT items:16:evicted_unfetched 0
STAT items:17:number 12508
STAT items:17:age 78042
STAT items:17:evicted 0
STAT items:17:evicted_nonzero 0
STAT items:17:evicted_time 0
STAT items:17:outofmemory 0
STAT items:17:tailrepairs 0
STAT items:17:reclaimed 2
STAT items:17:expired_unfetched 2
STAT items:17:evicted_unfetched 0
STAT items:18:number 9772
STAT items:18:age 78074
STAT items:18:evicted 0
STAT items:18:evicted_nonzero 0
STAT items:18:evicted_time 0
STAT items:18:outofmemory 0
STAT items:18:tailrepairs 0
STAT items:18:reclaimed 3
STAT items:18:expired_unfetched 2
STAT items:18:evicted_unfetched 0
STAT items:19:number 6284
STAT items:19:age 78169
STAT items:19:evicted 0
STAT items:19:evicted_nonzero 0
STAT items:19:evicted_time 0
STAT items:19:outofmemory 0
STAT items:19:tailrepairs 0
STAT items:19:reclaimed 0
STAT items:19:expired_unfetched 0
STAT items:19:evicted_unfetched 0
STAT items:20:number 5513
STAT items:20:age 78163
STAT items:20:evicted 0
STAT items:20:evicted_nonzero 0
STAT items:20:evicted_time 0
STAT items:20:outofmemory 0
STAT items:20:tailrepairs 0
STAT items:20:reclaimed 0
STAT items:20:expired_unfetched 0
STAT items:20:evicted_unfetched 0
STAT items:21:number 5457
STAT items:21:age 78203
STAT items:21:evicted 0
STAT items:21:evicted_nonzero 0
STAT items:21:evicted_time 0
STAT items:21:outofmemory 0
STAT items:21:tailrepairs 0
STAT items:21:reclaimed 0
STAT items:21:expired_unfetched 0
STAT items:21:evicted_unfetched 0
STAT items:22:number 5701
STAT items:22:age 78186
STAT items:22:evicted 0
STAT items:22:evicted_nonzero 0
STAT items:22:evicted_time 0
STAT items:22:outofmemory 0
STAT items:22:tailrepairs 0
STAT items:22:reclaimed 0
STAT items:22:expired_unfetched 0
STAT items:22:evicted_unfetched 0
STAT items:23:number 8972
STAT items:23:age 78206
STAT items:23:evicted 0
STAT items:23:evicted_nonzero 0
STAT items:23:evicted_time 0
STAT items:23:outofmemory 0
STAT items:23:tailrepairs 0
STAT items:23:reclaimed 0
STAT items:23:expired_unfetched 0
STAT items:23:evicted_unfetched 0
STAT items:24:number 7389
STAT items:24:age 78200
STAT items:24:evicted 0
STAT items:24:evicted_nonzero 0
STAT items:24:evicted_time 0
STAT items:24:outofmemory 0
STAT items:24:tailrepairs 0
STAT items:24:reclaimed 0
STAT items:24:expired_unfetched 0
STAT items:24:evicted_unfetched 0
STAT items:25:number 2390
STAT items:25:age 78108
STAT items:25:evicted 0
STAT items:25:evicted_nonzero 0
STAT items:25:evicted_time 0
STAT items:25:outofmemory 0
STAT items:25:tailrepairs 0
STAT items:25:reclaimed 0
STAT items:25:expired_unfetched 0
STAT items:25:evicted_unfetched 0
STAT items:26:number 2055
STAT items:26:age 77844
STAT items:26:evicted 0
STAT items:26:evicted_nonzero 0
STAT items:26:evicted_time 0
STAT items:26:outofmemory 0
STAT items:26:tailrepairs 0
STAT items:26:reclaimed 1
STAT items:26:expired_unfetched 1
STAT items:26:evicted_unfetched 0
STAT items:27:number 1900
STAT items:27:age 77950
STAT items:27:evicted 0
STAT items:27:evicted_nonzero 0
STAT items:27:evicted_time 0
STAT items:27:outofmemory 0
STAT items:27:tailrepairs 0
STAT items:27:reclaimed 0
STAT items:27:expired_unfetched 0
STAT items:27:evicted_unfetched 0
STAT items:28:number 2008
STAT items:28:age 77495
STAT items:28:evicted 0
STAT items:28:evicted_nonzero 0
STAT items:28:evicted_time 0
STAT items:28:outofmemory 0
STAT items:28:tailrepairs 0
STAT items:28:reclaimed 14
STAT items:28:expired_unfetched 12
STAT items:28:evicted_unfetched 0
STAT items:29:number 790
STAT items:29:age 75701
STAT items:29:evicted 0
STAT items:29:evicted_nonzero 0
STAT items:29:evicted_time 0
STAT items:29:outofmemory 0
STAT items:29:tailrepairs 0
STAT items:29:reclaimed 32
STAT items:29:expired_unfetched 21
STAT items:29:evicted_unfetched 0
STAT items:30:number 185
STAT items:30:age 78026
STAT items:30:evicted 0
STAT items:30:evicted_nonzero 0
STAT items:30:evicted_time 0
STAT items:30:outofmemory 0
STAT items:30:tailrepairs 0
STAT items:30:reclaimed 0
STAT items:30:expired_unfetched 0
STAT items:30:evicted_unfetched 0
STAT items:31:number 123
STAT items:31:age 70391
STAT items:31:evicted 0
STAT items:31:evicted_nonzero 0
STAT items:31:evicted_time 0
STAT items:31:outofmemory 0
STAT items:31:tailrepairs 0
STAT items:31:reclaimed 3
STAT items:31:expired_unfetched 3
STAT items:31:evicted_unfetched 0
STAT items:32:number 80
STAT items:32:age 77687
STAT items:32:evicted 0
STAT items:32:evicted_nonzero 0
STAT items:32:evicted_time 0
STAT items:32:outofmemory 0
STAT items:32:tailrepairs 0
STAT items:32:reclaimed 0
STAT items:32:expired_unfetched 0
STAT items:32:evicted_unfetched 0
STAT items:33:number 44
STAT items:33:age 69142
STAT items:33:evicted 0
STAT items:33:evicted_nonzero 0
STAT items:33:evicted_time 0
STAT items:33:outofmemory 0
STAT items:33:tailrepairs 0
STAT items:33:reclaimed 4
STAT items:33:expired_unfetched 4
STAT items:33:evicted_unfetched 0
STAT items:34:number 44
STAT items:34:age 77092
STAT items:34:evicted 0
STAT items:34:evicted_nonzero 0
STAT items:34:evicted_time 0
STAT items:34:outofmemory 0
STAT items:34:tailrepairs 0
STAT items:34:reclaimed 0
STAT items:34:expired_unfetched 0
STAT items:34:evicted_unfetched 0
STAT items:35:number 22
STAT items:35:age 69392
STAT items:35:evicted 0
STAT items:35:evicted_nonzero 0
STAT items:35:evicted_time 0
STAT items:35:outofmemory 0
STAT items:35:tailrepairs 0
STAT items:35:reclaimed 1
STAT items:35:expired_unfetched 1
STAT items:35:evicted_unfetched 0
STAT items:36:number 15
STAT items:36:age 74785
STAT items:36:evicted 0
STAT items:36:evicted_nonzero 0
STAT items:36:evicted_time 0
STAT items:36:outofmemory 0
STAT items:36:tailrepairs 0
STAT items:36:reclaimed 0
STAT items:36:expired_unfetched 0
STAT items:36:evicted_unfetched 0
STAT items:37:number 2
STAT items:37:age 12226
STAT items:37:evicted 0
STAT items:37:evicted_nonzero 0
STAT items:37:evicted_time 0
STAT items:37:outofmemory 0
STAT items:37:tailrepairs 0
STAT items:37:reclaimed 1
STAT items:37:expired_unfetched 1
STAT items:37:evicted_unfetched 0
STAT items:38:number 3
STAT items:38:age 49588
STAT items:38:evicted 0
STAT items:38:evicted_nonzero 0
STAT items:38:evicted_time 0
STAT items:38:outofmemory 0
STAT items:38:tailrepairs 0
STAT items:38:reclaimed 2
STAT items:38:expired_unfetched 2
STAT items:38:evicted_unfetched 0
STAT items:39:number 2
STAT items:39:age 47360
STAT items:39:evicted 0
STAT items:39:evicted_nonzero 0
STAT items:39:evicted_time 0
STAT items:39:outofmemory 0
STAT items:39:tailrepairs 0
STAT items:39:reclaimed 0
STAT items:39:expired_unfetched 0
STAT items:39:evicted_unfetched 0
STAT items:40:number 2
STAT items:40:age 48591
STAT items:40:evicted 0
STAT items:40:evicted_nonzero 0
STAT items:40:evicted_time 0
STAT items:40:outofmemory 0
STAT items:40:tailrepairs 0
STAT items:40:reclaimed 0
STAT items:40:expired_unfetched 0
STAT items:40:evicted_unfetched 0
STAT items:41:number 1
STAT items:41:age 11416
STAT items:41:evicted 0
STAT items:41:evicted_nonzero 0
STAT items:41:evicted_time 0
STAT items:41:outofmemory 0
STAT items:41:tailrepairs 0
STAT items:41:reclaimed 0
STAT items:41:expired_unfetched 0
STAT items:41:evicted_unfetched 0
END
-Does hash_power_level increase after every spike? Does the spikes stop
after a wile?
- You can start an instance with -o hashpower=26 or something similar. If
you start an instance that way does it not spike?
I've removed the machine from the cluster. Might be able to answer these later after putting it back again.
> nobody � �2727 49.4 38.5 13935812 13508096 ? � Ssl �00:46 619:36 /usr/bin/memcached -m 28000 -p 11211 -u nobody -l 0.0.0.0 -d -c 100000
>
> User cpu spikes every 40-60 minutes:
>
> [user_cpu.gif]
>
>
> Open connections seem to spike at same time:
>
> [open_connections.gif]
>
>
> User cpu graph for a non-production server at similar frequency but much shorter spikes:
>
> [non_prod_user_cpu.gif]
>
>
> I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
>
> Is there some background thread which does some heavy duty work every some minutes?
>
> --
> �
> ---
> You received this message because you are subscribed to the Google Groups "memcached" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to memcached+...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
> �
> �
>
>
dormando
Mar 27, 2013, 8:10:35 PM3/27/13
to memc...@googlegroups.com
> Thanks for a prompt response. My replies are inline:
> �
> There could be a brief spike when the hash_power_level is being increased�
> (it shuffles everything into a new hash table). That should stop after it�
> reaches a steady state.�
>
> Did we not have this in older binaries? (in particular we never observed it in 1.4.2). Also these spikes lasted for a few minutes. Is that possible?�
> �
> There could be a brief spike when the hash_power_level is being increased�
> (it shuffles everything into a new hash table). That should stop after it�
> reaches a steady state.�
>
The code's changed recently. Might be buggy/etc. However it seems
extremely unlikely this is a problem with memcached. I'm not sure how
you're seeing the spike though. Is it in user CPU or syscpu? Given you say
it happens when the thing's not in rotation I'm pretty suspicious.
> - What exactly are you seeing when a "set fails" ? is it timing out, are�
> you getting some specific error back?�
>
> I'm using libmemcached as my client and it din't throw back an error, just returned false so I'm assuming that it was timing out. Is there a better way of observing errors?
docs.
Maybe something else will have some info. Also, if you could gas up the
poor man's profiler: http://poormansprofiler.org/ - modify it to snapshot
memcached, and run it a few times when you see the "spike" happening, then
include the results please.
> >
> > User cpu spikes every 40-60 minutes:
> >
> > [user_cpu.gif]
> >
> >
> > Open connections seem to spike at same time:
> >
> > [open_connections.gif]
> >
> >
> > User cpu graph for a non-production server at similar frequency but much shorter spikes:
> >
> > [non_prod_user_cpu.gif]
> >
> >
> > I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
> >
> > Is there some background thread which does some heavy duty work every some minutes?
> >
> > --
> > �
> > User cpu spikes every 40-60 minutes:
> >
> > [user_cpu.gif]
> >
> >
> > Open connections seem to spike at same time:
> >
> > [open_connections.gif]
> >
> >
> > User cpu graph for a non-production server at similar frequency but much shorter spikes:
> >
> > [non_prod_user_cpu.gif]
> >
> >
> > I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
> >
> > Is there some background thread which does some heavy duty work every some minutes?
> >
> > --
> > ---
> > You received this message because you are subscribed to the Google Groups "memcached" group.
> > To unsubscribe from this group and stop receiving emails from it, send an email to memcached+...@googlegroups.com.
> > For more options, visit https://groups.google.com/groups/opt_out.
> > �
> > You received this message because you are subscribed to the Google Groups "memcached" group.
> > To unsubscribe from this group and stop receiving emails from it, send an email to memcached+...@googlegroups.com.
> > For more options, visit https://groups.google.com/groups/opt_out.
> > �
> >
> >
>
> --
> �
> �
>
>
Nikhil Garg
Apr 18, 2013, 11:01:54 PM4/18/13
to memc...@googlegroups.com
I've since tried following combinations (with hashtable presized to power26)
1.4.15 and libevent2
1.4.14 and libevent1.4
1.4.15 and libevent1.4
All on ubunutu 10.04 and ubuntu 12.04 but got similar problems in all cases.
I managed to get some samples of memcached from poormansprofiler. Attaching some :
root@mc5:~# cat result1
Fri Apr 19 02:02:17 UTC 2013
21 epoll_wait,libevent-1::??,event_base_loop,worker_libevent,start_thread,clone,??
3 pthread_cond_wait,assoc_maintenance_thread,start_thread,clone,??
3 epoll_wait,libevent-1::??,event_base_loop,main
2 libc::??,tokenize_command,process_get_command,process_command,try_read_command,drive_machine,event_handler,event_base_loop,worker_libevent,start_thread,clone,??
1 sendmsg,transmit,drive_machine,event_handler,event_base_loop,worker_libevent,start_thread,clone,??
root@mc5:~# cat result50
Fri Apr 19 02:03:13 UTC 2013
24 epoll_wait,libevent-1::??,event_base_loop,worker_libevent,start_thread,clone,??
3 pthread_cond_wait,assoc_maintenance_thread,start_thread,clone,??
3 epoll_wait,libevent-1::??,event_base_loop,main
root@mc5:~#
Fri Apr 19 02:03:47 UTC 2013
22 epoll_wait,libevent-1::??,event_base_loop,worker_libevent,start_thread,clone,??
3 pthread_cond_wait,assoc_maintenance_thread,start_thread,clone,??
3 epoll_wait,libevent-1::??,event_base_loop,main
2 sendmsg,transmit,drive_machine,event_handler,event_base_loop,worker_libevent,start_thread,clone,??
root@mc5:~#
These samples were obtained when I started memcached using :
usr/bin/memcached -v -m 28000 -p 11211 -u nobody -l 0.0.0.0 -c 100000 -o hashpower=26 -t 8
I had also run memcached server in verbose (-v) mode and found no errors there. I even ran mc_conn_tester.pl and found no timeouts. I noted that running mc_conn_tester.pl causes bunch of errors of this type on memcached.log:
Failed to write, and not due to blocking: Broken pipe
Failed to write, and not due to blocking: Connection reset by peer
Failed to write, and not due to blocking: Connection reset by peer
Failed to write, and not due to blocking: Broken pipe
Failed to write, and not due to blocking: Broken pipe
I have Ganglia on my machines and it shows spikes in user cpu times. I also can see using top that memcache starts hogging cpu during these spikes. Ignore anything I said about boxes not in rotation - I found the small user cpu spike to be caused by a cron.
Most startling aspect is that I've some 1.4.2 boxes running all this while and they dont' cause any errrors whatsoever. And everytime I try to add 1.4.14/1.4.15 box, I ALWAYS see periodic errors with period of 40-80 mins.
-
Nikhil
> > nobody � �2727 49.4 38.5 13935812 13508096 ? � Ssl �00:46 619:36 /usr/bin/memcached -m 28000 -p 11211 -u nobody -l 0.0.0.0 -d -c 100000
> >
> > User cpu spikes every 40-60 minutes:
> >
> > [user_cpu.gif]
> >
> >
> > Open connections seem to spike at same time:
> >
> > [open_connections.gif]
> >
> >
> > User cpu graph for a non-production server at similar frequency but much shorter spikes:
> >
> > [non_prod_user_cpu.gif]
> >
> >
> > I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
> >
> > Is there some background thread which does some heavy duty work every some minutes?
> >
> > --
> > �
> > ---
> > You received this message because you are subscribed to the Google Groups "memcached" group.
> > To unsubscribe from this group and stop receiving emails from it, send an email to memcached+...@googlegroups.com.
> > For more options, visit https://groups.google.com/groups/opt_out.
> > �
> > �
> >
> >
>
> --
>
> ---
> You received this message because you are subscribed to the Google Groups "memcached" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to memcached+...@googlegroups.com.
You received this message because you are subscribed to a topic in the Google Groups "memcached" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/memcached/rmbNc3qtrCA/unsubscribe?hl=en.
To unsubscribe from this group and all its topics, send an email to memcached+...@googlegroups.com.
dormando
Apr 19, 2013, 2:11:53 AM4/19/13
to memc...@googlegroups.com
I'm a bit confused: when the CPU usage is spiking is memcached still
functioning? Or is it completely hung?
those samples you have there are pretty weird. it doesn't appear to be
hung on anything?
If it's easy for you to reproduce, can you do a little more bisecting?
you've tried 1.4.15 and 1.4.14, can you go backwards until it "stops"
happening, so we know which exact version?
thanks,
-Dormando
> > � � � > nobody � �2727 49.4 38.5 13935812 13508096 ? � Ssl �00:46 619:36 /usr/bin/memcached -m 28000 -p 11211 -u nobody -l 0.0.0.0 -d -c 100000
> > � � � > ---
> �
> �
>
>
functioning? Or is it completely hung?
those samples you have there are pretty weird. it doesn't appear to be
hung on anything?
If it's easy for you to reproduce, can you do a little more bisecting?
you've tried 1.4.15 and 1.4.14, can you go backwards until it "stops"
happening, so we know which exact version?
thanks,
-Dormando
> > � � � >
> > � � � > User cpu spikes every 40-60 minutes:
> > � � � >
> > � � � > [user_cpu.gif]
> > � � � >
> > � � � >
> > � � � > Open connections seem to spike at same time:
> > � � � >
> > � � � > [open_connections.gif]
> > � � � >
> > � � � >
> > � � � > User cpu graph for a non-production server at similar frequency but much shorter spikes:
> > � � � >
> > � � � > [non_prod_user_cpu.gif]
> > � � � >
> > � � � >
> > � � � > I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
> > � � � >
> > � � � > Is there some background thread which does some heavy duty work every some minutes?
> > � � � >
> > � � � > --
> > � � � > �
> > � � � > User cpu spikes every 40-60 minutes:
> > � � � >
> > � � � > [user_cpu.gif]
> > � � � >
> > � � � >
> > � � � > Open connections seem to spike at same time:
> > � � � >
> > � � � > [open_connections.gif]
> > � � � >
> > � � � >
> > � � � > User cpu graph for a non-production server at similar frequency but much shorter spikes:
> > � � � >
> > � � � > [non_prod_user_cpu.gif]
> > � � � >
> > � � � >
> > � � � > I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
> > � � � >
> > � � � > Is there some background thread which does some heavy duty work every some minutes?
> > � � � >
> > � � � > --
> > � � � > ---
> �
>
>
Nikhil Garg
Apr 19, 2013, 2:57:47 AM4/19/13
to memc...@googlegroups.com
It was still functioning - I did a set/get/delete from telnet and it went through. But yeah, I couldn't find nothing obviously wrong with samples.
I ran 1.4.6 after posting here and it has been fine for last 3 hours.
I haven't been able to repro this condition in non-prod settings yet and that is why it is really difficult for me to try new configurations (set failures in production cause inconsistency which is painful). I'm doing this whole upgrade just to get rid of OOM (possibly connection leak?) that 1.4.2 seems to have. If 1.4.6 doesn't solve that, I'd try bisecting with more versions and will let you know. Sorry can't help you a lot yet.
-
Nikhil
> > > nobody � �2727 49.4 38.5 13935812 13508096 ? � Ssl �00:46 619:36 /usr/bin/memcached -m 28000 -p 11211 -u nobody -l 0.0.0.0 -d -c 100000
> > >
> > > User cpu spikes every 40-60 minutes:
> > >
> > > [user_cpu.gif]
> > >
> > >
> > > Open connections seem to spike at same time:
> > >
> > > [open_connections.gif]
> > >
> > >
> > > User cpu graph for a non-production server at similar frequency but much shorter spikes:
> > >
> > > [non_prod_user_cpu.gif]
> > >
> > >
> > > I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
> > >
> > > Is there some background thread which does some heavy duty work every some minutes?
> > >
> > > --
> > > �
> > > ---
> > > You received this message because you are subscribed to the Google Groups "memcached" group.
> > > To unsubscribe from this group and stop receiving emails from it, send an email to memcached+...@googlegroups.com.
> > > For more options, visit https://groups.google.com/groups/opt_out.
> > > �
> > > �
dormando
Apr 19, 2013, 3:00:39 AM4/19/13
to memc...@googlegroups.com
I understand it's hard; but I can't reproduce so anything you can do to
help narrow down where it came in is much appreciated. If you can find the
exact version that goes wrong that's best.
So, good luck. :(
> > > � � � > nobody � �2727 49.4 38.5 13935812 13508096 ? � Ssl �00:46 619:36 /usr/bin/memcached -m 28000 -p 11211 -u nobody -l 0.0.0.0 -d -c 100000
> > > � � � > ---
> �
> �
>
>
help narrow down where it came in is much appreciated. If you can find the
exact version that goes wrong that's best.
So, good luck. :(
> > > � � � >
> > > � � � > User cpu spikes every 40-60 minutes:
> > > � � � >
> > > � � � > [user_cpu.gif]
> > > � � � >
> > > � � � >
> > > � � � > Open connections seem to spike at same time:
> > > � � � >
> > > � � � > [open_connections.gif]
> > > � � � >
> > > � � � >
> > > � � � > User cpu graph for a non-production server at similar frequency but much shorter spikes:
> > > � � � >
> > > � � � > [non_prod_user_cpu.gif]
> > > � � � >
> > > � � � >
> > > � � � > I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
> > > � � � >
> > > � � � > Is there some background thread which does some heavy duty work every some minutes?
> > > � � � >
> > > � � � > --
> > > � � � > �
> > > � � � > User cpu spikes every 40-60 minutes:
> > > � � � >
> > > � � � > [user_cpu.gif]
> > > � � � >
> > > � � � >
> > > � � � > Open connections seem to spike at same time:
> > > � � � >
> > > � � � > [open_connections.gif]
> > > � � � >
> > > � � � >
> > > � � � > User cpu graph for a non-production server at similar frequency but much shorter spikes:
> > > � � � >
> > > � � � > [non_prod_user_cpu.gif]
> > > � � � >
> > > � � � >
> > > � � � > I obtained strace during one of the spikes though found nothing suspicious about it. Can provide it, if it is helpful. I also have the output of ls -l /proc/$(pidof memcached)/fd from a spike.
> > > � � � >
> > > � � � > Is there some background thread which does some heavy duty work every some minutes?
> > > � � � >
> > > � � � > --
> > > � � � > ---
> �
>
>
Reply all
Reply to author
Forward
0 new messages